# 分布式系统中如何优雅地追踪日志

> 转载：[分布式系统中如何优雅地追踪日志（原理篇）](https://juejin.im/post/6844904035955261454)

### 1. 分布式系统中日志追踪需要考虑的几个点？

1. 需要一个全服务唯一的id，即traceId，如何保证？
2. traceId如何在服务间传递？
3. traceId如何在服务内部传递？
4. traceId如何在多线程中传递？

**我们一一来解答：**

1. 全服务唯一的traceId，可以使用uuid生成，正常来说不会出现重复的；
2. 关于服务间传递，对于调用者，**在协议头加上traceId**，对于被调用者，通过前置拦截器或者过滤器统一拦截；
3. 关于服务内部传递，**可以使用ThreadLocal传递traceId**，一处放置，随处可用；
4. 关于多线程传递，分为两种情况：
   * 子线程，可以使用InheritableThreadLocal。
   * 线程池，需要改造线程池对提交的任务进行包装，把提交者的traceId包装到任务中。

![2020-10-08-kHkZzV](https://image.ldbmcs.com/2020-10-08-kHkZzV.jpg)

比如，上面这个系统，系统入口在A处，A调用B的服务，B里面又起了一个线程B1去访问D的服务，B本身又去访问C服务。

我们就可以这么来跟踪日志：

1. 所有服务都需要一个全局的InheritableThreadLocal保存服务内部traceId的传递；
2. 所有服务都需要一个前置拦截器或者过滤器，检测如果请求头没有traceId就生成一个，如果有就取出来，并把traceId放到全局的InheritableThreadLocal里面；
3. 一个服务调用另一个服务的时候把traceId塞到请求头里，比如http header；
4. 改造线程池，在提交的时候包装任务，这个工作量比较大，因为服务内部可能依赖其它框架，这些框架的线程池有可能也需要修改；

### 2. 实现

我们模拟A到B这两个服务来实现一个日志跟踪系统。

为了简单起见，我们使用SpringBoot，它默认使用的日志框架是logback，而且Slf4j提供了一个包装了`InheritableThreadLocal`的类叫MDC，我们只要把traceId放在MDC中，打印日志的时候统一打印就可以了，不用显式地打印traceId。

我们分成三个模块：

1. 公共包：封装拦截器，traceId的生成，服务内传递，请求头的传递等；
2. A服务：只依赖于公共包，并提供一个接口接收外部请求；
3. B服务：依赖于公共包，并内部起一个线程池，用于发送B1->D的请求，当然我们这里不发送请求，只在线程池中简单地打印一条日志；

### 3. 公共包

1. TraceFilter.java

   前置过滤器，用拦截器实现也是一样的。

   从请求头中获取traceId，如果不存在就生成一个，并放入MDC中。

   ```java
   @Slf4j
   @WebFilter("/**")
   @Component
   public class TraceFilter implements Filter {

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

       }

       @Override
       public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain) throws IOException, ServletException {
           HttpServletRequest request = (HttpServletRequest) servletRequest;

           // 从请求头中获取traceId
           String traceId = request.getHeader("traceId");
           // 不存在就生成一个
           if (traceId == null || "".equals(traceId)) {
               traceId = UUID.randomUUID().toString();
           }
           // 放入MDC中，本文来源于工从号彤哥读源码
           MDC.put("traceId", traceId);
           chain.doFilter(servletRequest, servletResponse);
       }

       @Override
       public void destroy() {

       }
   }
   ```
2. TraceThreadPoolExecutor.java

   改造线程池，提交任务的时候进行包装。

   ```java
   public class TraceThreadPoolExecutor extends ThreadPoolExecutor {
       public TraceThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
           super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
       }

       public TraceThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
           super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
       }

       public TraceThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
           super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
       }

       public TraceThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory, RejectedExecutionHandler handler) {
           super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
       }

       @Override
       public void execute(Runnable command) {
           // 提交者的本地变量
           Map<String, String> contextMap = MDC.getCopyOfContextMap();
           super.execute(()->{
               if (contextMap != null) {
                   // 如果提交者有本地变量，任务执行之前放入当前任务所在的线程的本地变量中
                   MDC.setContextMap(contextMap);
               }
               try {
                   command.run();
               } finally {
                   // 任务执行完，清除本地变量，以防对后续任务有影响
                   MDC.clear();
               }
           });
       }
   }
   ```
3. TraceAsyncConfigurer.java

   改造Spring的异步线程池，包装提交的任务。

   ```java
   @Slf4j
   @Component
   public class TraceAsyncConfigurer implements AsyncConfigurer {

       @Override
       public Executor getAsyncExecutor() {
           ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
           executor.setCorePoolSize(8);
           executor.setMaxPoolSize(16);
           executor.setQueueCapacity(100);
           executor.setThreadNamePrefix("async-pool-");
           executor.setTaskDecorator(new MdcTaskDecorator());
           executor.setWaitForTasksToCompleteOnShutdown(true);
           executor.initialize();
           return executor;
       }

       @Override
       public AsyncUncaughtExceptionHandler getAsyncUncaughtExceptionHandler() {
           return (throwable, method, params) -> log.error("asyc execute error, method={}, params={}", method.getName(), Arrays.toString(params));
       }

       public static class MdcTaskDecorator implements TaskDecorator {
           @Override
           public Runnable decorate(Runnable runnable) {
               Map<String, String> contextMap = MDC.getCopyOfContextMap();
               return () -> {
                   if (contextMap != null) {
                       MDC.setContextMap(contextMap);
                   }
                   try {
                       runnable.run();
                   } finally {
                       MDC.clear();
                   }
               };
           }
       }

   }
   ```
4. HttpUtils.java

   封装Http工具类，把traceId加入头中，带到下一个服务。

   ```java
   @Slf4j
   public class HttpUtils {

       public static String get(String url) throws URISyntaxException {
           RestTemplate restTemplate = new RestTemplate();
           MultiValueMap<String, String> headers = new HttpHeaders();
           headers.add("traceId", MDC.get("traceId"));
           URI uri = new URI(url);
           RequestEntity<?> requestEntity = new RequestEntity<>(headers, HttpMethod.GET, uri);
           ResponseEntity<String> exchange = restTemplate.exchange(requestEntity, String.class);

           if (exchange.getStatusCode().equals(HttpStatus.OK)) {
               log.info("send http request success");
           }

           return exchange.getBody();
       }

   }
   ```

#### 3.1 A服务

A服务通过Http调用B服务。

```java
@Slf4j
@RestController
public class AController {
    
    @RequestMapping("a")
    public String a(String name) {
        log.info("Hello, " + name);

        try {
            // A中调用B
            return HttpUtils.get("http://localhost:8002/b");
        } catch (Exception e) {
            log.error("call b error", e);
        }

        return "fail";
    }
}
```

A服务的日志输出格式：

中间加了`[%X{traceId}]`一串表示输出traceId。

```java
logging:
  pattern:
    console: '%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(%5p) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr([%X{traceId}]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n%wEx'
```

#### 3.2 B服务

B服务内部有两种跨线程调用：

* 利用Spring的异步线程池。
* 使用自己的线程池。

BController.java

```java
@Slf4j
@RestController
public class BController {

    @Autowired
    private BService bService;

    @RequestMapping("b")
    public String b() {
        log.info("Hello, b receive request from a");

        bService.sendMsgBySpring();

        bService.sendMsgByThreadPool();

        return "ok";
    }
}
```

BService.java

```java
@Slf4j
@Service
public class BService {

    public static final TraceThreadPoolExecutor threadPool = new TraceThreadPoolExecutor(5, 5, 60, TimeUnit.SECONDS, new LinkedBlockingQueue<>(100));

    @Async
    public void sendMsgBySpring() {
        log.info("send msg by spring success");
    }

    public void sendMsgByThreadPool() {
        threadPool.execute(()->log.info("send msg by thread pool success"));
    }
}
```

B服务的日志输出格式：

中间加了`[%X{traceId}]`一串表示输出traceId。

```java
logging:
  pattern:
    console: '%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(%5p) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr([%X{traceId}]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n%wEx'
```

#### 3.3 测试

打开浏览器，输入`http://localhost:8001/a?name=andy`。

A服务输出日志：

```java
2019-12-26 21:36:29.132  INFO 5132 --- [nio-8001-exec-2] [8a59cb96-bbc8-42a9-aa62-df7a52875447] com.alan.trace.a.AController             : Hello, andy
2019-12-26 21:36:35.380  INFO 5132 --- [nio-8001-exec-2] [8a59cb96-bbc8-42a9-aa62-df7a52875447] com.alan.trace.common.HttpUtils          : send http request success
```

B服务输出日志：

```java
2019-12-26 21:36:29.244  INFO 2368 --- [nio-8002-exec-1] [8a59cb96-bbc8-42a9-aa62-df7a52875447] com.alan.trace.b.BController             : Hello, b receive request from a
2019-12-26 21:36:29.247  INFO 2368 --- [nio-8002-exec-1] [8a59cb96-bbc8-42a9-aa62-df7a52875447] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService
2019-12-26 21:36:35.279  INFO 2368 --- [   async-pool-1] [8a59cb96-bbc8-42a9-aa62-df7a52875447] com.alan.trace.b.BService                : send msg by spring success
2019-12-26 21:36:35.283  INFO 2368 --- [pool-1-thread-1] [8a59cb96-bbc8-42a9-aa62-df7a52875447] com.alan.trace.b.BService                : send msg by thread pool success
```

可以看到，A服务成功生成了traceId，并且传递给了B服务，且B服务线程间可以保证同一个请求的traceId是可以传递的。


---

# Agent Instructions: Querying This Documentation

If you need additional information that is not directly available in this page, you can query the documentation dynamically by asking a question.

Perform an HTTP GET request on the current page URL with the `ask` query parameter:

```
GET https://ldbmcs.gitbook.io/java/fen-bu-shi-24/ri-zhi-xi-tong/fen-bu-shi-xi-tong-zhong-ru-he-you-ya-di-zhui-zong-ri-zhi.md?ask=<question>
```

The question should be specific, self-contained, and written in natural language.
The response will contain a direct answer to the question and relevant excerpts and sources from the documentation.

Use this mechanism when the answer is not explicitly present in the current page, you need clarification or additional context, or you want to retrieve related documentation sections.
