背景
最近线上的日志全局追踪 traceId 不好使了,不同请求经常出现重复的 traceId,或者通过某个请求的 traceId 追踪搜索,检索出了与该请求完全不相干的日志。我领导叫我去排查解决这个问题,这里我把我排查的过程思路以及如何解决这个问题稍微记录下。
全链路追踪原理:Spring web 的拦截器(HandlerInterceptor)+ 阿里的一个开源工具 (TransmittableThreadLocal 支持主线程到线程池的透传)+ feign 的 RequestInterceptor
排查过程
在排查日志之前,我经验告诉我,这大概率是 TTL 的 agent 代理与线上的 arm 监控代理冲突,导致线程池透传 traceId 没生效导致的(我以前也碰到过这类问题)
- 查看每个前端请求接口的日志打印,发现不同的请求确实存在重复的 traceId。
接着,我去看了下打印这行日志的实现,如下图,是通过一个 AOP 切面拦截所有的rest 请求去打印。其中,打印日志使用了线程池。
结论一:证实了我的猜测,线程池透传 traceId 没生效。也就是说,所有接口业务中使用到线程池的都可能会串 traceId。
-
当时我以为这就完了。在一次偶然的排查线上问题中发现,基本在同一时间,没有使用到线程池的两个业务接口,打印的日志的 traceId 是一样的。
我首先想到是,是不是接口请求接口没清除 traceId 呢,也就是没有重写 拦截器的 org.springframework.web.servlet.handler.HandlerInterceptorAdapter#afterCompletion 方法呢?
我去看一了下源代码,虽然没有重写afterCompletion() 方法在每次请求结束之后清除 traceId,但看 如上的preHandle()方法的代码逻辑,不清除也不要紧,如上代码所示,当在请求头中获取 traceId 不存在时会重新生成一个 traceId。
初步猜测:
1)IdWorker 生成的随机id重复了?
不太可能吧,IdWorker 用的是雪花算法啊,尽管在同一毫秒,并发量不高的话也不会生成重复的…
2) IdWorker 非单例的原因?
结论二:短时间内,存在 IdWorker 生成了重复的 traceId。
解决方案
-
关于第一个线程池透传 traceId 没生效问题。主要有两个原因:
1.1 项目压根就没有对线程池做 TTL 的包装增强(也就是项目启动参数没有加上 TTL 的 agent 方式代理),需要把参数给加上。
-javaagent:D:\AAA_pengyu\respository\com\alibaba\transmittable-thread-local\2.11.5\transmittable-thread-local-2.11.5.jar
1.2 实际上,尽管在所有项目把 TTL 的 agent 方式代理启动参数家加上也还是会失效的。前面说了,TTL 的 agent 代理与线上的 arm 监控代理冲突。
针对和阿里云的沟通,修改方案如下:
-
关于 IdWorker 生成了重复的 traceId。
在测试调整过程中,我把IdWorker 改成单例模式之后,也还是会存在 id重复问题。
原因是构造 IdWorker 时 workerId,datacenterId,sequence 都为同一个字符串的原因,IdWorker 生成的 随机id 是依赖这三个参数。
所以不同服务根据当前机器ip、mac 等参数动态生成就好了
最后,经过如上的修改之后,公司的全链路日志追踪就好了。