Logback日志跨线程追踪实践

Logback日志跨线程追踪实践

当咱们程序在服务器上面跑的时候,是否是不少时候很难定位问题? 当一大堆繁杂的日志文件丢给你的时候,你如何能从中定位到问题? 本项目源码已经上传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-----------
复制代码

完美解决问题~ 以上代码已经上传到同性交友网站~欢迎各位看官拍砖~