全链路日志追踪

背景

最近线上的日志全局追踪 traceId 不好使了，不同请求经常出现重复的 traceId，或者通过某个请求的 traceId 追踪搜索，检索出了与该请求完全不相干的日志。我领导叫我去排查解决这个问题，这里我把我排查的过程思路以及如何解决这个问题稍微记录下。

全链路追踪原理：Spring web 的拦截器（HandlerInterceptor）+ 阿里的一个开源工具 （TransmittableThreadLocal 支持主线程到线程池的透传）+ feign 的 RequestInterceptor

排查过程

在排查日志之前，我经验告诉我，这大概率是 TTL 的 agent 代理与线上的 arm 监控代理冲突，导致线程池透传 traceId 没生效导致的（我以前也碰到过这类问题）

1. 查看每个前端请求接口的日志打印，发现不同的请求确实存在重复的 traceId。

接着，我去看了下打印这行日志的实现，如下图，是通过一个 AOP 切面拦截所有的rest 请求去打印。其中，打印日志使用了线程池。

结论一：证实了我的猜测，线程池透传 traceId 没生效。也就是说，所有接口业务中使用到线程池的都可能会串 traceId。

2. 当时我以为这就完了。在一次偶然的排查线上问题中发现，基本在同一时间，没有使用到线程池的两个业务接口，打印的日志的 traceId 是一样的。

   我首先想到是，是不是接口请求接口没清除 traceId 呢，也就是没有重写 拦截器的 org.springframework.web.servlet.handler.HandlerInterceptorAdapter#afterCompletion 方法呢？

   

   我去看一了下源代码，虽然没有重写afterCompletion() 方法在每次请求结束之后清除 traceId，但看 如上的preHandle()方法的代码逻辑，不清除也不要紧，如上代码所示，当在请求头中获取 traceId 不存在时会重新生成一个 traceId。

   初步猜测：

   1）IdWorker 生成的随机id重复了？

   不太可能吧，IdWorker 用的是雪花算法啊，尽管在同一毫秒，并发量不高的话也不会生成重复的…

   2） IdWorker 非单例的原因？

结论二：短时间内，存在 IdWorker 生成了重复的 traceId。

解决方案

1. 关于第一个线程池透传 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 监控代理冲突。

   针对和阿里云的沟通，修改方案如下：

   

2. 关于 IdWorker 生成了重复的 traceId。

   在测试调整过程中，我把IdWorker 改成单例模式之后，也还是会存在 id重复问题。

   原因是构造 IdWorker 时 workerId，datacenterId，sequence 都为同一个字符串的原因，IdWorker 生成的 随机id 是依赖这三个参数。

   所以不同服务根据当前机器ip、mac 等参数动态生成就好了

最后，经过如上的修改之后，公司的全链路日志追踪就好了。