1.概述
作為一名後端開發工程師，排查系統問題用得最多的手段之一就是檢視系統日志，在當下主要的分布式叢集環境中一般使用ELK(Elasticsearch , Logstash, Kibana)來統一收集日志，以便後續檢視日志定位追蹤相關問題。但是在并發情況下，大量的系統使用者即多線程并發通路後端服務導緻同一個請求的日志記錄不再是連續相鄰的，此時多個請求的日志是一起串行輸出到檔案中，是以我們篩選出指定請求的全部相關日志還是比較麻煩的，同時當後端異步處理功能邏輯以及微服務的下遊服務調用日志追蹤也有着相同的問題。
為了快速排查、定位、解決日常回報的系統問題，我們就必須解決上面所說的檢視請求日志的痛點。解決方案就是：每個請求都使用一個唯一辨別traceId來追蹤全部的鍊路顯示在日志中，并且不修改原有的列印方式(代碼無入侵)，然後使用使用Logback的MDC機制日志模闆中加入traceId辨別，取值方式為%X{traceId} 。這樣在收集的日志檔案中就可以看到每行日志有一個tracceId值，每個請求的值都不一樣，這樣我們就可以根據traceId查詢過濾出一次請求的所有上下文日志了。
項目推薦：基于SpringBoot2.x、SpringCloud和SpringCloudAlibaba企業級系統架構底層架構封裝，解決業務開發時常見的非功能性需求，防止重複造輪子，友善業務快速開發和企業技術棧架構統一管理。引入元件化的思想實作高内聚低耦合并且高度可配置化，做到可插拔。嚴格控制包依賴和統一版本管理，做到最少化依賴。注重代碼規範和注釋，非常适合個人學習和企業使用
Github位址：github.com/plasticene/…
Gitee位址：gitee.com/plasticene3…
微信公衆号：Shepherd進階筆記
2.實作方案
MDC（Mapped Diagnostic Context，映射調試上下文）是 log4j 和logback 提供的一種友善在多線程條件下記錄日志的功能。MDC 可以看成是一個與目前線程綁定的Map，可以往其中添加鍵值對。MDC 中包含的内容可以被同一線程中執行的代碼所通路。目前線程的子線程會繼承其父線程中的 MDC 的内容。當需要記錄日志時，隻需要從MDC 中擷取所需的資訊即可。MDC的内容則由程式在适當的時候儲存進去。對于一個 Web 應用來說，通常是在請求被處理的最開始儲存這些資料。
由于MDC内部使用的是ThreadLocal是以隻有本線程才有效，子線程和下遊的服務MDC裡的值會丢失；是以方案主要的難點是解決traceId值的傳遞問題，需要重點關注一下兩點：
- MDC中traceId資料如何傳遞給下遊服務，下遊服務如何接收traceId并放入MDC中
- 異步的情況下(線程池)如何把traceId值傳給子線程。
2.1 設定日志模闆
無論是我們的項目使用的是log4j還是logback架構，我們都需要先調整日志配置檔案的日志格式如下：
xml複制代碼<!-- 日志格式 -->
<property name="CONSOLE_LOG_PATTERN" value="[%X{traceId}] [%-5p] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%t@${PID}] %c %M : %m%n"/>
這樣才能有效地把traceId收集到日志檔案中。
2.2 請求上下文設定traceId并有效傳遞下遊服務
按照上面說的，每個請求使用一個唯一辨別traceId來追蹤一次請求的全部日志，這就要求我們的traceId必須保證唯一性，不然就會出現請求日志混亂問題，是絕對不允許的。這裡我們利用hutool架構的生成id工具IdUtil來生成唯一值，可以生成uuid或者使用雪花算法Snowflake生成唯一id都可以，因為這裡id是記錄在日志檔案中做唯一辨別用的，是以對id字元類型，遞增性那些沒啥要求，隻要唯一辨別即可，按照之前習慣，我就用雪花算法生成唯一id辨別了。
生成traceId并放入到MDC上下文中
scala複制代碼public class WebTraceFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
FilterChain filterChain) throws IOException, ServletException {
try {
String traceId = request.getHeader(MDCTraceUtils.TRACE_ID_HEADER);
if (StrUtil.isEmpty(traceId)) {
MDCTraceUtils.addTrace();
} else {
MDCTraceUtils.putTrace(traceId);
}
filterChain.doFilter(request, response);
} finally {
MDCTraceUtils.removeTrace();
}
}
}
這裡通過一個過濾器來設定traceId放入到MDC中，可以将該過濾器的執行優先級設定比較靠前，這樣就可以有效保證我們一次請求上下文的日志中都有traceId了。同時這個過濾器我們是內建在自定義實作的web starter中，公司的所有服務都會引用web starter內建該過濾器，意味着隻要我們請求下遊服務時添加了traceId這個header，下遊服務執行到該過濾器時就會拿到上遊服務傳遞過來的traceId值放入到目前服務的MDC中。MDCTraceUtils工具類代碼如下：
arduino複制代碼public class MDCTraceUtils {
/**
* 追蹤id的名稱
*/
public static final String KEY_TRACE_ID = "traceId";
/**
* 日志鍊路追蹤id資訊頭
*/
public static final String TRACE_ID_HEADER = "x-traceId-header";
/**
* 建立traceId并指派MDC
*/
public static void addTrace() {
String traceId = createTraceId();
MDC.put(KEY_TRACE_ID, traceId);
}
/**
* 指派MDC
*/
public static void putTrace(String traceId) {
MDC.put(KEY_TRACE_ID, traceId);
}
/**
* 擷取MDC中的traceId值
*/
public static String getTraceId() {
return MDC.get(KEY_TRACE_ID);
}
/**
* 清除MDC的值
*/
public static void removeTrace() {
MDC.remove(KEY_TRACE_ID);
}
/**
* 建立traceId
*/
public static String createTraceId() {
return IdUtil.getSnowflake().nextIdStr();
}
}
接下來我們就來示範下traceId如何在服務間有效傳遞。無論是微服務間的服務調用還是單體項目的調用下遊服務，我都建議使用Spring Cloud架構中的openfeign元件進行服務間接口調用，如果對元件openfeign不太熟悉的，可以看看之前我總結的 openfeign實作原理進行了解。這裡就用openFeign進行模拟服務間調用下遊服務擷取工廠中的房間清單的接口
kotlin複制代碼@FeignClient(name = "workshopService", url = "http://127.0.0.1:16688/textile", path = "/workshop")
public interface WorkshopService {
@GetMapping("/list/temp")
ResponseVO<List<WorkshopDTO>> getList();
}
增加feign攔截器，繼續把目前服務的traceId值傳遞給下遊服務
ini複制代碼public class FeignInterceptor implements RequestInterceptor {
@Override
public void apply(RequestTemplate requestTemplate) {
ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
// 傳遞請求相關header
if (requestAttributes != null) {
HttpServletRequest request = requestAttributes.getRequest();
Enumeration<String> headerNames = request.getHeaderNames();
if (headerNames != null) {
while (headerNames.hasMoreElements()) {
String name = headerNames.nextElement();
// 跳過 content-length
if (Objects.equals("content-length", name)){
continue;
}
String value = request.getHeader(name);
requestTemplate.header(name, value);
}
}
}
// 傳遞日志追蹤的traceId
String traceId = MDCTraceUtils.getTraceId();
if (StringUtils.isNotBlank(traceId)) {
requestTemplate.header(MDCTraceUtils.TRACE_ID_HEADER, traceId);
}
}
}
可以看到這裡主要完成傳遞請求的header，traceId這個header單獨處理，這是因為webTraceFilter過濾器中隻把traceId放入了MDC中，并沒有吧traceId放入到請求的header中，servlet層的filter過濾器Spring不建議修改請求的參數，包括header，改起來也比較麻煩，是以這裡需要單獨處理傳遞。當然這裡的攔截器FeignInterceptor和上面的過濾器WebTraceFilter都需要注入到Spring容器中。
編寫代碼進行接口調用測試：
java複制代碼 @GetMapping("/trace")
public void testTrace() {
log.info("開始執行咯");
BaseQuery query = new BaseQuery();
ResponseVO<List<WorkshopDTO>> responseVO = workshopService.getList();
log.info("接口傳回結果：{}", responseVO);
}
執行日志列印如下，目前服務的日志：
sql複制代碼[1675794072381583360] [INFO ] [2023-07-03 17:10:16.289] [http-nio-18888-exec-5@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Request Info : {"ip":"127.0.0.1","url":"http://127.0.0.1:18888/fds/test/trace","httpMethod":"GET","classMethod":"com.plasticene.fast.controller.TestController.testTrace","requestParams":null}
[1675794072381583360] [INFO ] [2023-07-03 17:10:16.299] [http-nio-18888-exec-5@24417] com.plasticene.fast.controller.TestController testTrace$original$mZGAheRd : 開始執行咯
[1675794072381583360] [INFO ] [2023-07-03 17:10:17.087] [http-nio-18888-exec-5@24417] com.plasticene.fast.controller.TestController testTrace$original$mZGAheRd : 接口傳回結果：ResponseVO(code=200, msg=OK, data=[WorkshopDTO(id=3, orgId=4, name=檢驗工廠中的房間, location=杭州市西湖區, remark=這裡是最嚴格的, machineCount=null)])
[1675794072381583360] [INFO ] [2023-07-03 17:10:17.088] [http-nio-18888-exec-5@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Response result: null
[1675794072381583360] [INFO ] [2023-07-03 17:10:17.089] [http-nio-18888-exec-5@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : time cost: 805
traceId為：1675794072381583360，看看下遊服務textile的日志如下：
sql複制代碼[1675794072381583360] [INFO ] [2023-07-03 17:10:16.438] [http-nio-16688-exec-1@24461] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Request Info : {"ip":"127.0.0.1","url":"http://127.0.0.1:16688/textile/workshop/list/temp","httpMethod":"GET","classMethod":"com.plasticene.textile.controller.WorkshopController.getAllList","requestParams":null}
[1675794072381583360] [DEBUG] [2023-07-03 17:10:16.939] [http-nio-16688-exec-1@24461] com.plasticene.textile.dao.WorkshopDAO.selectList debug : ==> Preparing: SELECT id, org_id, name, location, remark, create_time, update_time, creator, updater FROM workshop WHERE (org_id = ?) ORDER BY id DESC
[1675794072381583360] [DEBUG] [2023-07-03 17:10:16.972] [http-nio-16688-exec-1@24461] com.plasticene.textile.dao.WorkshopDAO.selectList debug : ==> Parameters: 4(Integer)
[1675794072381583360] [DEBUG] [2023-07-03 17:10:17.008] [http-nio-16688-exec-1@24461] com.plasticene.textile.dao.WorkshopDAO.selectList debug : <== Total: 1
[1675794072381583360] [INFO ] [2023-07-03 17:10:17.029] [http-nio-16688-exec-1@24461] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Response result: [{"id":3,"orgId":4,"name":"檢驗工廠中的房間","location":"杭州市西湖區","remark":"這裡是最嚴格的","machineCount":null}]
[1675794072381583360] [INFO ] [2023-07-03 17:10:17.040] [http-nio-16688-exec-1@24461] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : time cost: 621
可以看到兩個服務的traceId都是一樣的，這就說明我們的traceId有效傳遞了。
當然我們也可以使用Spring自帶的RestTemplate、或者httpClient、OkHttp3等架構進行接口調用，隻要請求接口時設定traceId這個header即可，使用restTemplate用戶端調接口時，還可以通過擴充點ClientHttpRequestInterceptor接口的實作類對請求進行攔截處理進行統一traceId的header設定，這樣就不用每個接口請求都要設定一遍，盡量減少重複勞動做到優雅不過時。這裡不在展示詳細，請自我去實作。
2.3 異步父子線程traceId傳遞
上面說過MDC内部使用的是ThreadLocal，是以隻有本線程才有效，子線程和下遊的服務MDC裡的值會丢失。我們項目服務使用的logback日志架構，是以我們需要重寫logback的LogbackMDCAdapter，由于logback的MDC實作内部使用的是ThreadLocal不能傳遞子線程，是以需要重寫替換為阿裡的TransmittableThreadLocal。TransmittableThreadLocal 是Alibaba開源的、用于解決在使用線程池等會池化複用線程的執行元件情況下，提供ThreadLocal值的傳遞功能，解決異步執行時上下文傳遞的問題。官方文檔位址：github.com/alibaba/tra…
重寫logback的LogbackMDCAdapter，自定義實作TtlMDCAdapter類，其實就是把LogbackMDCAdapter的ThreadLocal換成TransmittableThreadLocal即可，其他代碼都是一樣的。
typescript複制代碼/**
*重構{@link LogbackMDCAdapter}類，搭配TransmittableThreadLocal實作父子線程之間的資料傳遞
*
* @author fjzheng
* @version 1.0
* @date 2022/7/14 13:50
*/
public class TtlMDCAdapter implements MDCAdapter {
private final ThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new TransmittableThreadLocal<>();
private static final int WRITE_OPERATION = 1;
private static final int MAP_COPY_OPERATION = 2;
private static TtlMDCAdapter mtcMDCAdapter;
/**
* keeps track of the last operation performed
*/
private final ThreadLocal<Integer> lastOperation = new ThreadLocal<>();
static {
mtcMDCAdapter = new TtlMDCAdapter();
MDC.mdcAdapter = mtcMDCAdapter;
}
public static MDCAdapter getInstance() {
return mtcMDCAdapter;
}
private Integer getAndSetLastOperation(int op) {
Integer lastOp = lastOperation.get();
lastOperation.set(op);
return lastOp;
}
private static boolean wasLastOpReadOrNull(Integer lastOp) {
return lastOp == null || lastOp == MAP_COPY_OPERATION;
}
private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) {
Map<String, String> newMap = Collections.synchronizedMap(new HashMap<>());
if (oldMap != null) {
// we don't want the parent thread modifying oldMap while we are
// iterating over it
synchronized (oldMap) {
newMap.putAll(oldMap);
}
}
copyOnInheritThreadLocal.set(newMap);
return newMap;
}
/**
* Put a context value (the <code>val</code> parameter) as identified with the
* <code>key</code> parameter into the current thread's context map. Note that
* contrary to log4j, the <code>val</code> parameter can be null.
* <p/>
* <p/>
* If the current thread does not have a context map it is created as a side
* effect of this call.
*
* @throws IllegalArgumentException in case the "key" parameter is null
*/
@Override
public void put(String key, String val) {
if (key == null) {
throw new IllegalArgumentException("key cannot be null");
}
Map<String, String> oldMap = copyOnInheritThreadLocal.get();
Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);
if (wasLastOpReadOrNull(lastOp) || oldMap == null) {
Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
newMap.put(key, val);
} else {
oldMap.put(key, val);
}
}
/**
* Remove the the context identified by the <code>key</code> parameter.
* <p/>
*/
@Override
public void remove(String key) {
if (key == null) {
return;
}
Map<String, String> oldMap = copyOnInheritThreadLocal.get();
if (oldMap == null) {
return;
}
Integer lastOp = getAndSetLastOperation(WRITE_OPERATION);
if (wasLastOpReadOrNull(lastOp)) {
Map<String, String> newMap = duplicateAndInsertNewMap(oldMap);
newMap.remove(key);
} else {
oldMap.remove(key);
}
}
/**
* Clear all entries in the MDC.
*/
@Override
public void clear() {
lastOperation.set(WRITE_OPERATION);
copyOnInheritThreadLocal.remove();
}
/**
* Get the context identified by the <code>key</code> parameter.
* <p/>
*/
@Override
public String get(String key) {
final Map<String, String> map = copyOnInheritThreadLocal.get();
if ((map != null) && (key != null)) {
return map.get(key);
} else {
return null;
}
}
/**
* Get the current thread's MDC as a map. This method is intended to be used
* internally.
*/
public Map<String, String> getPropertyMap() {
lastOperation.set(MAP_COPY_OPERATION);
return copyOnInheritThreadLocal.get();
}
/**
* Returns the keys in the MDC as a {@link Set}. The returned value can be
* null.
*/
public Set<String> getKeys() {
Map<String, String> map = getPropertyMap();
if (map != null) {
return map.keySet();
} else {
return null;
}
}
/**
* Return a copy of the current thread's context map. Returned value may be
* null.
*/
@Override
public Map<String, String> getCopyOfContextMap() {
Map<String, String> hashMap = copyOnInheritThreadLocal.get();
if (hashMap == null) {
return null;
} else {
return new HashMap<>(hashMap);
}
}
@Override
public void setContextMap(Map<String, String> contextMap) {
lastOperation.set(WRITE_OPERATION);
Map<String, String> newMap = Collections.synchronizedMap(new HashMap<>());
newMap.putAll(contextMap);
// the newMap replaces the old one for serialisation's sake
copyOnInheritThreadLocal.set(newMap);
}
}
接下來隻需要實作程式啟動時加載上我們自己實作的TtlMDCAdapter:
typescript複制代碼/**
*
* 初始化TtlMDCAdapter執行個體，并替換MDC中的adapter對象
*
* @author fjzheng
* @version 1.0
* @date 2022/7/14 13:55
*/
public class TtlMDCAdapterInitializer implements ApplicationContextInitializer<ConfigurableApplicationContext> {
@Override
public void initialize(ConfigurableApplicationContext applicationContext) {
//加載TtlMDCAdapter執行個體
TtlMDCAdapter.getInstance();
}
}
這樣我們在異步多線程情況下MDC的traceId值就能正常傳遞，下面來看看測試示例：
java複制代碼 // 定義線程池
private ThreadFactory namedThreadFactory = new ThreadFactoryBuilder()
.setNameFormat("letter-pool-%d").build();
private ExecutorService fixedThreadPool = new ThreadPoolExecutor(Runtime.getRuntime().availableProcessors()*2,
Runtime.getRuntime().availableProcessors() * 40,
0L,
TimeUnit.MILLISECONDS,
new LinkedBlockingQueue<Runnable>(Runtime.getRuntime().availableProcessors() * 20),
namedThreadFactory);
// 測試接口
@GetMapping("/async")
public void testAsync() {
log.info("列印日志了");
fixedThreadPool.execute(()->{
log.info("異步執行了");
try {
Student student = null;
String name = student.getName();
} catch (Exception e) {
log.error("異步報錯了：", e);
}
});
}
執行結果日志列印如下：
less複制代碼[1675805796950241280] [INFO ] [2023-07-03 17:56:51.683] [http-nio-18888-exec-8@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Request Info : {"ip":"127.0.0.1","url":"http://127.0.0.1:18888/fds/test","httpMethod":"GET","classMethod":"com.plasticene.fast.controller.TestController.test","requestParams":null}
[1675805796950241280] [INFO ] [2023-07-03 17:56:51.698] [http-nio-18888-exec-8@24417] com.plasticene.fast.controller.TestController test$original$mZGAheRd : 列印日志了
[1675805796950241280] [INFO ] [2023-07-03 17:56:51.700] [http-nio-18888-exec-8@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Response result: null
[1675805796950241280] [INFO ] [2023-07-03 17:56:51.700] [http-nio-18888-exec-8@24417] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : time cost: 24
[1675805796950241280] [INFO ] [2023-07-03 17:56:51.700] [letter-pool-1@24417] com.plasticene.fast.controller.TestController lambda$test$0 : 異步執行了
[1675805796950241280] [ERROR] [2023-07-03 17:56:51.704] [letter-pool-1@24417] com.plasticene.fast.controller.TestController lambda$test$0 : 異步報錯了：
java.lang.NullPointerException: null
at com.plasticene.fast.controller.TestController.lambda$test$0(TestController.java:93)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
3.總結
以上全部就是關于Spring Boot如何實作分布式日志鍊路追蹤的相關知識點。工欲善其事，必先利其器，我們要想快速通過日志定位系統問題，就必須通過traceId高效查找一次請求的全部上下文日志，包括異步執行的邏輯。
![基于Springboot+VUE+Mysql的大學生校園疫情防控管理系統[圖]](data:image/gif;base64,R0lGODlhAQABAIAAAP///wAAACwAAAAAAQABAAACAkQBADs=)