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

問題描述

最近常常作線上問題的排查，而排查問題用得最多的方式是查看日誌，可是在現有系統中，各類無關日誌穿行其中，致使我沒辦法快速的找出用戶在一次請求中全部的日誌。

問題分析

咱們沒辦法快速定位用戶在一次請求中對應的全部日誌，或者說是定位某個用戶操做的全部日誌，那是由於咱們在輸出的日誌的時候沒把請求的惟一標示或者說是用戶身份標示輸出到咱們的日誌中，致使咱們沒辦法根據一個請求或者用戶身份標示來作日誌的過濾。因此咱們在記錄日誌的是後把請求的惟一標示（sessionId）或者身份標示（userId） 記錄到日誌中這個問題就能夠獲得很好的解決了。

解決方案

1. 在每次請求的時候，獲取到請求的sessionId（或者本身生成一個僞sessionId），並在每次輸出log的時候將這個sessionId輸出到日誌中。這個方式實現簡單，代碼侵入型強，每次輸出都會多輸出一個sessionId參數，工做量大，可是可控粒度高。

2. 咱們使用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%的問題。

2. 在原來版本中新起線程時MDC會自動將父線程的MDC內容複製給子線程，由於MDC內部使用的是InheritableThreadLocal，可是由於性能問題在最新的版本中被取消了，因此子線程不會自動獲取到父線程的MDC內容。官方建議咱們在父線程新建子線程以前調用MDC.getCopyOfContextMap()方法將MDC內容取出來傳給子線程，子線程在執行操做前先調用MDC.setContextMap()方法將父線程的MDC內容設置到子線程。

3. 設置日誌輸出格式

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

擴展Hystrix

擴展Hystrix線程池隔離支持日誌鏈路跟蹤

/**
 * Hystrix線程池隔離支持日誌鏈路跟蹤
 *
 * @author yuhao.wang3
 */
public class MdcHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy {

    @Override
    public <T> Callable<T> wrapCallable(Callable<T> callable) {
        return new MdcAwareCallable(callable, MDC.getCopyOfContextMap());
    }

    private class MdcAwareCallable<T> implements Callable<T> {

        private final Callable<T> delegate;

        private final Map<String, String> contextMap;

        public MdcAwareCallable(Callable<T> callable, Map<String, String> contextMap) {
            this.delegate = callable;
            this.contextMap = contextMap != null ? contextMap : new HashMap();
        }

        @Override
        public T call() throws Exception {
            try {
                MDC.setContextMap(contextMap);
                return delegate.call();
            } finally {
                MDC.clear();
            }
        }
    }
}

配置Hystrix

@Configuration
public class HystrixConfig {

    //用來攔截處理HystrixCommand註解
    @Bean
    public HystrixCommandAspect hystrixAspect() {
        return new HystrixCommandAspect();
    }

    @PostConstruct
    public void init() {
        HystrixPlugins.getInstance().registerConcurrencyStrategy(new MdcHystrixConcurrencyStrategy());
    }

}

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          : ==============================================

源碼

https://github.com/wyh-spring-ecosystem-student/spring-boot-student/tree/releases

spring-boot-student-log 工程