[[392965]]

前言

在傳統(tǒng)系統(tǒng)中，如果能夠提供日志輸出，基本上已經(jīng)能夠滿足需求的。但一旦將系統(tǒng)拆分成兩套及以上的系統(tǒng)，再加上負(fù)載均衡等，調(diào)用鏈路就變得復(fù)雜起來。

特別是進(jìn)一步向微服務(wù)方向演化，如果沒有日志的合理規(guī)劃、鏈路追蹤，那么排查日志將變得異常困難。

比如系統(tǒng)A、B、C，調(diào)用鏈路為A -> B -> C，如果每套服務(wù)都是雙活，則調(diào)用路徑有2的三次方種可能性。如果系統(tǒng)更多，服務(wù)更多，調(diào)用鏈路則會(huì)成指數(shù)增長。

因此，無論是幾個(gè)簡單的內(nèi)部服務(wù)調(diào)用，還是復(fù)雜的微服務(wù)系統(tǒng)，都需要通過一個(gè)機(jī)制來實(shí)現(xiàn)日志的鏈路追蹤。讓你系統(tǒng)的日志輸出，像詩一樣有形式美，又有和諧的韻律。

日志追蹤其實(shí)已經(jīng)有很多現(xiàn)成的框架了，比如Sleuth、Zipkin等組件。但這不是我們要講的重點(diǎn)，本文重點(diǎn)基于Spring Boot、LogBack來手寫實(shí)現(xiàn)一個(gè)簡單的日志調(diào)用鏈路追蹤功能?；诖藢?shí)現(xiàn)模式，大家可以更細(xì)粒度的去實(shí)現(xiàn)。

Spring Boot中集成Logback

Spring Boot本身就內(nèi)置了日志功能，這里使用logback日志框架，并對(duì)輸出結(jié)果進(jìn)行格式化。先來看一下SpringBoot對(duì)Logback的內(nèi)置集成，依賴關(guān)系如下。當(dāng)項(xiàng)目中引入了：

<dependency> 
    <groupId>org.springframework.boot</groupId> 
    <artifactId>spring-boot-starter-web</artifactId> 
</dependency> 

spring-boot-starter-web中間接引入了：

<dependency> 
  <groupId>org.springframework.boot</groupId> 
  <artifactId>spring-boot-starter</artifactId> 
</dependency> 

spring-boot-starter又引入了logging的starter：

<dependency> 
  <groupId>org.springframework.boot</groupId> 
  <artifactId>spring-boot-starter-logging</artifactId> 
</dependency> 

在logging中真正引入了所需的logback包：

<dependency> 
  <groupId>ch.qos.logback</groupId> 
  <artifactId>logback-classic</artifactId> 
</dependency> 
<dependency> 
  <groupId>org.apache.logging.log4j</groupId> 
  <artifactId>log4j-to-slf4j</artifactId> 
</dependency> 
<dependency> 
  <groupId>org.slf4j</groupId> 
  <artifactId>jul-to-slf4j</artifactId> 
</dependency> 

因此，我們使用時(shí)，只需將logback-spring.xml配置文件放在resources目錄下即可。理論上配置文件命名為logback.xml也是支持的，但Spring Boot官網(wǎng)推薦使用的名稱為：logback-spring.xml。

然后，在logback-spring.xml中進(jìn)行日志輸出的配置即可。這里不貼全部代碼了，只貼出來相關(guān)日志輸出格式部分，以控制臺(tái)輸出為例：

在value屬性的表達(dá)式中，我們新增了自定義的變量值requestId，通過“[%X{requestId}]”的形式來展示。

這個(gè)requestId便是我們用來追蹤日志的唯一標(biāo)識(shí)。如果一個(gè)請(qǐng)求，從頭到尾都使用了同一個(gè)requestId便可以把整個(gè)請(qǐng)求鏈路串聯(lián)起來。如果系統(tǒng)還基于EKL等日志搜集工具進(jìn)行統(tǒng)一收集，就可以更方便的查看整個(gè)日志的調(diào)用鏈路了。

那么，這個(gè)requestId變量是如何來的，又存儲(chǔ)在何處呢?要了解這個(gè)，我們要先來了解一下日志框架提供的MDC功能。

什么是MDC?

MDC(Mapped Diagnostic Contexts) 是一個(gè)線程安全的存放診斷日志的容器。MDC是slf4j提供的適配其他具體日志實(shí)現(xiàn)包的工具類，目前只有l(wèi)ogback和log4j支持此功能。

MDC是線程獨(dú)立、線程安全的，通常無論是HTTP還是RPC請(qǐng)求，都是在各自獨(dú)立的線程中完成的，這與MDC的機(jī)制可以很好地契合。

在使用MDC功能時(shí)，我們主要使用是put方法，該方法間接的調(diào)用了MDCAdapter接口的put方法。

看一下接口MDCAdapter其中一個(gè)實(shí)現(xiàn)類BasicMDCAdapter中的代碼來：

public class BasicMDCAdapter implements MDCAdapter { 
 
    private InheritableThreadLocal<Map<String, String>> inheritableThreadLocal = new InheritableThreadLocal<Map<String, String>>() { 
        @Override 
        protected Map<String, String> childValue(Map<String, String> parentValue) { 
            if (parentValue == null) { 
                return null; 
            } 
            return new HashMap<String, String>(parentValue); 
        } 
    }; 
 
    public void put(String key, String val) { 
        if (key == null) { 
            throw new IllegalArgumentException("key cannot be null"); 
        } 
        Map<String, String> map = inheritableThreadLocal.get(); 
        if (map == null) { 
            map = new HashMap<String, String>(); 
            inheritableThreadLocal.set(map); 
        } 
        map.put(key, val); 
    } 
    // ... 
} 

通過源碼可以看出內(nèi)部持有一個(gè)InheritableThreadLocal的實(shí)例，該實(shí)例中通過HashMap來保存context數(shù)據(jù)。

此外，MDC提供了put/get/clear等幾個(gè)核心接口，用于操作ThreadLocal中存儲(chǔ)的數(shù)據(jù)。而在logback.xml中，可在layout中通過聲明“%X{requestId}”這種形式來獲得MDC中存儲(chǔ)的數(shù)據(jù)，并進(jìn)行打印此信息。

基于MDC的這些特性，因此它經(jīng)常被用來做日志鏈路跟蹤、動(dòng)態(tài)配置用戶自定義信息(比如requestId、sessionId等)等場景。

實(shí)戰(zhàn)使用

上面了解了一些基礎(chǔ)的原理知識(shí)，下面我們就來看看如何基于日志框架的MDC功能實(shí)現(xiàn)日志的追蹤。

工具類準(zhǔn)備

首先定義一些工具類，這個(gè)強(qiáng)烈建議大家將一些操作通過工具類的形式進(jìn)行實(shí)現(xiàn)，這是寫出優(yōu)雅代碼的一部分，也避免后期修改時(shí)每個(gè)地方都需要改。

TraceID(我們定義參數(shù)名為requestId)的生成類，這里采用UUID進(jìn)行生成，當(dāng)然可根據(jù)你的場景和需要，通過其他方式進(jìn)行生成。

public class TraceIdUtils { 
 
    /** 
     * 生成traceId 
     * 
     * @return TraceId 基于UUID 
     */ 
    public static String getTraceId() { 
        return UUID.randomUUID().toString().replace("-", ""); 
    } 
} 

對(duì)Context內(nèi)容的操作工具類TraceIdContext：

public class TraceIdContext { 
 
    public static final String TRACE_ID_KEY = "requestId"; 
 
    public static void setTraceId(String traceId) { 
        if (StringLocalUtil.isNotEmpty(traceId)) { 
            MDC.put(TRACE_ID_KEY, traceId); 
        } 
    } 
 
    public static String getTraceId() { 
        String traceId = MDC.get(TRACE_ID_KEY); 
        return traceId == null ? "" : traceId; 
    } 
 
    public static void removeTraceId() { 
        MDC.remove(TRACE_ID_KEY); 
    } 
 
    public static void clearTraceId() { 
        MDC.clear(); 
    } 
 
} 

通過工具類，方便所有服務(wù)統(tǒng)一使用，比如requestId可以統(tǒng)一定義，避免每處都不一樣。這里不僅提供了set方法，還提供了移除和清理的方法。

需要注意的是，MDC.clear()方法的使用。如果所有的線程都是通過new Thread方法建立的，線程消亡之后，存儲(chǔ)的數(shù)據(jù)也隨之消亡，這倒沒什么。但如果采用的是線程池的情況時(shí)，線程是可以被重復(fù)利用的，如果之前線程的MDC內(nèi)容沒有清除掉，再次從線程池中獲取這個(gè)線程，會(huì)取出之前的數(shù)據(jù)(臟數(shù)據(jù))，會(huì)導(dǎo)致一些不可預(yù)期的錯(cuò)誤，所以當(dāng)前線程結(jié)束后一定要清掉。

Filter攔截

既然我們要實(shí)現(xiàn)日志鏈路的追蹤，最直觀的思路就是在訪問的源頭生成一個(gè)請(qǐng)求ID，然后一路傳下去，直到這個(gè)請(qǐng)求完成。這里以Http為例，通過Filter來攔截請(qǐng)求，并將數(shù)據(jù)通過Http的Header來存儲(chǔ)和傳遞數(shù)據(jù)。涉及到系統(tǒng)之間調(diào)用時(shí)，調(diào)用方設(shè)置requestId到Header中，被調(diào)用方從Header中取即可。

Filter的定義：

public class TraceIdRequestLoggingFilter extends AbstractRequestLoggingFilter { 
 
    @Override 
    protected void beforeRequest(HttpServletRequest request, String message) { 
        String requestId = request.getHeader(TraceIdContext.TRACE_ID_KEY); 
        if (StringLocalUtil.isNotEmpty(requestId)) { 
            TraceIdContext.setTraceId(requestId); 
        } else { 
            TraceIdContext.setTraceId(TraceIdUtils.getTraceId()); 
        } 
    } 
 
    @Override 
    protected void afterRequest(HttpServletRequest request, String message) { 
        TraceIdContext.removeTraceId(); 
    } 
} 

在beforeRequest方法中，從Header中獲取requestId，如果獲取不到則視為“源頭”，生成一個(gè)requestId，設(shè)置到MDC當(dāng)中。當(dāng)這個(gè)請(qǐng)求完成時(shí)，將設(shè)置的requestId移除，防止上面說到的線程池問題。系統(tǒng)中每個(gè)服務(wù)都可以通過上述方式實(shí)現(xiàn)，整個(gè)請(qǐng)求鏈路就串起來了。

當(dāng)然，上面定義的Filter是需要進(jìn)行初始化的，在Spring Boot中實(shí)例化方法如下：

@Configuration 
public class TraceIdConfig { 
 
    @Bean 
    public TraceIdRequestLoggingFilter traceIdRequestLoggingFilter() { 
        return new TraceIdRequestLoggingFilter(); 
    } 
} 

針對(duì)普通的系統(tǒng)調(diào)用，上述方式基本上已經(jīng)能滿足了，實(shí)踐中可根據(jù)自己的需要在此基礎(chǔ)上進(jìn)行擴(kuò)展。這里使用的是Filter，也可以通過攔截器、Spring的AOP等方式進(jìn)行實(shí)現(xiàn)。

微服務(wù)中的Feign

如果你的系統(tǒng)是基于Spring Cloud中的Feign組件進(jìn)行調(diào)用，則可通過實(shí)現(xiàn)RequestInterceptor攔截器來達(dá)到添加requestId效果。具體實(shí)現(xiàn)如下：

@Configuration 
public class FeignConfig implements RequestInterceptor { 
 
    @Override 
    public void apply(RequestTemplate requestTemplate) { 
        requestTemplate.header(TraceIdContext.TRACE_ID_KEY, TraceIdContext.getTraceId()); 
    } 
 
} 

結(jié)果驗(yàn)證

當(dāng)完成上述操作之后，對(duì)一個(gè)Controller進(jìn)行請(qǐng)求，會(huì)打印如下的日志：

2021-04-13 10:58:31.092 cloud-sevice-consumer-demo [http-nio-7199-exec-1] INFO  [ef76526ca96242bc8e646cdef3ab31e6] c.b.demo.controller.CityController - getCity 
2021-04-13 10:58:31.185 cloud-sevice-consumer-demo [http-nio-7199-exec-1] WARN  [ef76526ca96242bc8e646cdef3ab31e6] o.s.c.o.l.FeignBlockingLoadBalancerClient - 

可以看到requestID已經(jīng)被成功添加。當(dāng)我們排查日志時(shí)，只需找到請(qǐng)求的關(guān)鍵信息，然后根據(jù)關(guān)鍵信息日志中的requestId值就可以把整個(gè)日志串聯(lián)起來。

小結(jié)

最后，我們來回顧一下日志追蹤的整個(gè)過程：當(dāng)請(qǐng)求到達(dá)第一個(gè)服務(wù)器，服務(wù)檢查requestId是否存在，如果不存在，則創(chuàng)建一個(gè)，放入MDC當(dāng)中;服務(wù)調(diào)用其他服務(wù)時(shí)，再通過Header將requestId進(jìn)行傳遞;而每個(gè)服務(wù)的logback配置requestId的輸出。從而達(dá)到從頭到尾將日志串聯(lián)的效果。

在學(xué)習(xí)本文，如果你只學(xué)到了日志追蹤，那是一種損失，因?yàn)槲闹羞€涉及到了SpringBoot對(duì)logback的集成、MDC的底層實(shí)現(xiàn)及坑、過濾器的使用、Feign的請(qǐng)求攔截器等。如果感興趣，每個(gè)都可以發(fā)散一下，學(xué)習(xí)到更多的知識(shí)點(diǎn)。