Logback日誌跨線程追蹤實踐

Logback日誌跨線程追蹤實踐

當咱們程序在服務器上面跑的時候,是否是不少時候很難定位問題? 當一大堆繁雜的日誌文件丟給你的時候,你如何能從中定位到問題? 本項目源碼已經上傳Github: https://github.com/liushunqiu/log-track

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-----------

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