springboot实现日志追踪

一、MDC介绍

​ MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 、logback及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。

二、API说明

• clear() => 移除所有MDC
• get (String key) => 获取当前线程MDC中指定key的值
• getContext() => 获取当前线程MDC的MDC
• put(String key, Object o) => 往当前线程的MDC中存入指定的键值对
• remove(String key) => 删除当前线程MDC中指定的键值对

三、优点

• 代码简洁，日志风格统一，不需要在log打印中手动拼写traceId，即LOGGER.info("traceId:{} ", traceId)

四、代码实现

4.1 请求没有子线程

4.1.1 实现日志拦截器

@Component
public class LogInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    System.out.println("进入拦截器");
    //如果有上层调用就用上层的ID
    String traceId = request.getHeader(Constants.TRACE_ID);
    if (traceId == null) {
        traceId = TraceIdUtil.getTraceId();
    }

    MDC.put(Constants.TRACE_ID, traceId);
    return true;
}

@Override
public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
    throws Exception {
}

@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
    throws Exception {
    //调用结束后删除
    System.out.println("调用结束");
    MDC.remove(Constants.TRACE_ID);
}
}

4.2.2 注册拦截器

@Configuration
public class MvcInterceptorConfig extends WebMvcConfigurationSupport {
@Autowired
private LogInterceptor logInterceptor;

@Override
protected void addInterceptors(InterceptorRegistry registry) {
    // 多个拦截器组成一个拦截器链
    // addPathPatterns 用于添加拦截规则，/**表示拦截所有请求
    // excludePathPatterns 用户排除拦截
    registry.addInterceptor(logInterceptor).addPathPatterns("/**");
    super.addInterceptors(registry);
}
}

4.3.3 日志输出格式设置

<property name="LOG_PATTERN_CONSOLE">
	[TRACEID:%X{traceId}] %clr{%d{HH:mm:ss.SSS}}{faint} %clr{%5p} %clr{[%15.15t]}{faint} %clr{%C{1.}(%M:%L)}{cyan} %clr{:}{faint} %m%n%xwEx
</property>

需要注意%X{traceId}中的threadId 需要和日志拦截中MDC put的key是一样的

4.2 请求有子线程的情况

​ slf4j的MDC机制其内部基于ThreadLocal实现。所以我们调用 MDC.put()方法传入的请求ID只在当前线程有效。所以，主线程中设置的MDC数据，在其子线程（线程池）中是无法获取的。

官方建议

1）在父线程新建子线程之前调用MDC.getCopyOfContextMap()方法将MDC内容取出来传给子线程

2）子线程在执行操作前先调用MDC.setContextMap()方法将父线程的MDC内容设置到子线程

代码实现：

1）使用Aop拦截请求，与上面相同

2）log4j日志配置与上面相同

3）装饰器模式装饰子线程，有两种方式

4.2.1 实现方式1——装饰Runnable

​ 使用装饰器模式，对Runnable接口进行一层装饰，在创建MDCRunnable类对Runnable接口进行一层装饰。

在创建MDCRunnable类时保存当前线程的MDC值，再执行run()方法

public class MDCRunnable implements Runnable{

private Runnable runnable;

/**
 * 保存当前主线程的MDC值
 */
private final Map<String, String> mainMdcMap;

public MDCRunnable(Runnable runnable) {
    this.runnable = runnable;
    this.mainMdcMap = MDC.getCopyOfContextMap();
}

@Override
public void run() {
    // 将父线程的MDC值赋给子线程
    for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
        MDC.put(entry.getKey(), entry.getValue());
    }
    // 执行被装饰的线程run方法
    runnable.run();
    // 执行结束移除MDC值
    for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
       MDC.remove(entry.getKey());
    }
  }
}

测试：使用MDCRunnable代替Runnable

@PostMapping("/test")
public String test(@RequestBody String str){
    log.info("进入test请求方法");
    SmsThreadPoolUtil.getInstance().execute(new MDCRunnable(new Runnable() {
        @Override
        public void run() {
            log.info("子线程1执行任务");
        }
    }));
    executorService.execute(new MDCRunnable(new Runnable() {
        @Override
        public void run() {
            log.info("子线程2执行任务");
        }
    }));

    log.info("test方法执行结束");
    return str;
}

[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.857 DEBUG [nio-9999-exec-1] o.s.c.l.LogFormatUtils(traceDebug:91) : Read "application/json;charset=UTF-8" to ["{
    "str":"11111111"
}"]
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.863  INFO [nio-9999-exec-1] c.t.c.TestController(test:41) : 进入test请求方法
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [pool-3-thread-1] c.t.c.TestController$1(run:45) : 子线程1执行任务
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [nio-9999-exec-1] c.t.c.TestController(test:55) : test方法执行结束
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.865  INFO [pool-2-thread-1] c.t.c.TestController$2(run:51) : 子线程2执行任务
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.871 DEBUG [nio-9999-exec-1] o.s.w.s.m.m.a.AbstractMessageConverterMethodProcessor(writeWithMessageConverters:268) : Using 'text/plain', given [*/*] and supported [text/plain, */*, application/json, application/*+json]
[TRACEID:4dead5ddd1a34d10a19ae286dea56ab3] 16:24:20.872 DEBUG [nio-9999-exec-1] o.s.c.l.LogFormatUtils(traceDebug:91) : Writing ["{
    "str":"11111111"
}"]

4.2.2 实现方式2——装饰线程池

public class MDCThreadPoolExecutor extends ThreadPoolExecutor {
public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
}

public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                    BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,
                                    RejectedExecutionHandler handler) {
    super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
}

@Override
public void execute(final Runnable runnable) {
    // 获取父线程MDC中的内容，必须在run方法之前，否则等异步线程执行的时候有可能MDC里面的值已经被清空了，这个时候就会返回null
    final Map<String, String> context = MDC.getCopyOfContextMap();
    super.execute(new Runnable() {
        @Override
        public void run() {
            // 将父线程的MDC内容传给子线程
            MDC.setContextMap(context);
            try {
                // 执行异步操作
                runnable.run();
            } finally {
                // 清空MDC内容
                MDC.clear();
            }
        }
    });
  }
}

测试：用MDCThreadPoolExecutor 代替ThreadPoolExecutor

public class SmsThreadPoolUtil {
	//定义类型
	private static ThreadPoolExecutor pool=new MDCThreadPoolExecutor(10, 20,
			10, TimeUnit.SECONDS, new LinkedBlockingDeque<Runnable>(10000), new RejectedPoolUtils());
	
	public static ThreadPoolExecutor getInstance() {
		return pool;
	}
}

@Service
@Slf4j
public class RejectedPoolUtils implements RejectedExecutionHandler{
	@Override
	public void rejectedExecution(Runnable r, ThreadPoolExecutor executor) {
		log.info("队列达到最大数");
	}
}

@PostMapping("/test")
public String test(@RequestBody String str){
    log.info("进入test请求方法");
    SmsThreadPoolUtil.getInstance().execute(new Runnable() {
        @Override
        public void run() {
            log.info("子线程1执行任务");
        }
    });
    log.info("test方法执行结束");
    return str;
}