1. 现场还原一条不该重复的 traceId把三套服务搅在了一起事情是这样的晚上 10 点 37 分报警群突然开始刷屏核心交易链路的 ERROR 日志一小时涨了 3 倍。我点开日志平台按错误关键字刷了一遍发现排在前面的一百多条日志traceId 一模一样全是134123123。第一反应是日志平台的分片索引坏了第二反应是哪个同事在测试环境里写死了 traceId第三反应才是——坏了这看着像生产数据。为了不暴露真实业务信息下面我把所有出问题的 traceId 统一脱敏成134123123来讲实际场景里它比这串数字更长、也没这么整齐。但现象本身是很明确的一条本该全局唯一的请求追踪编号在大量互不相关的请求里反复出现。在分布式链路追踪的排障体系里traceId 相当于快递单号。你把单号往查询框里一贴就能看到这个包裹从下单到签收的所有节点的处理记录。现在倒好几百个不同用户的订单打的却是同一个快递单号你想查其中任何一笔订单的时候系统把所有订单的日志全吐给你。这已经不是难排查的问题了是根本没法排查。先说日志长什么样。我们的应用是 Java 技术栈日志框架用的 Logback输出格式里统一带了一个[traceId]字段。正常情况下一条下单日志长这样[INFO ] [134123123] [order-service] [createOrder:123456] 订单创建成功, userId7890这个 traceId 在每个请求进来时生成整个调用链路上所有服务都往日志里带上同一个编号。排查问题的时候只需要拿到其中一个 traceId就能把入口网关、订单服务、库存服务、支付回调的日志全部串成一条线。可事故当天我在日志平台上搜134123123返回的结果总条数超过 40 万。这些日志的时间跨度横跨三个小时涉及 userId 各不相同下单的商品也是五花八门。它们唯一的共同点就是 traceId 都等于134123123。这在分布式系统里几乎是一个不可能事件。哪怕 ID 生成算法弱一点撞上相同 traceId 的概率也微乎其微。所以当我第一时间看到这个结果脑子里闪过的三个可能性是日志平台的 IK 分词把字段切错导致误展示、应用里有人手动改了 MDC 的值、或者上游某个系统在传递过程中偷偷把 traceId 替换掉了。排查方向基本都朝这几个地方去了。2. 从日志重复到请求头里写死完整定位过程2.1 先确认 traceId 是从哪一层进来的排查链路追踪类的问题第一步永远是搞清楚 traceId 的出生地。我在日志平台里随机挑了两条134123123的日志一条来自网关 access log一条来自订单服务。网关那一条的日志时间比订单服务早了大概 200 毫秒这意味着 traceId 是从网关注入并往下游传递的。我们当时的网关是基于 Spring Cloud Gateway 改造的在 WebFilter 里做了一层 MDC 注入。逻辑大致是优先读取 HTTP 请求头里的X-Request-Id如果请求头有值就用这个值作为 traceId如果没有再调用UUID.randomUUID().toString().replace(-, )新生成一个。这份代码已经在线上跑了两年多平时也没出过幺蛾子。照这个逻辑只要请求头里没有携带X-Request-Id每个请求都应该拿到不同的 traceId。为了验证是不是代码在某种并发情况下生成了重复 ID我把这一段过滤器代码翻出来反复看。UUID.randomUUID()在 Java 里用的是 SecureRandom重复概率低到可以忽略。而且就算真的重复了也不至于连续三个小时、四十万条日志全都重复同一个值。唯一合理的解释是上游确实给每一个请求都带了一个固定的X-Request-Id: 134123123。2.2 抓入口请求固定值的来源浮出水面接下来要做的就很直接了到生产网关前面抓头。我们有一个旁路的流量镜像口我直接开 tcpdump 抓了 30 秒过滤条件是tcp port 443然后从包里看 HTTP 请求头。不抓不知道一抓吓一跳我扒了前 20 个请求不管是 POST 还是 GET每个请求的X-Request-Id都是同一个值134123123。这个特征太明显了。如果是某个 SDK 自动生成的不可能所有客户端、所有请求都生成同一个值如果是中间网络设备伪造的那大多数请求的该字段应该时而存在、时而不存在。现在这个表现只有一种可能客户端侧的代码或者网关前置的某个代理层把X-Request-Id写死成了一个常量。我顺着调用链往下问上游系统是另一条业务线的应用他们最近一周刚好做了一个统一请求头规范化的升级。负责的同事看了代码后也很震惊在工具类里有一行httpHeaders.set(X-Request-Id, 134123123)。这行代码原本是一个脱敏测试占位符开发时用来模拟固定 requestId 方便本地联调。结果代码评审漏了流水线也通过了直接跟着常规版本发布到了生产环境。于是所有经过上游系统转发的请求都乖乖带着这个写死的 traceId 继续往下游走。2.3 为什么 APM 链路拓扑图一切正常这里有一个让我觉得特别值得写出来的教训事故期间我们的 APM 系统并没有报警。查看链路追踪平台上的拓扑图服务节点之间的调用关系完全正常延迟曲线也没有明显波动。因为这个固定 traceId 并不影响 RPC 调用的物理链路APM 自己内部使用的 traceId 是另外一套逻辑不会复用X-Request-Id。只有当日志平台按业务 traceId 检索时才会发现数据全部串在一起。这给我们提了一个醒监控体系里链路追踪不报警不代表日志追踪没问题。traceId 是否重复这件事常规 APM 根本感知不到。我需要单独写一个定时任务扫描日志平台里同一 traceId 在不同 userId 和时间戳下出现的次数超过阈值就告警。这套逻辑以前一直没做因为大家都默认traceId 肯定不会重复。实际上在一条链路上只要有一个节点做了一次写死的赋值这个默认的假设就会被击穿。2.4 为什么三个小时内没人第一时间发现还有一个问题值得复盘四十万条日志持续写入三个小时为什么没有业务方的人最先发现原因是大部分开发和运维查问题的时候都是先用userId或者订单号去关联日志很少有人会直接用 traceId 反查。真正引爆问题的是当天晚上的一个线上告警某个商品的库存扣减失败率突然升高。值班同事想通过 traceId 拉全链路日志时发现一个 traceId 拉出来的全是无关请求这才意识到追踪系统已经失效。所以在事故复盘时我把这个点专门列了一条可观测性的质量不只是日志有没有、埋点够不够还包括标识是否唯一、检索是否可信。一个看似简单的 traceId一旦污染整个排障链条上的所有工具都会失去参考价值。3. 修复方案把头里塞固定值改成没有值就现场生成3.1 需要改的三个位置根因清楚了修复就不难。但要注意这次事故暴露出来的问题不止是上游那一行写死的代码还包括我们自己系统里几个经不起推敲的信任。第一处改动在上游系统。把httpHeaders.set(X-Request-Id, 134123123)这行硬编码直接删掉改成从原始请求中透传没有值就让它为空。这个逻辑其实是大多数 HTTP 网关默认的做法X-Request-Id本身属于可选请求头不应该由转发节点主动补默认值。第二处改动在我们自己的网关。原来的逻辑是优先用请求头里的值没有才生成。在排障场景这没什么问题但结合这次事故来看这个逻辑没有防呆保护。我加了一个校验如果请求头里的值明显不符合 traceId 的格式规范比如长度不足、包含非法字符、或者是像0、1这种连续重复的极简序列就丢弃它并重新生成。这种防御性写法会增加一点点的 CPU 开销但换来的是整个链路不会被脏数据污染。第三处改动是排查期间临时加的逃生通道。我们在网关过滤器里预设了一个配置项可以从配置中心动态关闭透传 X-Request-Id的能力强制所有请求走重新生成的逻辑。这样即使上游再次出现类似的脏数据我们不需要发版就能先止血。// 网关过滤器中的核心逻辑示意代码已脱敏 String requestId request.getHeaders().getFirst(X-Request-Id); if (isValidTraceId(requestId)) { traceId requestId; } else { traceId generateTraceId(); } // 生成后写入 MDC同时把透传开关也考虑进去3.2 去掉硬编码之后还要处理 MDC 的线程池污染事情到这一步其实只解决了一半。真正让我懊恼的是后面这个问题修完上游写死 traceId 后我随机抽样生产日志发现仍然有小部分日志的 traceId 是134123123。按常理说源头断掉了新的日志不应该再出现这个值。查下去才发现是我们自身应用的线程池复用了旧的 MDC 数据。Java 服务里大量使用线程池处理异步任务而 MDC 是绑定在线程私有的 ThreadLocal 上的。如果在线程池执行完任务后没有清理 MDC那么同一个线程下一次被复用的时候就会带着上一次任务的 traceId 去打日志。这就是经典的 traceId 串号问题。我最后在异步任务执行器的包装逻辑里统一加了 MDC 清理和恢复。核心思想是任务执行前把父线程的 MDC 快照设置到子线程任务执行完毕后无论是否抛异常都要调用MDC.clear()。同时把ThreadPoolTaskExecutor的TaskDecorator也补上了。这个过程不复杂但它是一个和上游写死完全不同维度的坑。如果你不在上线前专门去压测异步场景根本发现不了。3.3 上线后的验证清单修复代码发完我没有直接宣布完成而是按下面这份清单逐项验证上游系统新代码上线后tcpdump 再抓一次头确认新请求的X-Request-Id不再固定为134123123。网关侧触发一条测试下单观察日志平台上生成的 traceId 是否每笔交易都不同。在订单服务和库存服务各挑 20 个新生成的 traceId分别检索确认每个 traceId 下能且只能拉出对应链路的日志。运行异步任务压测脚本观察同一线程池异步任务打出的 traceId 是否与请求上下文一一对应。观察配置中心开关热生效后的效果确认不需要重启就能切换 traceId 的透传/生成模式。这份清单用了大概一个小时跑完。同步也做了一轮历史脏数据治理把之前三个小时内产生的四十万条134123123日志在日志平台上打了一个批量迁移标记从新的检索逻辑里排除掉。这些日志本身还要保留用于事后审计但不能继续干扰正常检索。3.4 监控补齐让重复 traceId能被自动发现整个修复做完我不太想只是靠运气避免下一次发生。这类问题最可怕的是潜伏期它可能连续跑了一两周都没人关注直到某次真正需要排障时才发现检索不可用。所以我给日志平台配了一个定时巡检任务每分钟统计一次同一个 traceId 在最近 5 分钟内出现的日志条数如果超过 100 条就触发告警。这个阈值需要根据流量动态调。对高并发系统来说一个热门的 traceId 下面可能天然会有几十条日志比如大促活动秒杀某个用户批量下单。但正常情况下不应该出现同一个 traceId 关联到几百个不同 userId 的情况。所以巡检任务不能只看日志条数还要看 distinct userId 的数量。如果count(distinct userId) 50基本就可以断定 traceId 出现污染了。另外我在网关的日志输出里额外加了一个traceIdSource字段记录当前 traceId 是上游透传还是本级生成。有了这个字段未来再出现类似问题一眼就能看出污染是从入口进来的还是本地生成的逻辑有 bug。这是一件非常小的事但在排查效率上的提升是肉眼可见的。4. 从这次事故里反推出来的 traceId 设计原则4.1 全局唯一不能靠概率安全很多分布式系统在设计 traceId 时默认采用概率上近似唯一的方案。比如 32 位随机 UUID、雪花算法生成的 64 位 ID这些都是默认选项。概率不出错不代表全链路不会出错。因为这条链路上任何一环都有能力覆盖掉你原本生成的 traceId。上游系统写一个固定值你作为下游根本不知道。真正的全局唯一性靠的不是生成算法而是链路上所有系统的共同约定。我在复盘时给团队定了一个原则对于X-Request-Id这类请求头中间层默认只透传不生成不覆盖。只有系统入口处才有资格决定是否需要创建一个新 ID。每一个转发节点都要像一个没有感情的快递分拣员只看单号、不换单号哪怕这个单号在你看来长得再奇怪你也只能在面单上补充备注不能撕掉重贴。这个类比贴到代码里就是中间网关不要自作聪明地给请求补 traceId。4.2 上下文传递的默认行为决定了日志的成败这次事故有一半的锅要扣在隐式传递头上。Java 的 MDC 本身是一个隐式的上下文容器它靠着 ThreadLocal 在线程内部默默传递。这个机制非常便利但也非常脆弱。只要有一个异步线程池忘记清理 MDCtraceId 就会串线只要有一个 RPC 框架没有把 traceId 放到请求头里跨服务追踪就会断掉只要有一次消息队列消费时忘了从消息头里恢复 traceId异步消费者打出来的日志就成了孤儿。我在复盘文档里把全公司所有 middleware 的 traceId 传递方式全都捋了一遍竟然发现有三种框架在各自为政有的用X-Request-Id有的用trace_id有一个老系统甚至用的是reqId。它们之间没有统一转换逻辑全靠各业务系统自己在代码里适配。每次跳过一个 dubbo 调用traceId 就可能换一茬。你可以想象一下一票到底的快递模式到了我们系统里就变成了每到一站就要换一张新面单这还能追出什么线索来因为这次事故我们牵头做了一个统一的 traceId 上下文规范对外统一读取和写入X-Request-Id内部框架在跨服务调用时自动透传。业务代码一律不允许直接操作 MDC也不允许手动 set traceId。要用就通过框架提供的 API 来尽量把上下文传递变成一件无感知的事。4.3 代码里千万不要自己拼 traceId还有一个让我比较恼火的点是代码评审的时候居然没人在意一行写死的X-Request-Id常量。这里我想对所有团队说一句凡是出现在业务代码里的 traceId 赋值都需要像审查普通 SQL 一样严格。我后来做了一个小工具在 CI 流水线里做正则扫描匹配set.*X-Request-Id、put.*traceId这类写法只要命中的代码一律需要人工二次确认才允许合入。这确实会给开发流程带来一点摩擦但和事故排查成本比起来这点摩擦完全值得。实际生产环境里绝不缺这种临时写死的代码。开发阶段为了联调方便设置固定值理论上到了发布前应该删掉但一忙起来就忘。更糟的是有些框架会直接读取一个环境变量作为 traceId如果这个环境变量在 Docker 镜像里被配置成了静态字符串那整个环境的所有请求就全军覆没了。4.4 排查该类问题我留下的三条经验最后说说我在这次事故里沉淀下来的三条经验。第一条看到诡异的 traceId 重复不要先去怀疑生成算法先看链路入口和中间传递。绝大多数重复问题都出在有人主动赋值或者配置被固定而不是随机算法真的撞车了。拿着日志平台的截图去问上游你们是不是把 X-Request-Id 写死了往往比对着自己代码猜半天更高效。第二条修完源头之后一定要去查历史日志里是否存在持续写入的脏 traceId。这类问题不会因为源头修复就立刻消失因为已经写入日志平台的数据还在。如果之后排查其他问题时误用了这些脏 traceId你会被带到另一个完全不相干的请求链路里白白浪费几个小时。第三条可观测性基础设施一定要有自检能力。过去我们总认为 traceId 是底层机制天然可信不会出问题。但事实是只要有人的参与机器就会被人配置出奇怪的行为。给日志平台加一个traceId 唯一性巡检的定时任务相当于给追踪系统本身也上了监控。这个投入非常小但它是让整个可观测性体系从看起来能用变成真的经得起事故考验的关键一步。事后我开玩笑说以后谁再在业务代码里写死X-Request-Id就让谁用这个固定 ID 去日志平台翻一天日志保证记忆深刻。这当然是玩笑话但这个小小的字段确确实实是整个分布式系统排查效率的生命线。希望你们不要再踩同样的坑。