全链路日志追踪

0.由来

由于前司并无完整的日志系统，之前对这方面内容并无详细了解，在熟悉了现公司日志系统时发现，在排查日志时无论是ELK的日志检索，还是灰度的日志文件，都发现每次完整的接口调用，每一步日志都会带上同一个TraceId，用以追踪整个借口请求链路，特此研究如何通过TraceId将分布式系统的日志链路串联起来。

1.MDC

1.1 简介

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 、logback、slf4j及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。

当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。

1.2 常用API

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

1.3 优点

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

2.实现（单线程版）

2.1 相关依赖

<dependencies>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-web</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-test</artifactId>
        <scope>test</scope>
    </dependency>
    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-logging</artifactId>
    </dependency>
    <!--lombok配置-->
    <dependency>
        <groupId>org.projectlombok</groupId>
        <artifactId>lombok</artifactId>
        <version>1.16.10</version>
    </dependency>
</dependencies>

2.2 log配置文件

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
    <!--日志存储路径-->
    <property name="log" value="/Users/zhen/Downloads" />
    <!-- 控制台输出 -->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!--输出格式化-->
            <pattern>[%X{TRACE_ID}]  %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- 按天生成日志文件 -->
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!--日志文件名-->
            <FileNamePattern>${log}/%d{yyyy-MM-dd}.log</FileNamePattern>
            <!--保留天数-->
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>[%X{TRACE_ID}]  %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
        </encoder>
        <!--日志文件最大的大小-->
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>10MB</MaxFileSize>
        </triggeringPolicy>
    </appender>

    <!-- 日志输出级别 -->
    <root level="INFO">
        <appender-ref ref="console" />
        <appender-ref ref="file" />
    </root>
</configuration>

2.3 application.yml

server:
  port: 8081
logging:
  config: classpath:logback-spring.xml

2.4 拦截器

用途：每一次链路，线程维度，添加最终的链路ID TRACE_ID。

package com.zhen.studytotal.traceid.interceptor;

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.springframework.web.servlet.HandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

/**
  * Description: 请求拦截器（日志添加trace_id）
  * User: zhen0w0
  * Date: 2025/3/9
  * Time: 01:59
  */
public class LogInterceptor implements HandlerInterceptor {
    public static final String TRACE_ID = "TRACE_ID";
  
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String traceId = UUID.randomUUID().toString().replace("-", "");

        if (StringUtils.isNotBlank(request.getHeader(TRACE_ID))){
            traceId = request.getHeader(TRACE_ID);
        }
        MDC.put(TRACE_ID, traceId);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        MDC.remove(TRACE_ID);
    }
}

配置中添加自定义拦截器

package com.zhen.studytotal.traceid.config;

import com.zhen.studytotal.traceid.interceptor.LogInterceptor;
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.WebMvcConfigurer;

/**
 * Description: 配置自定义web拦截器
 * User: zhen0w0
 * Date: 2025/3/9
 * Time: 02:29
 */
@Configuration
public class WebConfigurerAdapter implements WebMvcConfigurer {

    @Bean
    public LogInterceptor logInterceptor(){
        return new LogInterceptor();
    }

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
    }
} 

2.5 测试

package com.zhen.studytotal.traceid.controller;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

/**
 * Description:
 * User: zhen0w0
 * Date: 2025/3/9
 * Time: 02:32
 */
@Slf4j
@RestController
@RequestMapping("/test")
public class TestController {

    @GetMapping("/doTest")
    public String doTest(@RequestParam("name") String name) throws InterruptedException {
        log.info("调用开始 name={}", name);
        log.info("这是一行info日志");
        log.error("这是一行error日志");
        log.info("调用结束 name={}", name);
        return "Hello," + name;
    }
}

2.6 效果展示

可以看出每次接口调用都有自己专属的trace_id

3.实现（多线程版）

拦截器参考单线程版即可，主要应对异步线程之外的常规操作

3.1 生成trace_id工具类

package com.zhen.studytotal.traceid.utils;

import java.util.UUID;

public class TraceIdUtil {

    private TraceIdUtil() {
        throw new UnsupportedOperationException("Utility class");
    }

    /**
     * 获取traceId
     * @return
     */
    public static String getTraceId() {
        return UUID.randomUUID().toString().replace("-", "").toUpperCase();
    }
}

3.2 MDC工具类

package com.zhen.studytotal.traceid.utils;

import org.slf4j.MDC;

import java.util.Map;
import java.util.concurrent.Callable;

/**
 * Description:
 * User: zhen0w0
 * Date: 2025/3/21
 * Time: 00:50
 */

public class ThreadMdcUtil {
        class LogConstant {
            public static final String TRACE_ID = "TRACE_ID";
        }

        public static void setTraceIdIfAbsent() {
            if (MDC.get(LogConstant.TRACE_ID) == null) {
                //插入唯一日志ID
                MDC.put(LogConstant.TRACE_ID, TraceIdUtil.getTraceId());
            }
        }

        public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
            return () -> {
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                setTraceIdIfAbsent();
                try {
                    return callable.call();
                } finally {
                    MDC.clear();
                }
            };
        }

        public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
            return () -> {
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                setTraceIdIfAbsent();
                try {
                    runnable.run();
                } finally {
                    MDC.clear();
                }
            };
        }

    }

3.3 重写线程池

这一步借助MDC工具类，对线程池原有的execute等方法进行优化，使每次线程执行时都附带trace_id

package com.zhen.studytotal.traceid.config;

import com.zhen.studytotal.traceid.utils.ThreadMdcUtil;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import org.springframework.util.concurrent.ListenableFuture;

import java.util.concurrent.Callable;
import java.util.concurrent.Future;
import java.util.concurrent.ThreadPoolExecutor;

@Slf4j
public class ThreadPoolExecutorMdcWrapper extends ThreadPoolTaskExecutor {

    private void showThreadPoolInfo(String prefix){
        ThreadPoolExecutor threadPoolExecutor = getThreadPoolExecutor();

        if(null==threadPoolExecutor){
            return;
        }

        log.info("{}, {},taskCount [{}], completedTaskCount [{}], activeCount [{}], queueSize [{}]",
                this.getThreadNamePrefix(),
                prefix,
                threadPoolExecutor.getTaskCount(),
                threadPoolExecutor.getCompletedTaskCount(),
                threadPoolExecutor.getActiveCount(),
                threadPoolExecutor.getQueue().size());
    }

    @Override
    public void execute(Runnable task) {
        showThreadPoolInfo("1. do execute");
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public void execute(Runnable task, long startTimeout) {
        showThreadPoolInfo("2. do execute");
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);

    }

    @Override
    public Future<?> submit(Runnable task) {
        showThreadPoolInfo("1. do submit");
        return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public <T> Future<T> submit(Callable<T> task) {
        showThreadPoolInfo("2. do submit");
        return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public ListenableFuture<?> submitListenable(Runnable task) {
        showThreadPoolInfo("1. do submitListenable");
        return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public <T> ListenableFuture<T> submitListenable(Callable<T> task) {
        showThreadPoolInfo("2. do submitListenable");
        return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

}

3.4 初始化线程池

package com.zhen.studytotal.traceid.config;

import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Primary;

import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;

/**
 * Description:
 * User: zhen0w0
 * Date: 2025/3/21
 * Time: 00:37
 */
@Slf4j
@Configuration
public class ExecutorConfig {

    @Bean
    @Primary
    public ThreadPoolExecutorMdcWrapper asyncServiceExecutor(){
        log.info("start asyncServiceExecutor");
        ThreadPoolExecutorMdcWrapper executor = new ThreadPoolExecutorMdcWrapper();
        //配置核心线程数
        executor.setCorePoolSize(10);
        //配置最大线程数
        executor.setMaxPoolSize(200);
        //配置队列大小
        executor.setQueueCapacity(99999);
        //配置线程池中的线程的名称前缀
        executor.setThreadNamePrefix("async-service-");

        // 设置拒绝策略：当pool已经达到max size的时候，如何处理新任务
        // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        //执行初始化
        executor.initialize();
        return executor;
    }
}

3.5 测试

@Autowired
private Executor executor;


@GetMapping("/logId")
public String logId(@RequestParam("name") String name) throws InterruptedException {
    log.info("调用开始------------------------------------ name={}", name);
    log.info("这是一行info日志");
    log.error("这是一行error日志");
    log.info("调用结束 name={}", name);

   //ExecutorService executor = Executors.newSingleThreadExecutor();
    executor.execute(() -> {
        log.info("线程内日志");
    });
    return "Hello," + name;
}

4.分布式解决方案

Sleuth

• 参考链接01

• 参考链接02