MDC实现微服务日志链路追踪

问题分析

在高并发情况下，我们没办法快速定位用户在一次请求中对应的所有日志，或者说是定位某个用户操作的所有日志，在追踪用户行为或排查生产问题会显得十分棘手，那是因为我们在输出的日志的时候没把请求的唯一标示或者说是用户身份标示输出到我们的日志中，导致我们没办法根据一个请求或者用户身份标识来做日志的过滤。

解决方案

我们在记录日志的时候把请求的唯一标识（sessionId）或者身份标识（userId） 记录到日志中这个问题就可以得到很好的解决了（本文使用UUID）并在每次输出log的时候将这个UUID输出到日志中。

知识点

• MDC
• Spring拦截器（HandlerInterceptor）
• Spring Cloud Feign拦截器（RequestInterceptor）
• Spring Cloud Hystrix的隔离策略
• 以上知识点详细各位同学可自行补习

引入JAR包

		<!--spring拦截器-->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <version>2.3.4.RELEASE</version>
        </dependency>
        <!-- feign请求拦截 -->
        <dependency>
            <groupId>com.moonciki.strongfeign</groupId>
            <artifactId>feign-core</artifactId>
            <version>10.2.3</version>
        </dependency>
        <!-- hystrix线程池隔离工具包 -->
        <dependency>
            <groupId>com.netflix.hystrix</groupId>
            <artifactId>hystrix-core</artifactId>
            <version>1.5.12</version>
        </dependency>

MDC

• MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。

实现拦截器LogInterceptor

/**
 * @Author 
 * @Date 2020/12/10
 * @Description 通过拦截器高并发场景下日志打印线程ID
 */
@Slf4j
public class LogInterceptor implements HandlerInterceptor {

    //线程ID常量
    private static final String THREAD_ID = "THREAD_ID";

    /**
     * controller方法前调用
     */
    @Override
    public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o) throws Exception {
        log.debug("preHandle running ...");
        //随机生成UUID
        String threadId = UUID.randomUUID().toString().trim().replaceAll("-", "");
        //添加到MDC
        MDC.put(THREAD_ID,threadId);
        }
        //永远返回true
        return true;
    }

    /**
     * preHandle方法返回true之后
     * 在controller方法处理完之后调用
     */
    @Override
    public void postHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o, ModelAndView modelAndView) throws Exception {
        //清空MDC的THREAD_ID
        MDC.remove(THREAD_ID);
    }

    /**
     * preHandle方法返回true之后
     * 在DispatcherServlet进行视图的渲染之后调用
     */
    @Override
    public void afterCompletion(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o, Exception e) throws Exception {
    }
}

注册拦截器

/**
 * @Author 
 * @Date 2020/12/10
 * @Description 配置拦截器
 */
@Configuration
public class ApplicationWebMvcConfig implements WebMvcConfigurer {

    /**
     * 注解LogInterceptor类到IOC容器中
     */
    @Bean
    public LogInterceptor logInterceptor() {
        return new LogInterceptor();
    }

    @Override
    public void addInterceptors(InterceptorRegistry interceptorRegistry) {
        interceptorRegistry.addInterceptor(logInterceptor());
    }
}

Logback配置输出THREAD_ID

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{THREAD_ID}] [%thread] %level %c{1.}.%M - %msg%n</pattern>

日志输出示例

20-12-21 19:02:15.965 [428ee1b3378341c4a40325441237dd5f] [http-nio-8087-exec-6] INFO com.xxxxxxxxxxx.日志XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
20-12-21 19:02:15.966 [428ee1b3378341c4a40325441237dd5f] [http-nio-8087-exec-6] INFO com.xxxxxxxxxxx.日志XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
20-12-21 19:02:15.967 [428ee1b3378341c4a40325441237dd5f] [http-nio-8087-exec-6] INFO com.xxxxxxxxxxx.日志XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

以上单应用服务器日志的链路追踪就已经实现了，那么在分布式服务下如何做到多台服务链路追踪呢？

• 第一种Spring Cloud Sleuth（Spring Cloud提供的组件）本博客不详解
• 第二种在服务A调用服务B时从MDC中取出对应的属性添加到Header，在B服务通过AOP拦截器获取到相同的MDC属性值

实现Feign拦截器

/**
 * @Author 
 * @Date 2020/12/15
 * @Description Feign拦截器实现链路追踪
 */
@Slf4j
@Component
public class FeignInterceptor implements RequestInterceptor {

    //线程ID常量
    private static final String THREAD_ID = "THREAD_ID";

    @Override
    public void apply(RequestTemplate requestTemplate) {
        log.info("进入feign拦截器...THREAD_ID:{}",MDC.get(THREAD_ID));
        requestTemplate.header(THREAD_ID, MDC.get(THREAD_ID));
    }
}

2020-12-23 20:23:33.518 [] [hystrix-iuss-core-insure-1] INFO com.xxxxxxxxxxxxxxxxxxxx - 进入feign拦截器...THREAD_ID:null

当Feign开启Hystrix时MDC.get为null，这样我们就无法往下游服务传递MDC的值。
原因在于，Hystrix的默认隔离策略是THREAD，当隔离策略为 THREAD 时，是没办法拿到 ThreadLocal 中的值的

解决方案

Hystrix的资源隔离策略分为两种：线程池（THREAD）和信号量（SEMAPHORE）

1. 调整隔离策略

hystrix.command.default.execution.isolation.strategy: SEMAPHORE

这样配置后，Feign拦截器中就能获取MDC值，但该方案不是特别好。原因是Hystrix官方强烈建议使用THREAD作为隔离策略！可以参考官方文档说明。

2. 自定义策略扩展HystrixConcurrencyStrategy并通过HystrixPlugins注册

/**
 * @Author
 * @Date 2020/12/15
 * @Description Hystrix线程池隔离支持日志链路跟踪
 */
@Component
public class MdcHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy {

    public MdcHystrixConcurrencyStrategy() {
    	//干掉原有包里的bean，否则启动会报重复注入
        HystrixPlugins.reset();
        HystrixPlugins.getInstance().registerConcurrencyStrategy(this);
    }

    @Override
    public <T> Callable<T> wrapCallable(Callable<T> callable) {
        return new MdcAwareCallable(callable, MDC.getCopyOfContextMap());
    }

    private class MdcAwareCallable<T> implements Callable<T> {

        private final Callable<T> delegate;

        private final Map<String, String> contextMap;

        public MdcAwareCallable(Callable<T> callable, Map<String, String> contextMap) {
            this.delegate = callable;
            this.contextMap = contextMap != null ? contextMap : new HashMap();
        }

        @Override
        public T call() throws Exception {
            try {
                MDC.setContextMap(contextMap);
                return delegate.call();
            } finally {
                MDC.clear();
            }
        }
    }
}

这样我们在Fegin拦截器中在MDC中取出对应的属性添加到Heade，然后在下游服务实现拦截器获取MDC值，输出在日志中。

2020-12-23 20:30:39.499 [4503027483c746079a9e31ba0e052847] [hystrix-iuss-core-insure-1] INFO com.xxxxxxxxxxxxxxxxx.apply - 进入feign拦截器...THREAD_ID:4503027483c746079a9e31ba0e052847

下游服务器实现拦截器

    public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object o) throws Exception {
        log.debug("preHandle running ...getHeader：{}",httpServletRequest.getHeader(THREAD_ID));
        String threadId = httpServletRequest.getHeader(THREAD_ID);
        //判断MDC(log4j中的上下文对象) 中是否有该threadId
        if (StringUtils.isEmpty(threadId)) {
            //如果没有，添加
            String uuId = UUID.randomUUID().toString().trim().replaceAll("-", "");
            MDC.put(THREAD_ID,uuId);
        }else{
            //如果上层服务有则直接使用
            MDC.put(THREAD_ID,threadId);
        }
        //永远返回true
        return true;
    }

2020-12-23 20:36:32.829 [] [http-nio-18203-exec-9] INFO com.cignacmb.iuss.core.common.util.interceptor.LogInterceptor.preHandle - preHandle running ...getHeader:d93436cadd62413aa64b6c47d58f8b8f

下游服务器Logback配置输出THREAD_ID

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{THREAD_ID}] [%thread] %level %c{1.}.%M - %msg%n</pattern>

下游服务日志输出

2020-12-23 20:38:05.529 [d93436cadd62413aa64b6c47d58f8b8f] [http-nio-18203-exec-9] INFO com.XXXXXXXcontroller.日志XXXXXXXXXXXXXXXXXXXXXXXX
2020-12-23 20:38:05.600 [d93436cadd62413aa64b6c47d58f8b8f] [http-nio-18203-exec-9] DEBUG com.XXXXXXXcontroller.日志XXXXXXXXXXXXXXXXXXXXXXXX
2020-12-23 20:38:05.600 [d93436cadd62413aa64b6c47d58f8b8f] [http-nio-18203-exec-9] DEBUG com.XXXXXXXcontroller.日志XXXXXXXXXXXXXXXXXXXXXXXX
2020-12-23 20:38:05.603 [d93436cadd62413aa64b6c47d58f8b8f] [http-nio-18203-exec-9] DEBUG com.XXXXXXXcontroller.日志XXXXXXXXXXXXXXXXXXXXXXXX
2020-12-23 20:38:05.707 [d93436cadd62413aa64b6c47d58f8b8f] [http-nio-18203-exec-9] INFO com.XXXXXXXcontroller.日志XXXXXXXXXXXXXXXXXXXXXXXX

高并发情况下对日志的链路追踪就已经实现了

                  船停泊在港湾里非常安全，但那不是造船的目的。