记一次实现日志链路追踪（log_trace_id）踩到的坑

背景

在分布式环境下，微服务众多、日志分散是一个令人头疼的问题，当然我们可以采用ELK来将单个微服务的各个容器节点日志汇总到一个索引中来集中查询，这确实能够提高日志查询的效率。 但是，在kiaban中查询日志的时候我们仍然会面对很多的问题，这里就拿四个例子来说明：

• 1、[用户请求 -> Gateway -> Microservice]，很多时候Microservice内部还有很多的相互调用，我们如何将一个用户的请求在微服务内部的调用串联起来呢，方便快速定位问题？ELK的架构是无法满足我们这个需求的。

• 2、MQ也是微服务必备的技术栈，通常producer和consumer不在同一个微服务里，就算在同一个服务里，也不会在同一个线程里。所以，当我们需要追踪某一条消费从生产到消费的完整路径时会比较麻烦。

• 3、当某一个较大的任务在执行时，我们通常会采用多线程的任务去执行，那么这些多个线程执行的情况我们要如何去串联在一起？方便我们看到整体执行情况 。

• 4、有时候我们采用@Async注解用异步的方式来运行某些任务，这个异步任务也会运行在一个新的线程中，我们要如何将调用方和异步任务串联起来？

上边描述的三个问题归根到底就是需要用一个“标识”将一次请求的完整链路全部串联起来，采用log_trace_ld能够帮助我们来实现全链路追踪。

实现串联微服务

在前边我们探讨了要使用log_trace_id的原因，所以就开始准备着手解决第一个问题：将微服务内部之间的调用串联起来。

思路如下：

• 1、我们将log_reace_id字段放到Http请求头里边，微服务在接收到请求时，使用拦截器拦截每次请求，若Header中已经存在此字段，则说明此次请求时微服务内部的调用，则继续沿用Header中的log_trace_log，否则重新生成log_trace_id设置到MDC中，代码如下:

public class RequestInterceptor extends HandlerInterceptorAdapter {

    private final static Logger log = LoggerFactory.getLogger(RequestInterceptor.class);

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        log.info("Enter Interceptor.");
        String traceId = request.getHeader(LOG_TRACE_ID);
        if (StringUtils.isBlank(traceId)){
           traceId = UuidUtil.get32UUID();
        }
        MDC.put(LOG_TRACE_ID, traceId);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        MDC.remove(LOG_TRACE_ID);
    }
}

• 2、当微服务发起远程调用的时候，我们还需要将log_trace_id设置到Header中，保持完整调用链使用同一个log_trace_id。因为微服务之间调用全部统一使用Feign来调用，所以这里使用Feign提供的RequestInterceptor拦截器在Feign发起微服务调用之前将参数设置到请求头中。

/**
 * 当前服务Feign请求拦截器，设置请求头信息
 *
 * @author leon
 * @date 2020/7/14
 */
@Configuration
public class MyFeignRequestInterceptor implements RequestInterceptor{

    private final static Logger log = LoggerFactory.getLogger(MyFeignRequestInterceptor.class);

    @Override
    public void apply(RequestTemplate template) {
        String traceId = MDC.get(LOG_TRACE_ID);
        if (StringUtils.isNotBlank(traceId)){
            template.header(LOG_TRACE_ID, traceId);
        }
    }
}

问题来了

• 在调试的过程中出现了一个现象，在有的微服务中String traceId = MDC.get(LOG_TRACE_ID)这行代码是能够拿到traceId的，而有些微服务traceId却为null

填坑之路

在很多时候，我们对某些现象感到疑惑，绝大部分时候说明我们没有认真看文档，没有完整的概念、原理认知才会出现这种情况。

首先我们需要弄清楚MDC。在上边我们使用MDC(Mapped Diagnostic Context)这个类保存traceId并在Feign请求的时候取出来设置到Header中。简单来说，MDC就是由log4j库提供的一个InheritableThreadLocal<Map<String, String>>对象，我们将traceId设置到这个InheritableThreadLocal中，在同一个线程中/子线程中能够获取到之前我们在拦截器的K-V，同时我们还可以在日志配置文件中pattern中引用当前MDC设置的值%X{log_trace_id}，可以在每行日志中打印traceId对应的值。

通过上边对MDC的描述，我们可以猜测在MyFeignRequestInterceptor拦截类的线程和请求进入的RequestInterceptor拦截器设置traceId并不在同一个线程里。

为了验证想法，我们将线程组的名称、当前线程的ID、name打印出来。

ThreadGroup threadGroup = Thread.currentThread().getThreadGroup();
Thread thread = Thread.currentThread();
log.info("RequestInterceptor current thread group name: {}, current thread name: {} , id: {}", threadGroup.getName(), thread.getName(), thread.getId());
        
ThreadGroup threadGroup = Thread.currentThread().getThreadGroup();
Thread thread = Thread.currentThread();
log.info("MyFeignRequestInterceptor current thread group: {}, name: {} , id: {}", threadGroup.getName(), thread.getName(), thread.getId());

上边日志打印的结果如下：

RequestInterceptor current thread name: XNIO-5 task-1 , id: 187
MyFeignRequestInterceptor current thread name: hystrix-bling-share-xdfproducer-1 , id: 192

可以明显的看到在RequestInterceptor拦截类中的线程和MyFeignRequestInterceptor拦截类中的线程并不是同一个线程，也没有父子关系，所以在Feign的拦截类是无法获取到traceId。

所以现在的问题是如何解决不同线程之间数据共享的问题？

---

分析：虽然当前请求的两个拦截类不处于同一个线程内，但却是处于同一个请求的生命周期内，那我们只要找到一种方法把变量设置到一个request scope的共享变量，那么这个请求周期内无论有多少个线程，我们设置的信息就都可以随时被这次请求内的线程获取到，也就间接地实现了线程间的信息共享。

HystrixRequestVariableDefault

“Default implementation of HystrixRequestVariable. Similar to ThreadLocal but scoped at the user request level. Context is managed via HystrixRequestContext”

HystrixRequestVariableDefault类是Hystrix Concurrency包提供的一个类，类似于ThreadLocal，但是它的生命周期是用户请求级别的，所以我们来尝试用它来解决同义词请求线程间数据共享的问题。

在使用HystrixRequestVariableDefault类的时候要注意，因为这是一个整个请求范围内的，我们需要将其定义为一个全局的变量，同时要注意 Context is managed via HystrixRequestContext这句话，我们在使用之前需要使用HystrixRequestContext.initializeContext()来初始化，否则将会抛出NPE。

我们首先定义一个全局的HystrixRequestVariableDefault<String>对象。

public class HystrixCredentialsContext {

    public static final HystrixRequestVariableDefault<String> HYSTRIX_REQUEST_VARIABLE_DEFAULT =
            new HystrixRequestVariableDefault<>();

    public static HystrixRequestVariableDefault<String> getInstance(){
        return HYSTRIX_REQUEST_VARIABLE_DEFAULT;
    }
}

定义完全局变量之后，我们使用过滤器来实现请求的过滤，设置traceId。

public class HystrixRequestContextEnablerFilter implements Filter {
    private final static Logger log = LoggerFactory.getLogger(HystrixRequestContextEnablerFilter.class);
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HystrixRequestContext context = HystrixRequestContext.initializeContext();
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String traceId = httpRequest.getHeader(LOG_TRACE_ID);
        if (StringUtils.isBlank(traceId)){
            traceId = UuidUtil.get32UUID();
        }
          MDC.put(LOG_TRACE_ID, traceId);
        try {
            HystrixCredentialsContext.getInstance().set(traceId);
            log.info("Set traceId successful: {}", traceId);
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
            context.shutdown();
        }
    }
    @Override
    public void init(FilterConfig filterConfig) throws ServletException {}
    @Override
    public void destroy() {}
    }

好了，经过这一番改造，我们再来尝试在MyFeignRequestInterceptor类中获取log_trace_id.

@Configuration
public class MyFeignRequestInterceptor implements RequestInterceptor{
    private final static Logger log = LoggerFactory.getLogger(MyFeignRequestInterceptor.class);
    @Override
    public void apply(RequestTemplate template) {
           // 这里不再使用MDC来获取了
            String traceId = HystrixCredentialsContext.getInstance().get();
            log.info("print current thread logTraceId: {}", traceId);    
           if (StringUtils.isNotBlank(traceId)){
            template.header(LOG_TRACE_ID, traceId);
        }
    }
}

通过日志，我们能看到这次确实能够拿到traceId了，说明我们采用HystrixRequestVariableDefault来解决线程间的数据共享是成功的。

但是现在还有一个问题没解决：为什么有的服务不采用HystrixRequestVariableDefault来实现数据共享也能拿到traceId呢？

为了表述的方便，这里使用A来代表不采用HystrixRequestVariableDefault也能获取到MDC的traceID的微服务，B来代表采用这种方式的微服务。

为了定位问题，我们分别在两个微服务的请求过滤器和Feign调用拦截器中打印当前线程的线程组名称、线程名、线程ID信息来帮助定位问题，下面是日志打印:

A服务：
 main, thread name: XNIO-5 task-1, thread id: 185
 main, thread name: XNIO-5 task-1, thread id: 185

B服务：
main, thread name: XNIO-5 task-1, thread id: 177
main, thread name: hystrix-B-1, thread id: 182

从上边我们可以看出，A服务在过滤器和拦截器中均为同一个线程，所以才能通过MDC获取到traceId，而B服务并非同一个线程，自然无法通过MDC拿到。

那么现在问题来了，为什么A服务使用同一个线程，则B服务却是不同的线程？？

通过对比A和B的配置，发现在B的服务中配置了feign.hystrix.enabled=true，而A服务却没有配置，经过验证之后确认是因为此配置导致A和B在调用微服务时，采用了不同的线程策略。

Hystrix feign请求流程

在上边B服务配置了feign.hystrix.enabled=true参数，也就是说B服务的Feign调用开启了熔断的的功能，因为开启了熔断，所以发起远程调用的时候Hystrix重启根据当前所调用的微服务使用了一个新的线程去处理远程调用，下边是Feign发起远程调用的完整流程。

从上图可以看到，第1步就是通过JDK动态生成代理类代理类，比较重要的是下边这段代码。

@Override
  public Object invoke(final Object proxy, final Method method, final Object[] args)
      throws Throwable {
      .....
    HystrixCommand<Object> hystrixCommand = new HystrixCommand<Object>(setterMethodMap.get(method)) {
      @Override
      protected Object run() throws Exception {
        try {
          return HystrixInvocationHandler.this.dispatch.get(method).invoke(args);
        } catch (Exception e) {
          throw e;
        } catch (Throwable t) {
          throw (Error) t;
        }
      }
    .......

其中最重要的一行代码就是HystrixInvocationHandler.this.dispatch.get(method).invoke(args);它将会生成一个新的hystrixCommand，同时启动一个新的线程。具体细节可以参考这里Hystrix feign thread model。因为第一步就创建了新的线程，所以在上图中第五步拦截的时候使用的就是这个新创建的线程。

到这里为止，我们也就能解释为什么A服务使用了同一个线程，则B服务却是不同的线程。

总结

首先我们介绍了为什么要实现日志链路追踪的背景，它能给我们解决什么问题，随后分享了如何实现微服务之间的串联，在实现这个的目的的过程我们碰到了什么问题，以及排查定位问题的过程，最后我们如何解决这个问题的，希望能给大家解决类似问题提供一点思路吧。

参考

• Hystrix feign thread model
• SpringBoot+MDC实现全链路调用日志跟踪
• 在Java项目中使用traceId跟踪请求全流程日志
• Spring Cloud OpenFeign source code analysis
• Feign源码分析:记初次使用Feign踩的一些坑