Java服务日志追踪

背景

在服务中打印日志是一个非常好的习惯，在生产环境中，我们没法对代码进行debug，这时候日志对排查问题来说就非常重要，规范的打印日志可以帮助我们快速的定位问题。

在我们排查日志的时候，往往会出现以下三个问题

1：这条日志是属于哪个请求的？

2：这个请求有哪些日志？

3：前面的日志和后面的日志是否是属于同一个请求？

如果你的日志中，没有请求的唯一性标识，是很容易出现日志混乱的现象，特别是在并发量比较高的情况下，更加难区分和筛选，形成无效日志

思想

针对以上问题，我们希望用一个trackId来标识一个http请求，这个标识必须贯穿整个http请求处理的生命周期，将这次请求处理过程中的所有日志串联在一起，以实现轻量级日志追踪

MDC简介

MDC是java日志框架中的一个组件，其核心功能是保存线程MDC变量，并自动将当前线程存放在MDC中的变量，在日志中打印出来（需在打印日志格式的地方配置此变量）。MDC的原理就是使用ThreadLocal线程变量，对ThreadLocal进行进一步的封装，提供便捷的api，方便在打印日志的时候使用

MDC的常用方法

public static void put(String key, String val) 存入一个值，key-value结构

public static String get(String key)  获取一个值

public static void remove(String key) 移除一个值

public static void clear() 清除当前线程MDC中的所有值

public static Map<String, String> getCopyOfContextMap() 获取当前线程MDC所有值

public static void setContextMap(Map<String, String> contextMap) 设置MDC的值，
此方法一般和上一个getCopyOfContextMap方法一起使用，通常用户在线程场景切换状态时，
获取旧线程的MDC值，重新设置到新线程的MDC中，实现多线程环境MDC值传递

MDC接入SpringBoot

MDC是属于日志框架中的一个组件，只要是项目中包含任何日志框架既可，springboot项目有自带的日志框架

完整代码地址在文章末尾

maven

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.83</version>
        </dependency>
    </dependencies>

定义日志格式

在logback.xml文件中定义日志输出格式，设定trackId是每个请求的唯一标识，在日志输出格式中将trackId添加上，每条日志和请求的关系就能对应上。这里设置的比较简单，每个公司都有不同的标准，大家按自己的来就行，只需要在输出日志格式上加上trackId就行

<configuration>
    <!-- 定义日志输出格式 -->
<!--    <conversionRule conversionWord="sessionId" converterClass="com.example.SessionIdConverter" />-->
    <!-- 定义日志输出器 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%X{trackId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg %n</pattern>
        </encoder>
    </appender>
    <!-- 设置日志级别 -->
    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

MDC存取TrackId

过滤器，在请求进入服务时给MDC添加上trackId，方便后续获取

@Component
@WebFilter
@Log4j2
public class DMCFilter implements Filter {
    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        try {
            // DMC过滤器，向请求头中获取trackId（此作用是当多个java服务之前的http调用时，可以做多服务追踪）
            HttpServletRequest httpServletRequest = (HttpServletRequest) servletRequest;
            String trackId = httpServletRequest.getHeader(BuConstant.TRACK_ID);
            if(StringUtils.isEmpty(trackId)){
                trackId = UUID.randomUUID().toString().replaceAll("-", "");
            }
            MDC.put(BuConstant.TRACK_ID,trackId);
            filterChain.doFilter(servletRequest,servletResponse);
        }finally {
            MDC.clear();
        }
    }
}

编写一个测试接口

@RequestMapping("/hello")
@RestController
@Log4j2
public class HelloController {

    @GetMapping("/hi")
    public Object hi(){
        log.info("/hello/hi ....");
        log.info("业务处理中...");
        return "hi";
    }
}

运行日志结果

在日志的最开始打印出trackId，我们可以根据这个来判断是否是同一个请求中的日志

异步多线程场景

由于MDC的实现原理是ThreadLocal线程变量，所以也存在子线程无法获取到父线程的MDC变量信息

MDC提供了两个方法， 可以让我们快速转存线程的MDC信息，实现线程间的MDC信息传递

getCopyOfContextMap()和 setContextMap(Map<String, String> contextMap)方法

新建线程方式

@RequestMapping("/hello")
@RestController
@Log4j2
public class HelloController {

    @GetMapping("/hi")
    public Object hi(){
        log.info("/hello/hi ....");

        // MDC的底层原理是ThreadLocal,在线程改变后，不会传递到子线程，需要重新传递，注意清理
        // 如果是线程池，线程池中的线程不是重新创建线程，需要重置MDC

        Map<String, String> copyOfContextMap = MDC.getCopyOfContextMap();
        new Thread(()->{
            try