基于SLF4J MDC機(jī)制實(shí)現(xiàn)日志的鏈路追蹤

問題描述

最近經(jīng)常做線上問題的排查，而排查問題用得最多的方式是查看日志，但是在現(xiàn)有系統(tǒng)中，各種無關(guān)日志穿行其中，導(dǎo)致我沒辦法快速的找出用戶在一次請(qǐng)求中所有的日志。

問題分析

我們沒辦法快速定位用戶在一次請(qǐng)求中對(duì)應(yīng)的所有日志，或者說是定位某個(gè)用戶操作的所有日志，那是因?yàn)槲覀冊(cè)谳敵龅娜罩镜臅r(shí)候沒把請(qǐng)求的唯一標(biāo)示或者說是用戶身份標(biāo)示輸出到我們的日志中，導(dǎo)致我們沒辦法根據(jù)一個(gè)請(qǐng)求或者用戶身份標(biāo)示來做日志的過濾。所以我們?cè)谟涗浫罩镜氖呛蟀颜?qǐng)求的唯一標(biāo)示（sessionId）或者身份標(biāo)示（userId） 記錄到日志中這個(gè)問題就可以得到很好的解決了。

解決方案

  1. 在每次請(qǐng)求的時(shí)候，獲取到請(qǐng)求的sessionId（或者自己生成一個(gè)偽sessionId），并在每次輸出log的時(shí)候?qū)⑦@個(gè)sessionId輸出到日志中。這個(gè)方式實(shí)現(xiàn)簡單，代碼侵入型強(qiáng)，每次輸出都會(huì)多輸出一個(gè)sessionId參數(shù)，工作量大，但是可控粒度高。

  2. 我們使用Logback的MDC機(jī)制，日志模板中加入sessionId格式。在日志輸出格式中指定輸出sessionId。如：

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

這種方式工作量小，代碼侵入小，易擴(kuò)展，但是可控粒度低。

方案說明

第一種方案很簡單，也很容易實(shí)現(xiàn)，就是在輸出日志的時(shí)候多輸出一個(gè)參數(shù)，如：

logger.info("sessionId: {}, message: {}", sessionId, "日志信息");

我們這里主要說一下第二種方式的實(shí)現(xiàn)。

實(shí)現(xiàn)思路，這里以Spring MVC為例：

  1. 新建一個(gè)日志攔截器，在攔截所有請(qǐng)求，在處理請(qǐng)求前將sessionId放到MDC中，在處理完請(qǐng)求后清除MDC的內(nèi)容。這里就解決了80%的問題。

  2. 在原來版本中新起線程時(shí)MDC會(huì)自動(dòng)將父線程的MDC內(nèi)容復(fù)制給子線程，因?yàn)镸DC內(nèi)部使用的是InheritableThreadLocal，但是因?yàn)樾阅軉栴}在最新的版本中被取消了，所以子線程不會(huì)自動(dòng)獲取到父線程的MDC內(nèi)容。官方建議我們?cè)诟妇€程新建子線程之前調(diào)用MDC.getCopyOfContextMap()方法將MDC內(nèi)容取出來傳給子線程，子線程在執(zhí)行操作前先調(diào)用MDC.setContextMap()方法將父線程的MDC內(nèi)容設(shè)置到子線程。

  3. 設(shè)置日志輸出格式

%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 {
    /**
     * 會(huì)話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 {

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

注冊(cè)攔截器

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

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

    /**
     * 注冊(cè)攔截器
     *
     * @param registry
     */
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        // addPathPatterns 用于添加攔截規(guī)則, 這里假設(shè)攔截 /url 后面的全部鏈接
        // excludePathPatterns 用戶排除攔截
        registry.addInterceptor(logInterceptor()).addPathPatterns("/**");
        super.addInterceptors(registry);
    }
}

擴(kuò)展ThreadPoolTaskExecutor線程池

擴(kuò)展ThreadPoolTaskExecutor線程池的主要目的是實(shí)現(xiàn)將父線程的MDC內(nèi)容復(fù)制給子線程。

package com.xiaolyuh.utils;

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

import java.util.Map;

/**
 * 這是{@link ThreadPoolTaskExecutor}的一個(gè)簡單替換，可以在每個(gè)任務(wù)之前設(shè)置子線程的MDC數(shù)據(jù)。
 * <p/>
 * 在記錄日志的時(shí)候，一般情況下我們會(huì)使用MDC來存儲(chǔ)每個(gè)線程的特有參數(shù)，如身份信息等，以便更好的查詢?nèi)罩尽? * 但是Logback在最新的版本中因?yàn)樾阅軉栴}，不會(huì)自動(dòng)的將MDC的內(nèi)存?zhèn)鹘o子線程。所以Logback建議在執(zhí)行異步線程前
 * 先通過MDC.getCopyOfContextMap()方法將MDC內(nèi)存獲取出來，再傳給線程。
 * 并在子線程的執(zhí)行的最開始調(diào)用MDC.setContextMap(context)方法將父線程的MDC內(nèi)容傳給子線程。
 * <p>
 * https://logback.qos.ch/manual/mdc.html
 *
 * @author yuhao.wang3
 */
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {

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

    /**
     * 子線程委托的執(zhí)行方法
     *
     * @param runnable {@link Runnable}
     * @param context  父線程MDC內(nèi)容
     */
    private void run(Runnable runnable, Map<String, String> context) {
        // 將父線程的MDC內(nèi)容傳給子線程
        MDC.setContextMap(context);
        try {
            // 執(zhí)行異步操作
            runnable.run();
        } finally {
            // 清空MDC內(nèi)容
            MDC.clear();
        }
    }
}

擴(kuò)展Hystrix

擴(kuò)展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">
        <!-- 不丟失日志.默認(rèn)的,如果隊(duì)列的80%已滿,則會(huì)丟棄TRACT、DEBUG、INFO級(jí)別的日志 -->
        <discardingThreshold>0</discardingThreshold>
        <!-- 更改默認(rèn)的隊(duì)列的深度,該值會(huì)影響性能.默認(rèn)值為256 -->
        <queueSize>2048</queueSize>
        <includeCallerData>true</includeCallerData>
        <!-- 添加附加的appender,最多只能添加一個(gè) -->
        <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 工程

最后編輯于 ：
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點(diǎn)，簡書系信息發(fā)布平臺(tái)，僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

  • Spring Cloud為開發(fā)人員提供了快速構(gòu)建分布式系統(tǒng)中一些常見模式的工具（例如配置管理，服務(wù)發(fā)現(xiàn)，斷路器，智...
    卡卡羅2017閱讀 136,506評(píng)論 19贊 139
  • 原文地址為 https://github.com/logstash/logstash-logback-encode...
    飛來來閱讀 19,116評(píng)論 1贊 10
  • 1.ios高性能編程 (1).內(nèi)層 最小的內(nèi)層平均值和峰值(2).耗電量 高效的算法和數(shù)據(jù)結(jié)構(gòu)(3).初始化時(shí)...
    歐辰_OSR閱讀 30,192評(píng)論 8贊 265
  • 你對(duì)別人有多少付出才有資格要求回報(bào)。
    剪秋瞳閱讀 294評(píng)論 0贊 0
  • 【如果人走茶不涼，那該有多累】 人走茶涼，物是人非，簡短的詞語，道盡了人情冷暖世態(tài)炎涼。人海茫茫，不論是一次偶然的...
    映卿閱讀 132評(píng)論 0贊 0

友情鏈接更多精彩內(nèi)容