详解Java如何在CompletableFuture中实现日志记录

平时写项目的时候，java之父叫我们多打日志，我们通常使用traceId和requestId来保存完整请求的链路日志，例如市面上的skywalking、zipkin等都能实现此功能。

下面介绍一种slf4j自带的MDC类，来记录完整的请求日志，和在CompletableFuture异步线程中如何保留链路id

1.首先利用aop为所有请求入口添加requestId。

@Aspect
@Component
public class LoggingAspect {

/**
    * AOP注解的Controller类方法必须为 public 或 protect ，千万不能用private！！！！！！！！否则会@Autowired注入的service会报空指针异常。
    * 私有方法和字段不属于Spring上下文中的bean属性。
    */
   @Around("@annotation(org.springframework.web.bind.annotation.GetMapping) || " +
           "@annotation(org.springframework.web.bind.annotation.PostMapping) || " +
           "@annotation(org.springframework.web.bind.annotation.PutMapping) || " +
           "@annotation(org.springframework.web.bind.annotation.DeleteMapping)")
   public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
       // 在logback-spring.xml里对应％X{requestId}
       MDC.put("requestId", UUID.randomUUID().toString().substring(0, 13));  // Add request ID to MDC
       try {
           return joinPoint.proceed(); // Execute method
       } finally {
           MDC.remove("requestId");  // Remove request ID from MDC
       }
   }
}

2.定义一下 logback-spring.xml ，引入 requestId 来进行链路记录，关键代码是 ％X{requestId}

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
   <!-- 控制台日志格式 -->
   <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-％clr(％d{yyyy-MM-dd HH:mm:ss.SSS}){faint} ％X{requestId} ％clr(${LOG_LEVEL_PATTERN:-％5p}) ％clr(${PID:- }){magenta} ％clr(---){faint} ％clr([％15.15t]){faint} ％clr(％-40.40logger{39}){cyan} ％clr(:){faint} ％m％n${LOG_EXCEPTION_CONVERSION_WORD:-％wEx}}"/>
   <!-- 控制台日志格式 依赖的渲染类 -->
   <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
   <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
   <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />
   <!-- 输出到控制台 -->
   <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
       <encoder>
           <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
               <level>debug</level>
           </filter>
           <!-- 配置日志输出格式 -->
           <pattern>${CONSOLE_LOG_PATTERN}</pattern>
           <!-- 使用的字符集 -->
           <charset>UTF-8</charset>
       </encoder>
   </appender>

<!-- 定义输出的路径，获取application.yml的source的值 -->
   <springProperty scope="context" name="LOG_FILE_PATH" source="logging.file-location" default="/var/log/myapp"/>
   <!-- 2.输出到文件 -->
   <!-- 2.1 level为 DEBUG 日志，时间滚动输出  -->
   <appender name="DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>${LOG_FILE_PATH}/debug.log</file> <!-- 文件路径 -->
       <encoder>
           <pattern>％d{yyyy-MM-dd HH:mm:ss.SSS} ％X{requestId} [％thread] ％-5level ％logger{50} - ％msg％n</pattern><!-- 日志文档输出格式 -->
           <charset>UTF-8</charset>
       </encoder>
       <!-- 日志记录器的滚动策略，按日期，按大小记录 -->
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
           <!-- 每天新开一个文件 -->
           <fileNamePattern>${LOG_FILE_PATH}/debug-％d{yyyy-MM-dd}.％i.log</fileNamePattern>
           <!-- 每天100m新开一个文件 -->
           <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
               <maxFileSize>100MB</maxFileSize>
           </timeBasedFileNamingAndTriggeringPolicy>
           <!-- 日志文档保留天数 -->
           <maxHistory>15</maxHistory>
           <!-- 用来指定日志文件的上限大小，例如设置为1GB的话，那么到了这个值，就会删除旧的日志。 -->
           <totalSizeCap>1GB</totalSizeCap>
       </rollingPolicy>
       <!-- 此日志文档只记录debug级别的 -->
       <filter class="ch.qos.logback.classic.filter.LevelFilter">
           <level>debug</level>
           <onMatch>ACCEPT</onMatch>
           <onMismatch>DENY</onMismatch>
       </filter>
   </appender>

<!-- 2.2 level为 INFO 日志，时间滚动输出  -->
   <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>${LOG_FILE_PATH}/info.log</file>
       <encoder>
           <pattern>％d{yyyy-MM-dd HH:mm:ss.SSS} ％X{requestId} [％thread] ％-5level ％logger{50} - ％msg％n</pattern>
           <charset>UTF-8</charset>
       </encoder>
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
           <fileNamePattern>${LOG_FILE_PATH}/info-％d{yyyy-MM-dd}.％i.log</fileNamePattern>
           <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
               <maxFileSize>100MB</maxFileSize>
           </timeBasedFileNamingAndTriggeringPolicy>
           <maxHistory>15</maxHistory>
       </rollingPolicy>
       <!-- 此日志文档只记录info级别的 -->
       <filter class="ch.qos.logback.classic.filter.LevelFilter">
           <level>info</level>
           <onMatch>ACCEPT</onMatch>
           <onMismatch>DENY</onMismatch>
       </filter>
   </appender>

<!-- 2.3 level为 WARN 日志，时间滚动输出  -->
   <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>${LOG_FILE_PATH}/warn.log</file>
       <encoder>
           <pattern>％d{yyyy-MM-dd HH:mm:ss.SSS} ％X{requestId} [％thread] ％-5level ％logger{50} - ％msg％n</pattern>
           <charset>UTF-8</charset> <!-- 此处设置字符集 -->
       </encoder>
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
           <fileNamePattern>${LOG_FILE_PATH}/warn-％d{yyyy-MM-dd}.％i.log</fileNamePattern>
           <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
               <maxFileSize>100MB</maxFileSize>
           </timeBasedFileNamingAndTriggeringPolicy>
           <maxHistory>15</maxHistory>
       </rollingPolicy>
       <!-- 此日志文档只记录warn级别的 -->
       <filter class="ch.qos.logback.classic.filter.LevelFilter">
           <level>warn</level>
           <onMatch>ACCEPT</onMatch>
           <onMismatch>DENY</onMismatch>
       </filter>
   </appender>

<!-- 2.4 level为 ERROR 日志，时间滚动输出  -->
   <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>${LOG_FILE_PATH}/error.log</file>
       <!--日志文档输出格式-->
       <encoder>
           <pattern>％d{yyyy-MM-dd HH:mm:ss.SSS} ％X{requestId} [％thread] ％-5level ％logger{50} - ％msg％n</pattern>
           <charset>UTF-8</charset>
       </encoder>
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
           <fileNamePattern>${LOG_FILE_PATH}/error-％d{yyyy-MM-dd}.％i.log</fileNamePattern>
           <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
               <maxFileSize>100MB</maxFileSize>
           </timeBasedFileNamingAndTriggeringPolicy>
           <maxHistory>15</maxHistory>
       </rollingPolicy>
       <!-- 此日志文档只记录ERROR级别的 -->
       <filter class="ch.qos.logback.classic.filter.LevelFilter">
           <level>ERROR</level>
           <onMatch>ACCEPT</onMatch>
           <onMismatch>DENY</onMismatch>
       </filter>
   </appender>

<!-- 使用异步，一个AsyncAppender只能添加一个appender-ref -->
   <appender name="ASYNC_DEBUG_FILE" class="ch.qos.logback.classic.AsyncAppender">
       <appender-ref ref="DEBUG_FILE"/>
   </appender>
   <appender name="ASYNC_INFO_FILE" class="ch.qos.logback.classic.AsyncAppender">
       <appender-ref ref="INFO_FILE"/>
   </appender>
   <appender name="ASYNC_WARN_FILE" class="ch.qos.logback.classic.AsyncAppender">
       <appender-ref ref="WARN_FILE"/>
   </appender>
   <appender name="ASYNC_ERROR_FILE" class="ch.qos.logback.classic.AsyncAppender">
       <appender-ref ref="ERROR_FILE"/>
   </appender>

<!-- 开启上面的appender -->
   <root level="info">
       <appender-ref ref="CONSOLE" />
       <appender-ref ref="ASYNC_DEBUG_FILE" />
       <appender-ref ref="ASYNC_INFO_FILE" />
       <appender-ref ref="ASYNC_WARN_FILE" />
       <appender-ref ref="ASYNC_ERROR_FILE" />
   </root>

</configuration>

2.定义一个`复杂`业务流程，来看看日志的实力

private final ExecutorService executorService = Executors.newFixedThreadPool(4);

@GetMapping("saveUser")
   public String saveUser() {
   log.info("进入了saveUser");
   // 异步
   CompletableFuture.runAsync(()-> b(), executorService);
   log.info("退出了saveUser");
   return "Ok";
}

private void b() {
   log.info("进入了b");
}

日志如下，可以看到异步线程的requestId丢失了，21dbaad3-3158 这个就是requestId，这种情况下我们需要自定义线程类来保存MDC的上下文

2023-04-19 11:51:59.309 21dbaad3-3158  INFO 23044 --- [p-nio-80-exec-1] c.h.m.api.CompletableFutureApi           : 进入了saveUser
2023-04-19 11:51:59.312 21dbaad3-3158  INFO 23044 --- [p-nio-80-exec-1] c.h.m.api.CompletableFutureApi           : 退出了saveUser
2023-04-19 11:51:59.312   INFO 23044 --- [pool-1-thread-1] c.h.m.api.CompletableFutureApi           : 进入了b

3.定义线程实现类，并且在构造函数中存储MDC的上下文

public static class MdcTaskWrapper implements Runnable {
   private final Runnable task;
   private final Map<String, String> contextMap;

public MdcTaskWrapper(Runnable task) {
       this.task = task;
       this.contextMap = MDC.getCopyOfContextMap();
   }

@Override
   public void run() {
       if (contextMap != null) {
           MDC.setContextMap(contextMap);
       }
       try {
           task.run();
       } finally {
           MDC.clear();
       }
   }
}

4.接下来再改写一下runAsync的使用方式，我们用MdcTaskWrapper来进行线程操作，这个线程类是包含mdc上下文的

@GetMapping("saveUser")
public String saveUser() {
   log.info("进入了saveUser");
   // 异步
   CompletableFuture.runAsync(this::b, command -> executorService.execute(new MdcTaskWrapper(command)));
   log.info("退出了saveUser");
   return "Ok";
}

private void b() {
   log.info("进入了b");
}

可以看到，requestId：4ab037ab-92cb，异步线程能够拿到MDC的上下文，并且成功记录链路日志

2023-04-19 11:58:27.581 4ab037ab-92cb  INFO 6816 --- [p-nio-80-exec-5] c.h.m.api.CompletableFutureApi           : 进入了saveUser
2023-04-19 11:58:27.582 4ab037ab-92cb  INFO 6816 --- [p-nio-80-exec-5] c.h.m.api.CompletableFutureApi           : 退出了saveUser
2023-04-19 11:58:27.582 4ab037ab-92cb  INFO 6816 --- [pool-1-thread-1] c.h.m.api.CompletableFutureApi    

来源：https://juejin.cn/post/7223590232728993852