基於SLF4J MDC機制實現日誌的鏈路追蹤

阿新 • • 發佈：2019-01-22

問題描述

最近經常做線上問題的排查，而排查問題用得最多的方式是檢視日誌，但是在現有系統中，各種無關日誌穿行其中，導致我沒辦法快速的找出使用者在一次請求中所有的日誌。

問題分析

我們沒辦法快速定位使用者在一次請求中對應的所有日誌，或者說是定位某個使用者操作的所有日誌，那是因為我們在輸出的日誌的時候沒把請求的唯一標示或者說是使用者身份標示輸出到我們的日誌中，導致我們沒辦法根據一個請求或者使用者身份標示來做日誌的過濾。所以我們在記錄日誌的是後把請求的唯一標示（sessionId）或者身份標示（userId）記錄到日誌中這個問題就可以得到很好的解決了。

解決方案

在每次請求的時候，獲取到請求的sessionId（或者自己生成一個偽sessionId），並在每次輸出log的時候將這個sessionId輸出到日誌中。這個方式實現簡單，程式碼侵入型強，每次輸出都會多輸出一個sessionId引數，工作量大，但是可控粒度高。
我們使用Logback的MDC機制，日誌模板中加入sessionId格式。在日誌輸出格式中指定輸出sessionId。如：

%d{yyyy-MM-dd HH:mm:ss.SSS}  [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n

這種方式工作量小，程式碼侵入小，易擴充套件，但是可控粒度低。

方案說明

第一種方案很簡單，也很容易實現，就是在輸出日誌的時候多輸出一個引數，如：

logger.info("sessionId: {}, message: {}", sessionId, "日誌資訊");

我們這裡主要說一下第二種方式的實現。

實現思路，這裡以Spring MVC為例：
1. 新建一個日誌攔截器，在攔截所有請求，在處理請求前將sessionId放到MDC中，在處理完請求後清除MDC的內容。這裡就解決了80%的問題。
在原來版本中新起執行緒時MDC會自動將父執行緒的MDC內容複製給子執行緒，因為MDC內部使用的是InheritableThreadLocal，但是因為效能問題在最新的版本中被取消了，所以子執行緒不會自動獲取到父執行緒的MDC內容。官方建議我們在父執行緒新建子執行緒之前呼叫MDC.getCopyOfContextMap()方法將MDC內容取出來傳給子執行緒，子執行緒在執行操作前先呼叫MDC.setContextMap()方法將父執行緒的MDC內容設定到子執行緒。
設定日誌輸出格式
%d{yyyy-MM-dd HH:mm:ss.SSS}  [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n

攔截器 LogInterceptor

package com.xiaolyuh.interceptors;

import org.slf4j.MDC;
import org.springframework.web.servlet.ModelAndView;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

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

/**
 * 日誌攔截器元件，在輸出日誌中加上sessionId
 *
 * @author yuhao.wang3
 */
public class LogInterceptor extends HandlerInterceptorAdapter {
    /**
     * 會話ID
     */
    private final static String SESSION_KEY = "sessionId";

    @Override
    public void afterCompletion(HttpServletRequest arg0, HttpServletResponse arg1, Object arg2, Exception arg3)
            throws Exception {

        // 刪除SessionId
        MDC.remove(SESSION_KEY);
    }

    @Override
    public void postHandle(HttpServletRequest arg0, HttpServletResponse arg1,
                           Object arg2, ModelAndView arg3) throws Exception {
    }

    @Override
    public boolean preHandle(HttpServletRequest request,
                             HttpServletResponse response, Object handler) throws Exception {

        // 設定SessionId
        String token = UUID.randomUUID().toString().replace("-", "");
        MDC.put(SESSION_KEY, token);
        return true;
    }
}

註冊攔截器

/**
 * WEB MVC配置類
 *
 * @author yuhao.wang3
 */
@Configuration
public class WebMvcConfigurer extends WebMvcConfigurerAdapter {

    /**
     * 把我們的攔截器注入為bean
     *
     * @return
     */
    @Bean
    public HandlerInterceptor logInterceptor() {
        return new LogInterceptor();
    }

    /**
     * 註冊攔截器
     *
     * @param registry
     */
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        // addPathPatterns 用於新增攔截規則, 這裡假設攔截 /url 後面的全部連結
        // excludePathPatterns 使用者排除攔截
        registry.addInterceptor(logInterceptor()).addPathPatterns("/**");
        super.addInterceptors(registry);
    }
}

擴充套件ThreadPoolTaskExecutor執行緒池

擴充套件ThreadPoolTaskExecutor執行緒池的主要目的是實現將父執行緒的MDC內容複製給子執行緒。

package com.xiaolyuh.utils;

import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

import java.util.Map;

/**
 * 這是{@link ThreadPoolTaskExecutor}的一個簡單替換，可以在每個任務之前設定子執行緒的MDC資料。
 * <p/>
 * 在記錄日誌的時候，一般情況下我們會使用MDC來儲存每個執行緒的特有引數，如身份資訊等，以便更好的查詢日誌。
 * 但是Logback在最新的版本中因為效能問題，不會自動的將MDC的記憶體傳給子執行緒。所以Logback建議在執行非同步執行緒前
 * 先通過MDC.getCopyOfContextMap()方法將MDC記憶體獲取出來，再傳給執行緒。
 * 並在子執行緒的執行的最開始呼叫MDC.setContextMap(context)方法將父執行緒的MDC內容傳給子執行緒。
 * <p>
 * https://logback.qos.ch/manual/mdc.html
 *
 * @author yuhao.wang3
 */
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {

    /**
     * 所有執行緒都會委託給這個execute方法，在這個方法中我們把父執行緒的MDC內容賦值給子執行緒
     * https://logback.qos.ch/manual/mdc.html#managedThreads
     *
     * @param runnable
     */
    @Override
    public void execute(Runnable runnable) {
        // 獲取父執行緒MDC中的內容，必須在run方法之前，否則等非同步執行緒執行的時候有可能MDC裡面的值已經被清空了，這個時候就會返回null
        Map<String, String> context = MDC.getCopyOfContextMap();
        super.execute(() -> run(runnable, context));
    }

    /**
     * 子執行緒委託的執行方法
     *
     * @param runnable {@link Runnable}
     * @param context  父執行緒MDC內容
     */
    private void run(Runnable runnable, Map<String, String> context) {
        // 將父執行緒的MDC內容傳給子執行緒
        MDC.setContextMap(context);
        try {
            // 執行非同步操作
            runnable.run();
        } finally {
            // 清空MDC內容
            MDC.clear();
        }
    }
}

Logback配置

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="CONSOLE_LOG_PATTERN"
              value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} [%X{sessionId}] %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
    <property name="FILE_LOG_PATTERN"
              value="${FILE_LOG_PATTERN:-%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
    <include resource="org/springframework/boot/logging/logback/base.xml"/>

    <appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
        <!-- 不丟失日誌.預設的,如果佇列的80%已滿,則會丟棄TRACT、DEBUG、INFO級別的日誌 -->
        <discardingThreshold>0</discardingThreshold>
        <!-- 更改預設的佇列的深度,該值會影響效能.預設值為256 -->
        <queueSize>2048</queueSize>
        <includeCallerData>true</includeCallerData>
        <!-- 新增附加的appender,最多隻能新增一個 -->
        <appender-ref ref="FILE"/>
    </appender>

    <logger name="com.xiaolyuh" level="debug" additivity="true"/>
</configuration>

測試類

@Service
public class LogService {
    Logger logger = LoggerFactory.getLogger(LogService.class);

    public void log() {
        logger.debug("==============================================");
        ThreadTaskUtils.run(() -> run());
        FutureTask<String> futureTask = new FutureTask<String>(() -> call());
        ThreadTaskUtils.run(futureTask);
        try {
            logger.debug("===================: {}", futureTask.get());
        } catch (Exception e) {
            logger.error(e.getMessage(), e);
        }
        logger.debug("==============================================");
    }

    private String call() {
        logger.debug("11111111111");
        return "3333";
    }

    public void run() {
        logger.debug("222222222222222");
    }
}

日誌輸出示例

2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService          : ==============================================
2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService          : 222222222222222
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-1] com.xiaolyuh.service.LogService          : 11111111111
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService          : ===================: 3333
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService          : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService          : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-5] com.xiaolyuh.service.LogService          : 222222222222222
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-3] com.xiaolyuh.service.LogService          : 11111111111
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService          : ===================: 3333
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService          : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService          : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-2] com.xiaolyuh.service.LogService          : 222222222222222
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService          : 11111111111
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService          : ===================: 3333
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService          : ==============================================

原始碼

spring-boot-student-log 工程

基於SLF4J MDC機制實現日誌的鏈路追蹤

問題描述

問題分析

解決方案

方案說明

攔截器 LogInterceptor

註冊攔截器

擴充套件ThreadPoolTaskExecutor執行緒池

Logback配置

測試類

日誌輸出示例

原始碼

基於SLF4J MDC機制實現日誌的鏈路追蹤

Laravel + go-micro + grpc 實踐基於 Zipkin 的分布式鏈路追蹤系統摘自https://mp.weixin.qq.com/s/JkLMNabnYbod-b4syMB3Hw?

dubbo + zipkin 實現全鏈路追蹤

SpringBoot之微服務日誌鏈路追蹤

.NET Core整合SkyWalking+SkyAPM-dotne實現分散式鏈路追蹤

基於SLF4J的MDC機制和Dubbo的Filter機制，實現分散式系統的日誌全鏈路追蹤

Dubbox 鏈路追蹤（基於Brave+Zipkin的簡單實現）上

通過slf4j/log4j的MDC/NDC 實現日誌追蹤

基於Spring Boot + Dubbo的全鏈路日誌追蹤(一)

巧用MDC實現簡易分散式鏈路追蹤

Dubbo 全鏈路追蹤日誌的實現

spring cloud分布式使用日誌鏈路跟蹤

Spring Boot + Spring Cloud 實現許可權管理系統後端篇（二十二）：鏈路追蹤（Sleuth、Zipkin）

Centos7 安裝skywalking+elasticsearch,實現java web程式鏈路追蹤

Laravel + go-micro + grpc 實踐基於 Zipkin 的分散式鏈路追蹤系統摘自https://mp.weixin.qq.com/s/JkLMNabnYbod-b4syMB3Hw?

cat 如何實現分散式鏈路跟蹤

阿里雲釋出鏈路追蹤服務Tracing Analysis，從此告別告別日誌查詢

spring cloud分布式日誌鏈路跟蹤

【連載】redis庫存操作，分散式鎖的四種實現方式[三]--基於Redis watch機制實現分散式鎖

SpringCloud學習記錄——Sleuth服務鏈路追蹤（Zipkin實現）

基於SLF4J MDC機制實現日誌的鏈路追蹤

問題描述

問題分析

解決方案

方案說明

攔截器 LogInterceptor

註冊攔截器

擴充套件ThreadPoolTaskExecutor執行緒池

Logback配置

測試類

日誌輸出示例

原始碼

相關推薦