分布式系統中如何優雅地追蹤日志（原理篇）

本文隻講原理，不講架構。

分布式系統中日志追蹤需要考慮的幾個點？

需要一個全服務唯一的id，即traceId，如何保證？
traceId如何在服務間傳遞？
traceId如何在服務内部傳遞？
traceId如何在多線程中傳遞？

我們一一來解答：

全服務唯一的traceId，可以使用uuid生成，正常來說不會出現重複的；
關于服務間傳遞，對于調用者，在協定頭加上traceId，對于被調用者，通過前置攔截器或者過濾器統一攔截；
關于服務内部傳遞，可以使用ThreadLocal傳遞traceId，一處放置，随處可用；
關于多線程傳遞，分為兩種情況：
- 子線程，可以使用InheritableThreadLocal
- 線程池，需要改造線程池對送出的任務進行包裝，把送出者的traceId包裝到任務中

比如，上面這個系統，系統入口在A處，A調用B的服務，B裡面又起了一個線程B1去通路D的服務，B本身又去通路C服務。

我們就可以這麼來跟蹤日志：

所有服務都需要一個全局的InheritableThreadLocal儲存服務内部traceId的傳遞；
所有服務都需要一個前置攔截器或者過濾器，檢測如果請求頭沒有traceId就生成一個，如果有就取出來，并把traceId放到全局的InheritableThreadLocal裡面；
一個服務調用另一個服務的時候把traceId塞到請求頭裡，比如http header，本文來源于工從号彤哥讀源碼；
改造線程池，在送出的時候包裝任務，這個工作量比較大，因為服務内部可能依賴其它架構，這些架構的線程池有可能也需要修改；

實作

我們模拟A到B這兩個服務來實作一個日志跟蹤系統。

為了簡單起見，我們使用SpringBoot，它預設使用的日志架構是logback，而且Slf4j提供了一個包裝了InheritableThreadLocal的類叫MDC，我們隻要把traceId放在MDC中，列印日志的時候統一列印就可以了，不用顯式地列印traceId。

我們分成三個子產品：

公共包：封裝攔截器，traceId的生成，服務内傳遞，請求頭的傳遞等；
A服務：隻依賴于公共包，并提供一個接口接收外部請求；
B服務：依賴于公共包，并内部起一個線程池，用于發送B1->D的請求，當然我們這裡不發送請求，隻線上程池中簡單地列印一條日志；

公共包

TraceFilter.java

前置過濾器，用攔截器實作也是一樣的。

從請求頭中擷取traceId，如果不存在就生成一個，并放入MDC中。

@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() {

    }
}

TraceThreadPoolExecutor.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();
            }
        });
    }
}

TraceAsyncConfigurer.java

改造Spring的異步線程池，包裝送出的任務。

@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();
                }
            };
        }
    }

}

HttpUtils.java

封裝Http工具類，把traceId加入頭中，帶到下一個服務。

@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();
    }

}

A服務

A服務通過Http調用B服務。

@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。

# 本文來源于工從号彤哥讀源碼
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'

B服務

B服務内部有兩種跨線程調用：

利用Spring的異步線程池
使用自己的線程池

BController.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

@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}]

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'

測試

打開浏覽器，輸入

http://localhost:8001/a?name=andy

。

A服務輸出日志：

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服務輸出日志：

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是可以傳遞的。

分布式系統中如何優雅地追蹤日志（原理篇）

分布式系統中日志追蹤需要考慮的幾個點？

實作

公共包

A服務

B服務

測試

繼續閱讀

關于Gradle配置的小結

Java小案例——随機數猜測随機數猜測

nginx location中斜線的位置的重要性

27 Best Free Eclipse Plug-ins for Java Developer to be ProductiveCode Quality PluginsText Editor PluginsDependency ManagementVersion Control Integration PluginsFramework Development Continuous Integration Related PluginsOther Utility Plugins

Java String.format方法的簡單使用

neo4j之cypher使用文檔

GitHub連夜封殺！這份阿裡 10W 字内部 Java 字面試手冊到底有多強？

spark/scala關于【資源檔案】加載方法概述外部檔案加載方案測試資源檔案打包入jar包中小結

mybatis_入門程式Mybatis入門

AOP程式設計_Android優雅權限架構(1)概念基礎，2021金三銀四前言正文大綱正文

Effective Java 8:通用程式設計

OOM三種類型

工廠模式-三種類型

【遞歸】高效率求2的n次幂

win10本地scala和spark安裝安裝scala安裝spark

scala (3) Function 和 Method