如何快速过滤出一次请求的所有日志?
关于日志链路追踪,之前在.net项目和java项目里有过不同的最佳实践。见下面链接。
▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志
▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(续)
▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(完结篇)
▄︻┻┳═一asp.net拦截器
▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(java-logback篇)
本文呢,还是java项目,这次用AOP来实现。
至于为什么要改threadName,为什么要用AOP,就不再铺垫赘述了。Talk is cheap, show me the code。下面代码可以直接使用,拿走不谢。
package com.aop;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;
import java.util.Random;
/**
* 【日志链路追踪】重置工作线程名为唯一字符串,
* 这样在生产排障时,可以快速过滤一次请求的所有日志
*/
@Slf4j
@Component
@Aspect
public class WorkThreadNameAspect {
@Pointcut("execution(public * com.clz.*.*(..))")
public void pointCut() {
}
ThreadLocal<String> threadLocal = new ThreadLocal<>();
// @Before("pointCut()")
// public void before(JoinPoint joinPoint) {
public void setThreadName(JoinPoint joinPoint) {
// if (Thread.currentThread().getName().contains("-")) {
String threadNameFlag = getMethodSignature(joinPoint);
String before = Thread.currentThread().getName();
String s = threadLocal.get();
if (threadLocal.get() == null) {
String threadName = threadNameFlag + System.currentTimeMillis() + "_" + new Random().nextInt(1000);
threadLocal.set(threadName);
Thread.currentThread().setName(threadName);
}
log.debug("threadName={}→→→{}, threadLocal.get()={}→→→{}", before, Thread.currentThread().getName(), s, threadLocal.get());
// }
}
String getMethodSignature(JoinPoint joinPoint) {
return joinPoint.getSignature().getDeclaringType().getSimpleName() + "_" + joinPoint.getSignature().getName();
}
@After("pointCut()")
public void after(JoinPoint joinPoint) {
String threadNameFlag = getMethodSignature(joinPoint);
if (threadLocal.get() != null && threadLocal.get().contains(threadNameFlag)) {
log.debug("remove name {}", Thread.currentThread().getName());
threadLocal.remove();
}
}
@Around("pointCut()")
public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
setThreadName(joinPoint);
long start = System.currentTimeMillis();
try {
return joinPoint.proceed(joinPoint.getArgs());
} finally {
log.info("{} duration=执行耗时={}ms", getMethodSignature(joinPoint),
System.currentTimeMillis() - start);
}
}
}
注意,aspectj里各个advice的执行顺序,Around advice是先于Before advice的,所以设置线程名要在@Around注解的方法里来执行。下图是advice的执行顺序。
好了。如下多线程模拟并发来测试,从运行结果可以看出,想定位某一次请求的日志,就方便多了。
package com.clz;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.junit.runner.RunWith;import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringRunner;
import java.util.concurrent.LinkedBlockingDeque;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;
@Slf4j
@SpringBootTest
@RunWith(SpringRunner.class)
class AOPTest {
@Autowired
private Class1 class1;
@Test
public void testWorkThreadName() throws InterruptedException {
class1.test();
Thread.currentThread().setName("mmmmmmmm");
log.info("异步多线程测试");
ThreadPoolExecutor poolExecutor = new ThreadPoolExecutor(5, 5, 10, TimeUnit.MILLISECONDS, new LinkedBlockingDeque<>(5));
Thread.sleep(5);
for (int i = 0; i < 2; i++) {
poolExecutor.execute(() -> {
class1.test();
// csdfsdafdsfdsfdsf.test();
});
}
poolExecutor.shutdown();
poolExecutor.awaitTermination(2, TimeUnit.SECONDS);
}
}
如下是执行结果。
那么,有了这个重置线程名的切面以后,当我们在linux服务器上定位log时,实现了slf4j-api的日志框架,不管是log4j/log4j2,还是logback,只要每条日志的前缀携带线程名(默认是有的,见pattern标识符%t或%thread),直接grep某次请求的唯一线程名,就可以看到程序处理本次请求的所有日志了。