MDC链路跟踪

chanchaw大约 5 分钟javaspring日志

概述

当你的应用程序同时处理多个用户的请求时，你会看到日志文件或者控制台中的输出通常都是交错的，而非线性连续的。尤其是在分布式系统中，一个用户请求可能包含了若干次的服务节点调用，它的日志也因此变得碎片化，如果缺乏一个用于归类和关联的标识，就会导致这笔交易难以被跟踪和追查。简言之按照时间顺序写入的日志是多个请求链路穿插显示的，如果要跟踪一个请求从头到尾的完整链路是很难从日志文件中提取出来的，此时就要用到 logback 的 MDC 功能了。

MDC(Mapped Diagnostic Context)是一种用于区分来自不同来源日志的工具。它的本质是一个由日志框架维护的Map存储结构，应用程序可以向其中写入键值对，并被日志框架访问。我们常用的日志门面SLF4J就对MDC的实现进行了抽象，由日志框架提供真正的实现。

实现

拦截器创建traceId并清空

因为 MDC 是线程安全的，所以可以使用拦截器为每个请求创建一个 traceId，这样一个请求的一个线程（子线程同样可以使用）不管在哪个业务逻辑中都打印出该 traceId，日志文件中就可以查看到一个请求的完整链路了。首先制作拦截器，在其中创建 traceId 之后清空，注意一定要清空，因为线程安全，每一个新的线程都会生成一个 traceId，如果不清空时间长了会导致内存泄露。

下面代码中还判断了 DispatcherType.REQUEST ，是为解决多线程多次请求 http 造成的重入情况时所有子线程，子请求都可以使用父级 traceId。

package com.xdf.xzymanagementsystem.config;

import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.web.servlet.AsyncHandlerInterceptor;
import javax.servlet.DispatcherType;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import com.cc.alltype.UUID;

@Slf4j
public class LogInterceptor implements AsyncHandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        if (request.getDispatcherType() != DispatcherType.REQUEST) {
            // 非 DispatcherType.REQUEST 分发类型，尝试从 Attribute 获取 LOG_TRACE_ID
            MDC.put("traceId", (String) request.getAttribute("traceId"));
            log.info("preHandle Non DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
            return true;
        }
        // 如果本次调用来自上游服务，那么尝试从请求头获取上游传递的 traceId
        String traceId = request.getHeader("traceId");
        if (traceId == null) {
            // 本服务节点是起始服务节点，设置 traceId
//            traceId = UUID.randomUUID().toString();
            traceId = UUID.getNoSeparator();
        }
        MDC.put("traceId", traceId);
        // 异步处理会在内部进行 Request 转发，通过 Attribute 携带 traceId
        request.setAttribute("traceId", traceId);
        log.info("preHandle DispatcherType.REQUEST type with DispatcherType {}", request.getDispatcherType());
        return true;
    }

    @Override
    public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 清理 MDC
        log.info("afterConcurrentHandlingStarted Clearing MDC.");
        MDC.clear();
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception exception) {
        // 清理 MDC
        log.info("afterCompletion Clearing MDC with DispatcherType {}", request.getDispatcherType());
        MDC.clear();
    }
}

WebMvcConfigurer

实现拦截器

package com.xdf.xzymanagementsystem.config;

import org.apache.catalina.connector.Connector;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.web.embedded.tomcat.TomcatConnectorCustomizer;
import org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.ResourceHandlerRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;

@Configuration
public class WebMvcConfigure implements WebMvcConfigurer {
    /**
     * 使用 MDC 实现链路跟踪
     * @param registry
     */
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
    }
}

日志显示traceId

在 logback 的 xml 配置文件中设置打印样式中打印出线程以及 traceId。多线程多次写入日志时就能看出线程以及 traceId 了。

    <appender name="halfProductEnter" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!--日志文件输出的文件名-->
            <FileNamePattern>${LOG_HOME}/halfProductEnter.%d{yyyyMMdd}.log</FileNamePattern>
            <!--日志文件保留天数-->
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<!--            <pattern>[ %d{yyyy-MM-dd HH:mm:ss.SSS} ] - [ %msg ]%n</pattern>-->
            <pattern>[%thread][%X{traceId:--}][ %d{yyyy-MM-dd HH:mm:ss.SSS} ] - [ %msg ]%n</pattern>
        </encoder>
        <!--日志文件最大的大小-->
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>10MB</MaxFileSize>
        </triggeringPolicy>
    </appender>

子线程丢失 traceId

解决线程池

一个请求中通过线程池或者手动线程执行的任务中会丢失 traceId，解决的方法是在子线程中要手动设置。调用多线程任务时将 traceId 传入子线程方法中

@GetMapping("/serverTime")
public ResponseResult<String> getServerTime(){
    String traceId = Optional.ofNullable(MDC.get("traceId")).orElse("");
    logger.info("开始使用线程池发送邮件");
    mailUtils.sendSimpleMailTraceId("409223171@qq.com","测试发送邮件","server:"+server+",获取服务器时间", traceId);
    return ResponseResult.<String>builder().success(true).message(ResponseEnum.OK.getName())
            .data(DatetimeUtils.formatNow())
            .build();
}

上面代码将 traceId 传给方法 sendSimpleMailTraceId，该方法的源码如下：

    @Async("ccAlarmThreadPool")
    public void sendSimpleMailTraceId(String to,String subject,String content,String traceId){
        MDC.put("traceId", traceId);
        message = new SimpleMailMessage();
        message.setTo(to);//收信人
        message.setSubject(subject);//主题
        message.setText(content);//内容
        message.setFrom(from);//发信人
        try {
            mailSender.send(message);
            logger.info("线程池发送邮件完毕");
        }catch (Exception e){
            System.out.println(e);
            logger.info("线程池发送邮件出现异常");
        }
    }

可以看到该方法使用了自定义线程池 ccAlarmThreadPool，在方法的头部就设置好 traceId，之后的所有逻辑中打印日志时都会带有标识了。如下

[http-nio-8081-exec-20][80afe8d0ee9643038495f305115a471d][ 2023-12-29 15:48:19.929 ] - [ 开始使用线程池发送邮件 ]
[ccAlarmThreadPool-1][-][ 2023-12-29 15:48:21.048 ] - [ 线程池发送邮件完毕 ]
[http-nio-8081-exec-7][33ca922d859542e7bce0fe4994c4e209][ 2023-12-29 15:58:05.952 ] - [ 开始使用线程池发送邮件 ]
[ccAlarmThreadPool-1][33ca922d859542e7bce0fe4994c4e209][ 2023-12-29 15:58:07.271 ] - [ 线程池发送邮件完毕 ]

可以看到第二行执行多线程任务时由于没有设置 traceId，导致打印的日志中没有显示，后面一次请求同样使用该线程池就打印了 traceId。

解决手动子线程

如果是手动子线程也可以采用下面的方法，原理是一样的

@GetMapping("/asyncMDC")
public Callable<String> mdcAsync() {
    LOGGER.info("async MDC test.");
    Map<String, String> mdcMap = MDC.getCopyOfContextMap();
    return () -> {
        try {
            MDC.setContextMap(mdcMap);
            LOGGER.info("异步业务逻辑处理");
            return "asyncMDC";
        } finally {
            MDC.clear();
        }
    };
}

MDC链路跟踪

# 概述

# 实现

# 拦截器创建traceId并清空

# WebMvcConfigurer

# 日志显示traceId

# 子线程丢失 traceId

# 解决线程池

# 解决手动子线程

概述

实现