PS:本文只贴出核心代码,完整代码在文末可以自行下载
出现故障时,我们经常需要获取一次请求流程里的所有日志进行定位。
如果请求只在一个线程里处理,则我们可以通过线程ID来过滤日志,但如果请求包含异步线程的处理,那么光靠线程ID就显得捉襟见肘了。
典型的例子是 Web 应用服务器。当用户访问某个页面时,应用服务器可能会创建一个新的线程来处理该请求,也可能从线程池中复用已有的线程。在一个用户的会话存续期间,可能有多个线程处理过该用户的请求。这使得比较难以区分不同用户所对应的日志。当需要追踪某个用户在系统中的相关日志记录时,就会变得很麻烦。
由于这个逻辑之间没有强耦合的关系,所以通常是异步处理。如何将一次数据上报请求中包含的所有业务日志快速过滤出来,就是本文要介绍的。
1.SLF4J—MDC
SLF4J日志框架提供了一个MDC(Mapped Diagnostic Contexts)工具类,谷歌翻译为映射的诊断上下文,是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。
在一个用户的会话存续期间,可能有多个线程处理过该用户的请求。这使得比较难以区分不同用户所对应的日志。当需要追踪某个用户在系统中的相关日志记录时,就会变得很麻烦。
一种解决的办法是采用自定义的日志格式,把用户的信息采用某种方式编码在日志记录中。这种方式的问题在于要求在每个使用日志记录器的类中,都可以访问到用户相关的信息。这样才可能在记录日志时使用。这样的条件通常是比较难以满足的。MDC 的作用是解决这个问题。
MDC 可以看成是一个与当前线程绑定的哈希表,可以往其中添加键值对。
MDC 中包含的内容可以被同一线程中执行的代码所访问。
当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时,只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说,通常是在请求被处理的最开始保存这些数据。
2.使用案例
相对比较大的项目来说,一般会有多个开发人员,如果每个开发人员凭自己的理解打印日志,那么当用户反馈问题时,很难通过日志去快速的定位到出错原因,也会消耗更多的时间。
所以针对这种问题,一般会定义好整个项目的日志格式,如果是需要追踪的日志,开发人员调用统一的打印方法,在日志配置文件里面定义好相应的字段,通过MDC功能就能很好的解决问题。
比如我们可以事先把用户的sessionId,登录用户的用户名,访问的城市id,当前访问商户id等信息定义成字段,线程开始时把值放入MDC里面,后续在其他地方就能直接使用,无需再去设置了。
使用MDC来记录日志,一来可以规范多开发下日志格式的一致性,二来可以为后续使用ELK对日志进行分析。
下面我们进行一些简单的实战
首先我们需要配置日志的输出格式以及需要输出的信息,通过在log4j2.xml进行设置
追踪日志自定义格式主要在name="trance"的layout里面进行设置,我们使用%X{userName}来定义此处会打印MDC里面key为userName的value,如果所定义的字段在MDC不存在对应的key,那么将不会打印,会留一个占位符。
<property name="log_pattern">%d{yyyy-MM-dd HH:mm:ss.SSS} [%level] -%X{filter} <%t|%C{1.}.%M(%L)> -%X{requestId} %m%n%ex</property>
因为我们使用的是log4j日志,所以我们需要禁用掉SpringBoot自身所使用的日志
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
<exclusions><!-- 去掉springboot默认配置 -->
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
<!-- 引入log4j2依赖 -->
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
同时需要在配置文件中进行指定日志的配置文件
# 配置日志信息
logging.config=classpath:log4j2.xml
下面简单写个接口测试一下
@Slf4j
@RestController
public class TestController {
private static final String KEY = "requestId";
@GetMapping("test")
public String test() {
// 入口传入请求ID
MDC.put(KEY, "key-" + UUID.randomUUID().toString()); // 打印日志
log.info("log in main thread 1");
log.info("log in main thread 2");
log.info("log in main thread 3");
// 出口移除请求ID
MDC.remove(KEY);
return "测试";
}
}
效果如上图所示
从日志中可以明显地看到中(映射的)请求ID(requestId),这其实就是我们定位(诊断)问题的关键字(上下文) 。
有了MDC工具,只要在接口或切面植入put()和remove()代码,在现网定位问题时,我们就可以通过grep requestId=xxx *.log快速的过滤出某次请求的所有日志。
一定不要忘记在最后添加remove()指令,否则有可能会导致内存泄漏。
我简单说一下linux命令中的grep命令:
3.grep命令
grep 命令用于查找文件里符合条件的字符串。
日志文件太大无法直接 cat 查看,可以用grep
常用参数:
- -A<显示行数> : 除了显示符合范本样式的那一列之外,并显示该行之后的内容。
- -C<显示行数> : 除了显示符合样式的那一行之外,并显示该行之前后的内容。
- -E : 将样式为延伸的正则表达式来使用。
eg:
查询 包含 trainSegment/detail 的字符串的前后10行
grep -C 10 trainSegment/detail webapi-info-VM-130-116-centos.log
正则
grep -E -C 30 "keyword1.* keyword2.* " webapi-info-VM-130-116-centos.log
4.MDC在异步线程中的应用
然而,MDC工具真的有我们所想的这么方便吗?回到我们开头,一次请求可能涉及多线程异步处理,那么在多线程异步的场景下,它是否还能正常运作呢?
下面通过简单实验来看一下在异步线程里的运行结果
@GetMapping("test2")
public String test2() {
// 入口传入请求ID
MDC.put(KEY, "key-" + UUID.randomUUID().toString());
// 打印日志
log.info("log in main thread");
// 异步线程打印
new Thread(new Runnable() {
@Override
public void run() {
log.info("log in other thread");
}
}).start();
// 出口移除请求ID
MDC.remove(KEY);
return "测试";
}
代码里我们新起了一个异步线程,并在匿名对象Runnable的run()方法打印日志。运行main函数,可以在控制台看到以下日志输出:
不幸的是,请求ID在异步线程里不打印了。这是怎么回事呢?
要解决这个问题,我们就得知道MDC的实现原理。由于篇幅有限,这里就暂不详细介绍,MDC之所以在异步线程中不生效是因为底层采用ThreadLocal 作为数据结构,我们调用MDC.put()方法传入的请求ID只在当前线程有效。
知道了原理那么解决这个问题就轻而易举了,我们可以使用装饰器模式,新写一个MDCRunnable类对Runnable接口进行一层装饰。
在创建MDCRunnable类时保存当前线程的MDC值,在执行run()方法时再将保存的MDC值拷贝到异步线程中去。
代码实现如下:
public class MDCRunnable implements Runnable {
private final Runnable runnable;
private final Map<String, String> map;
public MDCRunnable(Runnable runnable) {
this.runnable = runnable;
// 保存当前线程的MDC值
this.map = MDC.getCopyOfContextMap();
}
@Override
public void run() {
// 传入已保存的MDC值
for (Map.Entry<String, String> entry : map.entrySet()) {
MDC.put(entry.getKey(), entry.getValue());
}
// 装饰器模式,执行run方法
runnable.run();
// 移除已保存的MDC值
for (Map.Entry<String, String> entry : map.entrySet()) {
MDC.remove(entry.getKey());
}
}
}
接着,我们需要对函数里创建的Runnable实现类进行装饰:
@GetMapping("test3")
public String test3() {
// 入口传入请求ID
MDC.put(KEY, "key-" + UUID.randomUUID().toString());
// 主线程打印日志
log.info("log in main thread");
// 异步线程打印日志,用MDCRunnable装饰Runnable
new Thread(new MDCRunnable(new Runnable() {
@Override
public void run() {
log.info("log in other thread");
}
})).start();
// 出口移除请求ID
MDC.remove(KEY);
return "测试";
}
可以看到异步线程里也可以打印出MDC的key的信息了。
5.通过AOP植入requestId
添加依赖
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
切面代码如下:
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import java.util.UUID;
@Aspect
@Component
@Slf4j
@Order(-10)
public class ControllerRequestIdAspect {
@Pointcut("execution(public * com.example.demo.controller..*.*(..))")
public void controllerPoint() {
}
@Around("controllerPoint()")
public Object doControllerPointAround(ProceedingJoinPoint joinPoint) throws Throwable {
String requestId = UUID.randomUUID().toString();
MDC.put("requestId", requestId);
Object result = null;
try {
result = joinPoint.proceed();
} finally {
MDC.remove("requestId");
}
return result;
}
}
5.总结
本文讲述了如何使用MDC工具来快速过滤一次请求的所有日志,并通过装饰器模式使得MDC工具在异步线程里也能生效。
有了MDC,再通过AOP技术对所有的切面植入requestId,就可以将整个系统的任意流程的日志过滤出来。
使用MDC工具,在开发自测阶段,可以极大地节省定位问题的时间,提升开发效率;在运维维护阶段,可以快速地收集相关日志信息,加快分析速度。
git地址:https://gitee.com/ninesuntec/filter-the-log-of-the-request.git