平常技巧 - 微服務中單應用全鏈路日誌處理

背景

最近在排查問題查詢日誌的的時候，有個很困擾的問題就是多線程調用的狀況下，沒辦法查詢一次調用的全鏈路調用日誌，好比在使用elk查詢日誌的時候，我想看某個日誌的先後調用的完整的日誌，若是不作處理的話是不太好查詢的，因此我經過查詢資料發現確實有不少方式處理這種問題，如下是我我的認爲比較好的處理方式，即經過MDC處理.

MDC介紹

MDC（Mapped Diagnostic Context，映射調試上下文）是 log4j 、logback及log4j2 提供的一種方便在多線程條件下記錄日誌的功能。 MDC 能夠當作是一個 與當前線程綁定的哈希表，能夠往其中添加鍵值對。MDC 中包含的內容能夠 被同一線程中執行的代碼所訪問。當前線程的子線程會繼承其父線程中的 MDC 的內容。當須要記錄日誌時，只須要從 MDC 中獲取所需的信息便可。MDC 的內容則由程序在適當的時候保存進去。對於一個 Web 應用來講，一般是在請求被處理的最開始保存這些數據

API說明：

• clear() => 移除全部MDC
• get (String key) => 獲取當前線程MDC中指定key的值
• getContext() => 獲取當前線程MDC的MDC
• put(String key, Object o) => 往當前線程的MDC中存入指定的鍵值對
• remove(String key) => 刪除當前線程MDC中指定的鍵值對

實現（基於spring boot）

一，建立EnvironmentPostProcessor實現類，配置日誌格式化全局環境配置，如："%1p [%X{X-B3-TraceId:-}]"

public class TraceEnvironmentPostProcessor implements EnvironmentPostProcessor {

    private static final String PROPERTY_SOURCE_NAME = "defaultProperties";

    private static final String LEVEL_STR_PARENT = "%1p [%X{X-B3-TraceId:-}]";

    private static final String LOG_PATTERN_LEVEL = "logging.pattern.level";

    @Override
    public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {

        Map<String, Object> map = new HashMap<>(1);
        map.put(LOG_PATTERN_LEVEL, LEVEL_STR_PARENT);

        MutablePropertySources propertySources = environment.getPropertySources();

        MapPropertySource target = null;
        if (propertySources.contains(PROPERTY_SOURCE_NAME)) {
            PropertySource<?> source = propertySources.get(PROPERTY_SOURCE_NAME);
            if (source instanceof MapPropertySource) {
                target = (MapPropertySource) source;
                for (String key : map.keySet()) {
                    if (!target.containsProperty(key)) {
                        target.getSource().put(key, map.get(key));
                    }
                }
            }
        }
        if (target == null) {
            target = new MapPropertySource(PROPERTY_SOURCE_NAME, map);
        }
        if (!propertySources.contains(PROPERTY_SOURCE_NAME)) {
            propertySources.addLast(target);
        }
    }
}

二，使用filter攔截每次請求，經過MDC爲當前線程添加惟一traceId

@Component
public class TraceFilter implements Filter {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain) throws IOException, ServletException {
        //String LEGACY_TRACE_ID_NAME = "X-B3-TraceId";
        HttpServletRequest request = ((HttpServletRequest) servletRequest);
        String traceId = request.getParameter(LogConstant.LEGACY_TRACE_ID_NAME);

        // 若是爲空，則表示第一次訪問，即上游服務端的請求
        if (StringUtils.isEmpty(traceId)) {
            //使用工具類生成uuid
            MDC.put(LogConstant.LEGACY_TRACE_ID_NAME, TraceIdUtil.traceId());
        } else {
            MDC.put(LogConstant.LEGACY_TRACE_ID_NAME, traceId);
        }
        chain.doFilter(servletRequest, servletResponse);
        MDC.clear();
    }
}

三，在META-INF目錄下添加spring.factories文件，添加咱們建立的processor類，在項目啓動的時候經過spring boot自動掃描，經過spring調用postProcessEnvironment發放初始化配置

# Environment Post Processor
org.springframework.boot.env.EnvironmentPostProcessor=\
com.example.log.trace.processor.TraceEnvironmentPostProcessor

四，使用簡單的controller測試日誌

@Slf4j
@RestController
public class TraceLogController {

    @GetMapping(value = "/trace")
    public Object trace() {
        log.info("---------trace log 1--------");
        log.info("---------trace log 2--------");
        log.info("---------trace log 3--------");
        log.info("---------trace log 4--------");
        return Boolean.TRUE;
    }
}

發現打印的日誌已經有咱們添加的惟一的 traceId,而且屢次打印的都是同一個traceId，這樣咱們在elk中想要查詢一次調用的全鏈路調用日誌就很方便了，只要經過traceId查詢就很容易查詢全鏈路的日誌

2020-08-29 16:48:37.412 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 1--------
2020-08-29 16:52:11.284 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 2--------
2020-08-29 16:53:38.189 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 3--------
2020-08-29 17:23:37.527 INFO [36d47a716d6d4891a264f050ff710d38] 20856 --- [nio-8080-exec-3] c.e.l.t.controller.TraceLogController    : ---------trace log 4--------

原理分析

猜測

實現原理確定是log-back(spring boot默認日誌框架)經過拼接的方式打印日誌，咱們在全局添加了對應的key-value的匹配原則，在經過log打印日誌的時候使用mdc經過key替換咱們在添加的uuid,所以很簡單的實現了全鏈路日誌

源碼分析

經過debug跟蹤log鏈路，其調用鏈路仍是很長的（以下圖），咱們只須要關心關鍵的邏輯就能夠了，
其中打印日誌拼接是經過ch.qos.logback.core.pattern.PatternLayoutBase#writeLoopOnConverters 進行處理的。

writeLoopOnConverters經過遍歷調用converter的write方法拼接所須要打印的日誌，以下流程：

DateConverter       -----時間---- 2020-08-29 17:45:22.318
LiteralConverter    -----空格---- 2020-08-29 17:45:22.318 有空格
CompositeConverter ----自定義---- 2020-08-29 17:45:22.318 INFO [1a3801d149bb4b5e99698ab53481e263]
......剩下的還有線程號,執行類等咱們只關心自定義的規則處理.....

再看看CompositeConverter具體處理邏輯，發現其中還存在一層遍歷處理以下圖，
拼接了咱們自定義的[traceId]的日誌，其中核心的處理類就是MDCConverter的處理，替換咱們定義的key

MDCConverter核心處理方法以下，經過key：X-B3-TraceId從 mdcPropertyMap中獲取traceId，自此證明了咱們的猜測，經過key拿到value進行日誌拼接，全鏈路日誌原理簡單分析到此爲止！

@Override
public String convert(ILoggingEvent event) {
    //X-B3-TraceId -> 1a3801d149bb4b5e99698ab53481e263
    Map<String, String> mdcPropertyMap = event.getMDCPropertyMap();

    if (mdcPropertyMap == null) {
        return defaultValue;
    }

    if (key == null) {
        return outputMDCForAllKeys(mdcPropertyMap);
    } else {
        //X-B3-TraceId
        String value = mdcPropertyMap.get(key);
        if (value != null) {
            return value;
        } else {
            return defaultValue;
        }
    }
}