SpringBoot 添加 MDC 日志链路追踪

日志链路追踪的意思就是将一个标志跨线程进行传递，在一般的小项目中也就是在你新起一个线程的时候，或者使用线程池执行任务的时候会用到，比如追踪一个用户请求的完整执行流程。

这里用到MDC和ThreadLocal，分别由下面的包提供：

java.lang.ThreadLocal
org.slf4j.MDC

直接上代码：

1. 线程池配置

如果你直接通过手动新建线程来执行异步任务，想要实现标志传递的话，需要自己去实现，其实和线程池一样，也是调用MDC的相关方法，如下所示：

//取出父线程的MDCMap<String,String> context= MDC.getCopyOfContextMap();//将父线程的MDC内容传给子线程
MDC.setContextMap(context);

首先提供一个常量：

packagecom.example.demo.common.constant;/**
 * 常量
 *
 * @author wangbo
 * @date 2021/5/13
 */publicclassConstants{publicstaticfinalString LOG_MDC_ID="trace_id";}

接下来需要对ThreadPoolTaskExecutor的方法进行重写：

packagecom.example.demo.common.threadpool;importcom.example.demo.common.constant.Constants;importlombok.extern.slf4j.Slf4j;importorg.slf4j.MDC;importorg.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;importjava.util.Map;importjava.util.UUID;importjava.util.concurrent.Callable;importjava.util.concurrent.Future;/**
 * MDC线程池
 * 实现内容传递
 *
 * @author wangbo
 * @date 2021/5/13
 */@Slf4jpublicclassMdcTaskExecutorextendsThreadPoolTaskExecutor{@Overridepublic<T>Future<T>submit(Callable<T> task){
        log.info("mdc thread pool task executor submit");Map<String,String> context= MDC.getCopyOfContextMap();returnsuper.submit(()->{T result;if(context!=null){//将父线程的MDC内容传给子线程
                MDC.setContextMap(context);}else{//直接给子线程设置MDC
                MDC.put(Constants.LOG_MDC_ID, UUID.randomUUID().toString().replace("-",""));}try{//执行任务
                result= task.call();}finally{try{
                    MDC.clear();}catch(Exception e){
                    log.warn("MDC clear exception", e);}}return result;});}@Overridepublicvoidexecute(Runnable task){
        log.info("mdc thread pool task executor execute");Map<String,String> context= MDC.getCopyOfContextMap();super.execute(()->{if(context!=null){//将父线程的MDC内容传给子线程
                MDC.setContextMap(context);}else{//直接给子线程设置MDC
                MDC.put(Constants.LOG_MDC_ID, UUID.randomUUID().toString().replace("-",""));}try{//执行任务
                task.run();}finally{try{
                    MDC.clear();}catch(Exception e){
                    log.warn("MDC clear exception", e);}}});}}

然后使用自定义的重写子类MdcTaskExecutor来实现线程池配置：

packagecom.example.demo.common.threadpool;importlombok.extern.slf4j.Slf4j;importorg.springframework.context.annotation.Bean;importorg.springframework.context.annotation.Configuration;importjava.util.concurrent.Executor;importjava.util.concurrent.ThreadPoolExecutor;/**
 * 线程池配置
 *
 * @author wangbo
 * @date 2021/5/13
 */@Slf4j@ConfigurationpublicclassThreadPoolConfig{/**
     * 异步任务线程池
     * 用于执行普通的异步请求，带有请求链路的MDC标志
     */@BeanpublicExecutorcommonThreadPool(){
        log.info("start init common thread pool");//ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();MdcTaskExecutor executor=newMdcTaskExecutor();//配置核心线程数
        executor.setCorePoolSize(10);//配置最大线程数
        executor.setMaxPoolSize(20);//配置队列大小
        executor.setQueueCapacity(3000);//配置空闲线程存活时间
        executor.setKeepAliveSeconds(120);//配置线程池中的线程的名称前缀
        executor.setThreadNamePrefix("common-thread-pool-");//当达到最大线程池的时候丢弃最老的任务
        executor.setRejectedExecutionHandler(newThreadPoolExecutor.DiscardOldestPolicy());//执行初始化
        executor.initialize();return executor;}/**
     * 定时任务线程池
     * 用于执行自启动的任务执行，父线程不带有MDC标志，不需要传递，直接设置新的MDC
     * 和上面的线程池没啥区别，只是名字不同
     */@BeanpublicExecutorscheduleThreadPool(){
        log.info("start init schedule thread pool");MdcTaskExecutor executor=newMdcTaskExecutor();
        executor.setCorePoolSize(10);
        executor.setMaxPoolSize(20);
        executor.setQueueCapacity(3000);
        executor.setKeepAliveSeconds(120);
        executor.setThreadNamePrefix("schedule-thread-pool-");
        executor.setRejectedExecutionHandler(newThreadPoolExecutor.DiscardOldestPolicy());
        executor.initialize();return executor;}}

2. 拦截器配置

packagecom.example.demo.common.interceptor;importcom.example.demo.common.constant.Constants;importlombok.extern.slf4j.Slf4j;importorg.slf4j.MDC;importorg.springframework.stereotype.Component;importorg.springframework.web.servlet.HandlerInterceptor;importorg.springframework.web.servlet.ModelAndView;importjavax.servlet.http.HttpServletRequest;importjavax.servlet.http.HttpServletResponse;importjava.util.UUID;/**
 * 日志拦截器
 *
 * @author wangbo
 * @date 2021/5/13
 */@Slf4j@ComponentpublicclassLogInterceptorimplementsHandlerInterceptor{@OverridepublicbooleanpreHandle(HttpServletRequest request,HttpServletResponse response,Object handler)throwsException{//log.info("进入 LogInterceptor");//添加MDC值
        MDC.put(Constants.LOG_MDC_ID, UUID.randomUUID().toString().replace("-",""));//打印接口请求信息String method= request.getMethod();String uri= request.getRequestURI();
        log.info("[请求接口] : {} : {}", method, uri);//打印请求参数returntrue;}@OverridepublicvoidpostHandle(HttpServletRequest request,HttpServletResponse response,Object handler,ModelAndView modelAndView)throwsException{//log.info("执行 LogInterceptor");}@OverridepublicvoidafterCompletion(HttpServletRequest request,HttpServletResponse response,Object handler,Exception ex)throwsException{//log.info("退出 LogInterceptor");//打印请求结果//删除MDC值
        MDC.remove(Constants.LOG_MDC_ID);}}

对拦截器进行注册：

packagecom.example.demo.common.config;importcom.example.demo.common.interceptor.LogInterceptor;importorg.springframework.beans.factory.annotation.Autowired;importorg.springframework.context.annotation.Configuration;importorg.springframework.web.servlet.config.annotation.InterceptorRegistry;importorg.springframework.web.servlet.config.annotation.WebMvcConfigurer;/**
 * MVC配置
 *  * @author wangbo
 * @date 2021/5/13
 */@ConfigurationpublicclassWebMvcConfigimplementsWebMvcConfigurer{@AutowiredprivateLogInterceptor logInterceptor;/**
     * 拦截器注册
     */@OverridepublicvoidaddInterceptors(InterceptorRegistry registry){
        registry.addInterceptor(logInterceptor);}}

3. 日志文件配置

需要在logback-spring.xml文件中的日志打印格式里添加%X{trace_id}，如下所示：

<!-- 控制台打印日志的相关配置 --><appendername="console_out"class="ch.qos.logback.core.ConsoleAppender"><!-- 日志格式 --><encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{trace_id}] [%level] [%thread] [%class:%line] - %m%n</pattern><charset>UTF-8</charset></encoder></appender>

也可以简单配置，下面是在 application.properties 文件中配置的 SpringBoot 默认日志打印格式，只是在其中添加了%clr([%X{trace_id}])

logging.level.root=info
logging.pattern.console=%clr(%d{${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr([%X{trace_id}]) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}

4. 异步方法使用

这里注意，异步方法的调用不能直接调用当前类的方法，也就是说调用方法和异步方法不能在同一个类里，否则会变为同步执行。

/**
     * 异步方法
     *///@Async//这种写法，当只有一个线程池时，会使用该线程池执行，有多个则会使用SimpleAsyncTaskExecutor@Async(value="commonThreadPool")//指定执行的线程池@Overridepublicvoidasync(){
        log.info("测试异步线程池");}

有时候会发现 @Async 注解没有生效，失效原因：

• @SpringBootApplication 启动类上没有添加 @EnableAsync 注解。
• 异步方法使用注解 @Async 的返回值只能为 void 或者 Future。
• 没有走 Spring 的代理类。因为 @Transactional 和 @Async 注解的实现都是基于 Spring 的 AOP，而 AOP 的实现是基于动态代理模式实现的。那么注解失效的原因就很明显了，有可能因为调用方法的是对象本身而不是代理对象，没有经过 Spring 容器管理。
  • 注解的方法必须是 public 方法。
  • 方法一定要从另一个类中调用，也就是从类的外部调用，类的内部调用是无效的。
  • 如果需要从类的内部调用，需要先获取其代理类。

5. 定时任务使用

packagecom.example.demo.generator.crontab;importlombok.extern.slf4j.Slf4j;importorg.springframework.stereotype.Component;importjava.time.LocalDateTime;/**
 * 定时任务
 *
 * @author wangbo
 * @date 2021/5/14
 */@Slf4j@ComponentpublicclassTestTimeTask{//基于注解@Scheduled默认为单线程，开启多个任务时，任务的执行时机会受上一个任务执行时间的影响。//使用的线程池是taskScheduler，线程ID为scheduling-x//添加@Async注解指定线程池，则可以多线程执行定时任务（原本是单线程的）。/**
     * 两次任务开始的时间间隔为2S
     * 不使用线程池，单线程间隔则为4S。单线程保证不了这个2S间隔，因为任务执行耗时超过了定时间隔，就会影响下一次任务的执行
     * 使用线程池，多线程执行，时间间隔为2S
     *///@Async(value = "scheduleThreadPool")//@Scheduled(fixedRate = 2000)publicvoidfixedRate(){
        log.info("定时间隔任务 fixedRate = {}",LocalDateTime.now());try{Thread.sleep(4_000);}catch(InterruptedException e){
            e.printStackTrace();}}/**
     * 下次任务的开始时间距离上次任务的结束时间间隔为2S
     * 这种适合使用单线程，不适合使用线程池，单线程间隔则为6S。
     * 用了线程池，和这个特性相背离了
     *///@Scheduled(fixedDelay = 2_000)publicvoidfixedDelay(){
        log.info("延迟定时间隔任务 fixedDelay = {}",LocalDateTime.now());try{Thread.sleep(4_000);}catch(InterruptedException e){
            e.printStackTrace();}}/**
     * 首次延迟10S后执行fixedRate类型间隔任务，也可以配置为fixedDelay类型间隔任务
     * 控件第一次执行之前要延迟的毫秒数
     * {@link # fixedRate} or {@link #fixedDelay}
     *///@Scheduled(initialDelay = 10_000, fixedDelay = 1_000)publicvoidinitialDelay(){
        log.info("首次延迟定时间隔任务 initialDelay = {}",LocalDateTime.now());}/**
     * 这里使用线程池也是为了防止任务执行耗时超过了定时间隔，就会影响下一次任务的执行
     *///@Async(value = "scheduleThreadPool")//@Scheduled(cron = "0/2 * * * * *")publicvoidtestCron(){
        log.info("测试表达式定时任务 testCron = {}",LocalDateTime.now());try{Thread.sleep(4_000);}catch(InterruptedException e){
            e.printStackTrace();}}}