MDC机制实现日志的追踪

老胡的技术笔记 2021-05-27

2250

背景

前言：

开发排查系统问题用得最多的手段就是查看系统日志，在分布式环境中一般使用ELK来统一收集日志，但是在并发大时使用日志定位问题还是比较麻烦，由于大量的其他用户/其他线程的日志也一起输出穿行其中导致很难筛选出指定请求的全部相关日志，以及下游线程/服务对应的日志。

需要考虑的问题：

每个请求都使用一个唯一标识来追踪全部的链路显示在日志中，并且不修改原有的打印方式(代码无入侵)
对于多线程要实现异步子线程传承主线程的请求流水号

解决思路：

使用Logback的MDC机制日志模板中加入requestId请求流水号标识，取值方式为%X{requestId}
自定义MDC自定义MDC实现AsyncConfigurer自定义线程池，实现TaskDecorator接口（这是一个执行回调方法的装饰器，主要应用于传递上下文，或者提供任务的监控/统计信息），从主线程拷贝数据到子线程

MDC的使用

加入请求流水号：

//把唯一请求id添加到当前线程的contextMap中
MDC.put(HttpConstant.REQUEST_ID, requestId);

logback-spring.xml日志模板中打印请求流水号：

<property name="customLogPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{request_id}|%thread|%file|%logger:%line|%msg%n" />

自定义MDC实现AsyncConfigurer，实现TaskDecorator接口：

Tips：下面代码是为了不改变Spring的注解(Async)，也可自定义异步注解

@Slf4j
@EnableAsync
@Configuration
public class MdcThreadPoolTaskExecutor implements AsyncConfigurer  {
  
  //核心线程池大小
    private final int corePoolSize = 10;
    //最大线程数
    private final int maxPoolSize = 15;
    //队列容量
    private final int queueCapacity = 50;
    //活跃时间/秒
    private final int keepAliveSeconds = 30;
    
  @Override
  public Executor getAsyncExecutor() {
    ThreadPoolTaskExecutor  executor = new ThreadPoolTaskExecutor ();
        //核心线程池大小
        executor.setCorePoolSize(corePoolSize);
        //最大线程数
        executor.setMaxPoolSize(maxPoolSize);
        //队列容量
        executor.setQueueCapacity(queueCapacity);
        //活跃时间
        executor.setKeepAliveSeconds(keepAliveSeconds);
        //线程名字前缀
        executor.setThreadNamePrefix("AsyncExecutor-");
        
        executor.setTaskDecorator(new MdcTaskDecorator());
        // setRejectedExecutionHandler：当pool已经达到max size的时候，如何处理新任务
        // CallerRunsPolicy：不在新线程中执行任务，而是由调用者所在的线程来执行
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        executor.initialize();
        return executor;
  }
  class MdcTaskDecorator implements TaskDecorator {
          @Override
          public Runnable decorate(Runnable runnable) {
            //把主线程的context制作一份副本
              Map<String, String> contextMap = MDC.getCopyOfContextMap();
              return () -> {
                try {
                    if (contextMap != null) {
                        //放到MDC中去子线程的contextMap中去
                            MDC.setContextMap(contextMap);
                        }
                    runnable.run();
          } finally {
            MDC.clear();
          }
              };
          }
  }
  @Override
  public AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {
     return (throwable, method, params) -> {
              log.error("异步任务异常：方法：{} 参数：{}", method.getName(), JSON.toJSONString(params));
              log.error(throwable.getMessage(), throwable);
          };
  }
}

请求结束后移除流水号：

MDC.remove(HttpConstant.REQUEST_ID)

测试

测试异步线程传承主线程的请求流水号：

  @ApiOperation(value = "getResult", notes = "测试接口")
  @PostMapping("/getResult")
  public ReponseResult getResult(@Valid @RequestBody TestVo testVo) {
      shortMessageService.saveMessage("15711111111","144686");
      log.info("开始异步处理");
      testService.asyncTest();
      return ReponseResult.success();
    }
  }

@Override
@Async
public void asyncTest() {
    log.info("我是一个异步方法");
  }

其他

日志切割：

<?xml version="1.0" encoding="UTF-8"?>
<!-- scan:当此属性设置为true时，配置文件如果发生改变，将会被重新加载，默认值为true scanPeriod:设置监测配置文件是否有修改的时间间隔，如果没有给出时间单位，默认单位是毫秒，当scan为true时，此属性生效，more时间间隔为1分钟 
  debug:当此属性设置为true时，将打印处的logback内部日志信息，实时查看logback运行状态。默认值为false configuration下有两个属性，3个节点 -->
<configuration scan="true" scanPeriod="60 seconds" debug="false">
  <include resource="org.springframework.boot.logging.logback.base.xml" />
  <springProperty scope="context" name="logPath" source="log.path"/>
  <contextName>logFile</contextName>
  
  <property name="customLogPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{request_id}|%thread|%file|%logger:%line|%msg%n" />
    <!-- 定义日志文件名格式化,定义到哪个维度则按哪个维度切割日志，只支持每周，每天，每个小时，每分钟等创建一个文件 yyyy-MM-dd-HH-mm 分钟维度 -->
    <property name="logTimeFormat" value="yyyy-MM-dd" />
    <!-- 定义日志文件保留天数，单位和log.timeFormat定义的最小维度保持一致，上面定义到天，则单位默认为天 -->
    <property name="logMaxHistory" value="30" />
    <!-- 定义日志文件最大限制，超过限制则切割日志 -->
    <property name="logMaxFileSize" value="500MB" />
    
  
  <!-- 控制台输出 -->
  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>debug</level>
    </filter>
    <encoder>
      <pattern>${customLogPattern}</pattern>
    </encoder>
  </appender>
  <!-- 文件输出 -->
  <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${logPath}/logFile.log</file>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>info</level>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${logPath}/logFile.%d{${logTimeFormat}}-%i.log</FileNamePattern>
            <MaxHistory>${logMaxHistory}</MaxHistory>
            <timeBasedFileNamingAndTriggeringPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <MaxFileSize>${logMaxFileSize}</MaxFileSize><!-- 日志文件分割的条件为日志文件大小达到maxFileSize -->
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    <encoder>
      <pattern>${customLogPattern}</pattern>
    </encoder>
  </appender>


  <logger name="com.example" level="debug" additivity="false">
    <appender-ref ref="console" />
    <appender-ref ref="file" />
  </logger>
  
  <root level="info">
    <appender-ref ref="console" />
    <appender-ref ref="file" />
  </root>
</configuration>

效果展示：

END

数据库

文章转载自老胡的技术笔记，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

MDC机制实现日志的追踪

评论