Logback日誌跨執行緒追蹤實踐

Logback 執行緒 · 發表 2019-05-11 13:23:31

摘要：當我們程式在伺服器上面跑的時候,是不是很多時候很難定位問題? 當一大堆繁雜的日誌檔案丟給你的時候,你如何能從中定位到問題? 本專案原始碼已經上傳Github: github.com/liushunqiu/… 1. 自定義日誌模板引數：Logback的Pattern模板當一個請求過...

當我們程式在伺服器上面跑的時候,是不是很多時候很難定位問題? 當一大堆繁雜的日誌檔案丟給你的時候,你如何能從中定位到問題? 本專案原始碼已經上傳Github: github.com/liushunqiu/…

1. 自定義日誌模板引數：Logback的Pattern模板

當一個請求過來,我們想要知道當前請求具體跑了那些流程該怎麼做呢？噔噔噔噔..我們的男主Logback自定義Pattern模板即將登場.

在我們列印日誌的時候,通常我們都會把一些重要的引數資訊寫到日誌裡面,方便我們後期從日誌裡面定位問題,其他的內部系統呼叫我們的程式的時候，我們可以要求他們那邊在header頭裡面增加trace-id這樣的唯一標識，如果沒有該引數的話，我們自己手動生成一個唯一的標識，方便我們將整條請求鏈路構建起來.

<property name="CONSOLE_LOG_PATTERN"
value="[%yellow(%date{yyyy-MM-dd HH:mm:ss})] [%highlight(%-5level)] [%cyan(%traceId)] [%magenta(%thread)] [%blue(%file:%line)] [%green(%logger)] : %.4000m%n"/>
複製程式碼

上面這裡是Logback的定義變數,重點關注 [%cyan(%traceId)] 這個引數(ps:其他的日誌系統如log4j2都有類似的實現)

要實現讓Logback識別我們自定義的識別符號,我們需要繼承兩個方法 ClassicConverter 跟 PatternLayout ,具體實現如下:

public class PatternLogbackLayout extends PatternLayout {
static {
defaultConverterMap.put("traceId", TraceIdPatternConverter.class.getName());
}
}

public class TraceIdPatternConverter extends ClassicConverter {
@Override
public String convert(ILoggingEvent iLoggingEvent) {
String traceId = LogHandlerInterceptor.getTrack();
return StringUtils.isEmpty(traceId) ? "traceId" : traceId;
}
}
複製程式碼

通過spring的攔截器我們將請求的header頭裡面的引數賦值給traceId,然後配置logback.xml，讓logback去識別我們定義的traceId

<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="com.blacksearch.logback.PatternLogbackLayout">
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
</layout>
</encoder>
</appender>
複製程式碼

通過以上配置,我們已經可以在日誌裡面看到traceId了

[2019-05-10 16:47:38] [INFO ] [538e2c0d-3800-4c86-b320-260bdd945c0c] [http-nio-8080-exec-6] [TestLogTrackController.java:15] [com.blacksearch.controller.TestLogTrackController] : 測試
[2019-05-10 16:47:38] [DEBUG] [538e2c0d-3800-4c86-b320-260bdd945c0c] [http-nio-8080-exec-6] [AbstractMessageConverterMethodProcessor.java:298] [org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor] : Nothing to write: null body
複製程式碼

這樣子在伺服器上面我們可以通過

grep '538e2c0d-3800-4c86-b320-260bdd945c0c'
複製程式碼

檢視到當前請求的所有日誌~或者上ELK之後直接搜尋538e2c0d-3800-4c86-b320-260bdd945c0c 方便開心~

2. 當我們使用多執行緒的時候,我們發現,原先定義的標識居然消失了！！！

解決方案：自定義抽象類實現Runnable 首先我們先來複現問題. eg:

@RequestMapping("/asynLogTrack")
public String asynLogTrack(){
logger.info("ces--------");
new Thread(new Runnable() {
@Override
public void run() {
logger.info("ces");
}
}).start();
return null;
}
[2019-05-10 16:55:18] [INFO ] [5b446567-97be-42f7-b6b0-205a6b431e87] [http-nio-8080-exec-2] [TestLogTrackController.java:21] [com.blacksearch.controller.TestLogTrackController] : ces--------
[2019-05-10 16:55:18] [INFO ] [traceId] [Thread-10] [TestLogTrackController.java:25] [com.blacksearch.controller.TestLogTrackController] : ces
[2019-05-10 16:55:18] [DEBUG] [5b446567-97be-42f7-b6b0-205a6b431e87] [http-nio-8080-exec-2] [AbstractMessageConverterMethodProcessor.java:298] [org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor] : Nothing to write: null body
複製程式碼

我們看到列印 ces 的列印記錄,我們發現，traceId居然丟失了!!! 原因在於,棧是執行緒私有,當我們新建執行緒的時候,新建的執行緒跟原來的執行緒互相獨立,也就是說logback無法在新建的執行緒上獲取到值。既然如何,那麼我們該如何讓Logback在新執行緒上獲取到值呢？正如標題而言。

public abstract class TrackRunnable implements Runnable {

public abstract void trackRun();

private String track = LogHandlerInterceptor.getTrack();

@Override
public void run() {
try {
LogHandlerInterceptor.setTrace(track);
trackRun();
}finally {
LogHandlerInterceptor.remove();
}
}
}
複製程式碼

我們採用抽象類實現 Runnable ,然後在 run() 方法裡面通過ThreadLocal去重新賦值。eg:

@RequestMapping("/asynLogTrackHasTrace")
public String asynLogTrackHasTrace(){
logger.info("ces1------");
new Thread(new TrackRunnable() {
@Override
public void trackRun() {
try {
Thread.sleep(4000);
} catch (InterruptedException e) {
e.printStackTrace();
}
logger.info("ces2-----------");
}
}).start();
return null;
}
[2019-05-10 17:07:20] [INFO ] [0a7f30d3-8e1d-49b4-9bca-4b72fd1c0ccd] [http-nio-8080-exec-5] [TestLogTrackController.java:33] [com.blacksearch.controller.TestLogTrackController] : ces1------
[2019-05-10 17:07:20] [DEBUG] [0a7f30d3-8e1d-49b4-9bca-4b72fd1c0ccd] [http-nio-8080-exec-5] [AbstractMessageConverterMethodProcessor.java:298] [org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor] : Nothing to write: null body
[2019-05-10 17:07:20] [DEBUG] [traceId] [http-nio-8080-exec-5] [FrameworkServlet.java:1130] [org.springframework.web.servlet.DispatcherServlet] : Completed 200 OK
[2019-05-10 17:07:24] [INFO ] [0a7f30d3-8e1d-49b4-9bca-4b72fd1c0ccd] [Thread-11] [TestLogTrackController.java:42] [com.blacksearch.controller.TestLogTrackController] : ces2-----------
複製程式碼

完美解決問題~ 以上程式碼已經上傳到同性交友網站~歡迎各位看官拍磚~

Logback日誌跨執行緒追蹤實踐

1. 自定義日誌模板引數：Logback的Pattern模板

2. 當我們使用多執行緒的時候,我們發現,原先定義的標識居然消失了！！！

您可能也會喜歡…