全链路追踪traceId【上篇】

在查日志时，我们通常需要一个关键字去查询，比如用户id，手机号，接口名之类的。但是这些查询出来的都只是关键字维度的信息。如果我们想查询某个请求在服务中整个执行过程中的日志，就需要用到一个唯一字符串标识，然后我们通过这个标识查询，就能知道这个请求的生命周期都做了哪些事情。这就是traceId。

traceId的实现过程通常需要在日志中添加上一个请求维度的唯一字符串。要实现这个功能我们需要先创建一个唯一字符串，然后将这个串加到请求上，并且每个请求是隔离的。

唯一字符串可以使用**uuid**。如何达到请求之间隔离呢？这就需要用到ThreadLocal，但ThreadLocal在多线程直接是不能传递变量信息的，但我们有时有多线程执行的场景，因此可以用InheritableThreadLocal或者**TransmittableThreadLocal**。如何将这个串添加到请求日志上呢？可以使用**过滤器**在请求进来时将串放入**MDC**中，请求结束时删除掉。

以SpringBoot工程为例：

### 方案1

#### 依赖：

```xml
		<dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>cn.hutool</groupId>
            <artifactId>hutool-all</artifactId>
            <version>5.8.3</version>
        </dependency>
        
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>transmittable-thread-local</artifactId>
            <version>2.11.2</version>
        </dependency>
        
        <dependency>
            <groupId>com.ofpay</groupId>
            <artifactId>logback-mdc-ttl</artifactId>
            <version>1.0.2</version>
            <exclusions>
                <exclusion>
                    <groupId>com.alibaba</groupId>
                    <artifactId>transmittable-thread-local</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <optional>true</optional>
        </dependency>
```

#### 线程变量工具类：

```java
package com.example.ttldemo.utils;

import com.alibaba.ttl.TransmittableThreadLocal;

/**
 * @author: HanXu
 * Class description: 线程变量工具类
 */
public class ThreadLocalUtil {

//    private static final ThreadLocal<String> currentThreadLocal = ThreadLocal.withInitial(() -> new String());
    /**
     * 使用阿里的TransmittableThreadLocal
     */
    private static final TransmittableThreadLocal<String> currentThreadLocal = new TransmittableThreadLocal<>();

/**
     * 获取值
     * @return 当前线程中存放的变量值
     */
    public static String getCurrentThreadVal() {
        return currentThreadLocal.get();
    }

/**
     * set值
     * @param value 唯一
     */
    public static void putCurrentThreadVal(String value) {
        currentThreadLocal.set(value);
    }

/**
     * 清空当前线程中的数据
     */
    public static void clear() {
        currentThreadLocal.remove();
    }
}
```

#### 生成traceId并放入日志：

```java
package com.example.ttldemo.config;

import cn.hutool.core.lang.UUID;
import com.example.ttldemo.utils.ThreadLocalUtil;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import javax.servlet.*;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;

/**
 * @author: HanXu
 * on 2021/11/17
 * Class description: 对请求的一些处理
 */
@Slf4j
@Component
public class RequestFilter implements Filter {

private static final String TRACE_ID = "traceId";

@Override
    public void init(FilterConfig filterConfig) throws ServletException {

}

/**
     * 请求线程添加traceId；slf4j日志框架中添加key为traceId，value为uuid的变量；并将traceId放入响应头的traceId字段里
     * @param servletRequest
     * @param servletResponse
     * @param filterChain
     * @throws IOException
     * @throws ServletException
     */
    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        HttpServletResponse httpResponse = (HttpServletResponse) servletResponse;

ThreadLocalUtil.putCurrentThreadVal(UUID.fastUUID().toString(true));
        httpResponse.setHeader(TRACE_ID, ThreadLocalUtil.getCurrentThreadVal());
        //在slf4j日志框架中记录RequestId，值为线程中存放的唯一变量，用以标记一个请求在其生命流程中的行为
        MDC.put(TRACE_ID, ThreadLocalUtil.getCurrentThreadVal());

try {
            filterChain.doFilter(servletRequest, servletResponse);
        } finally {
            MDC.remove(TRACE_ID);
            ThreadLocalUtil.clear();
        }
    }

@Override
    public void destroy() {

}
}
```

#### 日志配置：

logback-spring.xml

```xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <timestamp key="TIMESTAMP" datePattern="yyyy-MM-dd"/>
    
    
    
    <springProfile name="local">
        <property name="LOG_HOME" value="/var/logs"/>
        <springProperty name="LOG_FILE" source="spring.application.name"/>
    </springProfile>

<springProfile name="dev|test|gray|prod">
        <property name="LOG_HOME" value="/var/logs"/>
        <springProperty name="LOG_FILE" source="spring.application.name"/>
    </springProfile>
    
    <contextListener class="com.ofpay.logback.TtlMdcListener"/>
    
    
    <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"/>
    
    <property name="CONSOLE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] -%clr(%-5level) - -%clr([traceId-%X{traceId}]){magenta}  %clr(%logger{56}.%method:%clr(%L){blue}){cyan} - %msg%n"/>
    
    <property name="FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level - [traceId-%X{traceId}] %logger{56}.%method:%L - %msg%n"/>
    
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>
                ${CONSOLE_LOG_PATTERN}
            </pattern>
        </encoder>
    </appender>
    
    
    <appender name="ALL_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <append>true</append>
        <encoder>
            <pattern>
                ${FILE_LOG_PATTERN}
            </pattern>
            
            <charset>UTF-8</charset>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>
                ${LOG_HOME}/${LOG_FILE}_%d{yyyyMMdd}_%i.log
            </fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            
            
            
        </rollingPolicy>
    </appender>

<appender name="async" class="ch.qos.logback.classic.AsyncAppender">
        
        <discardingThreshold>0</discardingThreshold>
        
        <queueSize>256</queueSize>
        
        <appender-ref ref="ALL_FILE"/>
    </appender>

</configuration>
```

#### 线程池配置：

```java
package com.example.ttldemo.config;

import com.alibaba.ttl.threadpool.TtlExecutors;
import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableAsync;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

import java.util.concurrent.ExecutorService;

/**
 * @author: HanXu
 * Class description: 线程池配置
 */
@Slf4j
@Configuration
@EnableAsync
public class ExecutorConfig {

/**
     * 使用普通线程池不行
     * @return
     */
    @Bean(name = "testExecutor")
    public ThreadPoolTaskExecutor testExecutor(){
        log.info("start testExecutor------------------------");
        ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(1);
        threadPoolTaskExecutor.setMaxPoolSize(3);
        threadPoolTaskExecutor.setQueueCapacity(2);
        threadPoolTaskExecutor.initialize();
        return threadPoolTaskExecutor;
    }

/**
     * 使用ttl包装的线程池才能在日志输出中带有正确的traceId
     * @return
     */
    @Bean(name = "ttlExecutor")
    public ExecutorService ttlExecutor(){
        log.info("start ttlExecutor------------------------");
        ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(1);
        threadPoolTaskExecutor.setMaxPoolSize(3);
        threadPoolTaskExecutor.setQueueCapacity(2);
        threadPoolTaskExecutor.initialize();
        ExecutorService ttlExecutorService = TtlExecutors.getTtlExecutorService(threadPoolTaskExecutor.getThreadPoolExecutor());
        return ttlExecutorService;
    }
}
```

#### 测试：

```java
package com.example.ttldemo.controller;

import com.alibaba.ttl.TransmittableThreadLocal;
import com.example.ttldemo.utils.ThreadLocalUtil;
import lombok.SneakyThrows;
import lombok.extern.slf4j.Slf4j;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

import javax.annotation.Resource;
import java.util.concurrent.CyclicBarrier;
import java.util.concurrent.ExecutorService;

/**
 * @Author HanXu
 */
@Slf4j
@RestController
@RequestMapping
public class TestController {

@Resource
    private ExecutorService ttlExecutor;

@GetMapping("/log2")
    public String test5() {
        //父线程
        log.info("父线程执行:{}", ThreadLocalUtil.getCurrentThreadVal());

//子线程
        ttlExecutor.submit(() -> {
            log.info("子线程执行:{}", ThreadLocalUtil.getCurrentThreadVal());
        });
        return "ok";
    }
}
```

配置：

```yml
spring:
  profiles:
    active: local
```

调用请求http://127.0.0.1:8080/log2 多次：
```
    2023-04-24 10:59:18.011 [http-nio-8080-exec-2] -INFO  - -[traceId-f86a0a6c01474408a690b302324ed7b5]  com.example.ttldemo.controller.TestController.test5:139 - 父线程执行:f86a0a6c01474408a690b302324ed7b5
    2023-04-24 10:59:18.020 [ThreadPoolTaskExecutor-1] -INFO  - -[traceId-f86a0a6c01474408a690b302324ed7b5]  com.example.ttldemo.controller.TestController.lambda$test5$4:143 - 子线程执行:f86a0a6c01474408a690b302324ed7b5
    2023-04-24 10:59:23.713 [http-nio-8080-exec-3] -INFO  - -[traceId-918062e7b8b9476c88c7d8e710b449ad]  com.example.ttldemo.controller.TestController.test5:139 - 父线程执行:918062e7b8b9476c88c7d8e710b449ad
    2023-04-24 10:59:23.714 [ThreadPoolTaskExecutor-1] -INFO  - -[traceId-918062e7b8b9476c88c7d8e710b449ad]  com.example.ttldemo.controller.TestController.lambda$test5$4:143 - 子线程执行:918062e7b8b9476c88c7d8e710b449ad
```
可以看到对于每个请求都有唯一id:traceId贯穿整个请求，这样就可以方便的查找某个请求的日志了。

### 方案2

上述方案使用阿里的ttl体系，帮我们做线程间变量的传递。我们也可以自己做。

#### 依赖：

自己实现的话无需依赖阿里ttl：

#### 线程变量工具类：

只需要使用InheritableThreadLocal即可：

```java
package com.example.traceiddemo.demos.utils;

/**
 * @author: HanXu
 * Class description: 线程变量工具类
 */
public class ThreadLocalUtil {

//    private static final ThreadLocal<String> currentThreadLocal = ThreadLocal.withInitial(() -> new String());
    /**
     * 使用阿里的TransmittableThreadLocal
     */
    private static final InheritableThreadLocal<String> currentThreadLocal = new InheritableThreadLocal<>();

/**
     * 获取值
     * @return 当前线程中存放的变量值
     */
    public static String getCurrentThreadVal() {
        return currentThreadLocal.get();
    }

/**
     * set值
     * @param value 唯一
     */
    public static void putCurrentThreadVal(String value) {
        currentThreadLocal.set(value);
    }

/**
     * 清空当前线程中的数据
     */
    public static void clear() {
        currentThreadLocal.remove();
    }
}
```

#### 线程变量传递工具类：

```java
package com.example.traceiddemo.demos.utils;

import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;

import java.util.Map;

/**
 * @Author HanXu
 */
@Slf4j
public class ThreadMdcUtil {

/**
     * 将线程中的上下文内容传递到另一个线程
     * @param task 新的线程任务
     * @param context 当前线程内存的上下文
     * @return
     */
    public static Runnable warpAsync(Runnable task, Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }

try {
                task.run();
            } finally {
                MDC.clear();
            }
        };
    }
}
```

#### 生成traceId并放入日志：

和上述RequestFilter保持不变。

#### 日志配置：

和上述logback-spring.xml保持不变，不过要删除这个：这是阿里的ttl监听器，我们没有引入也不需要。

```xml
	
    <contextListener class="com.ofpay.logback.TtlMdcListener"/>
```

#### 线程池配置：

```java
package com.example.traceiddemo.demos.config;

import com.example.traceiddemo.demos.utils.ThreadMdcUtil;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableAsync;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

import java.util.concurrent.ThreadPoolExecutor;

/**
 * @author: HanXu
 * Class description: 线程池配置
 */
@Slf4j
@Configuration
@EnableAsync
public class ExecutorConfig {
 
    @Bean(name = "testExecutor")
    public ThreadPoolTaskExecutor testExecutor(){
        log.info("start testExecutor------------------------");
		//使用spring提供的带有装饰器的线程池
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(2);
        executor.setMaxPoolSize(3);
        executor.setQueueCapacity(2);
        executor.setKeepAliveSeconds(60);
        //这里使用装饰器，传递线程上下文信息
        executor.setTaskDecorator(runnable -> ThreadMdcUtil.warpAsync(runnable, MDC.getCopyOfContextMap()));
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());
        executor.initialize();
        return executor;
    }
}
```

#### Service层：

```java
package com.example.traceiddemo.demos.service;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;

/**
 * @Author HanXu
 */
@Slf4j
@Service
public class DemoService {

public void print() {
        log.info("demoService...");
    }
}
```

#### 测试：

```java
package com.example.traceiddemo.demos.web;

import com.example.traceiddemo.demos.service.DemoService;
import lombok.SneakyThrows;
import lombok.extern.slf4j.Slf4j;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

import javax.annotation.Resource;

@Slf4j
@RequestMapping
@RestController
public class BasicController {

@Resource
    private DemoService demoService;
    @Resource
    private ThreadPoolTaskExecutor testExecutor;

@SneakyThrows
    @GetMapping("/log2")
    public String test5() {
        //父线程
        log.info("父线程执行");

//子线程
        testExecutor.submit(() -> {
            try {
                Thread.sleep(100);
            } catch (InterruptedException e) {
                throw new RuntimeException(e);
            }
            log.info("子线程执行");
        });

Thread.sleep(100);
        log.info("父线程执行end");
        demoService.print();
        return "ok";
    }
}
```

访问http://127.0.0.1:8080/log2 ，查看日志：

```
2023-04-24 11:12:52.744 [http-nio-8080-exec-1] -INFO  - -[traceId-60b719c946884117873d761b7e6c579b]  com.example.traceiddemo.demos.web.BasicController.test5:48 - 父线程执行
2023-04-24 11:12:52.860 [testExecutor-1] -INFO  - -[traceId-60b719c946884117873d761b7e6c579b]  com.example.traceiddemo.demos.web.BasicController.lambda$test5$0:57 - 子线程执行
2023-04-24 11:12:52.860 [http-nio-8080-exec-1] -INFO  - -[traceId-60b719c946884117873d761b7e6c579b]  com.example.traceiddemo.demos.web.BasicController.test5:61 - 父线程执行end
2023-04-24 11:12:52.860 [http-nio-8080-exec-1] -INFO  - -[traceId-60b719c946884117873d761b7e6c579b]  com.example.traceiddemo.demos.service.DemoService.print:15 - demoService...

4-24 11:13:22.455 [http-nio-8080-exec-2] -INFO  - -[traceId-b5c684cc5f264cee90cf12b1d333fef4]  com.example.traceiddemo.demos.web.BasicController.test5:48 - 父线程执行
2023-04-24 11:13:22.561 [testExecutor-2] -INFO  - -[traceId-b5c684cc5f264cee90cf12b1d333fef4]  com.example.traceiddemo.demos.web.BasicController.lambda$test5$0:57 - 子线程执行
2023-04-24 11:13:22.561 [http-nio-8080-exec-2] -INFO  - -[traceId-b5c684cc5f264cee90cf12b1d333fef4]  com.example.traceiddemo.demos.web.BasicController.test5:61 - 父线程执行end
2023-04-24 11:13:22.561 [http-nio-8080-exec-2] -INFO  - -[traceId-b5c684cc5f264cee90cf12b1d333fef4]  com.example.traceiddemo.demos.service.DemoService.print:15 - demoService...
```

每个请求都有唯一的traceId标识。

以上就是普通web项目中的链路追踪实现。微服务中需要用到feign之类的调用，那么就需要在feign调用时传递traceId，这个我们放在下篇继续。

全链路追踪traceId【上篇】

发表评论