拓十年匠心定制 · 商业建站与技术教学双线并行 咨询热线:400-886-1026 service@lmnt.cn
ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

traceId写死引发日志串线:分布式链路追踪故障深度复盘

traceId写死引发日志串线:分布式链路追踪故障深度复盘

1. 现场还原:一条"不该重复"的 traceId,把三套服务搅在了一起

事情是这样的,晚上 10 点 37 分,报警群突然开始刷屏:核心交易链路的 ERROR 日志一小时涨了 3 倍。我点开日志平台,按错误关键字刷了一遍,发现排在前面的一百多条日志,traceId 一模一样,全是134123123。第一反应是日志平台的分片索引坏了,第二反应是哪个同事在测试环境里写死了 traceId,第三反应才是——坏了,这看着像生产数据。

为了不暴露真实业务信息,下面我把所有出问题的 traceId 统一脱敏成134123123来讲,实际场景里它比这串数字更长、也没这么整齐。但现象本身是很明确的:一条本该全局唯一的请求追踪编号,在大量互不相关的请求里反复出现。在分布式链路追踪的排障体系里,traceId 相当于快递单号。你把单号往查询框里一贴,就能看到这个包裹从下单到签收的所有节点的处理记录。现在倒好,几百个不同用户的订单,打的却是同一个快递单号,你想查其中任何一笔订单的时候,系统把所有订单的日志全吐给你。这已经不是难排查的问题了,是根本没法排查。

先说日志长什么样。我们的应用是 Java 技术栈,日志框架用的 Logback,输出格式里统一带了一个[traceId]字段。正常情况下一条下单日志长这样:

[INFO ] [134123123] [order-service] [createOrder:123456] 订单创建成功, userId=7890

这个 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 在线程内部默默传递。这个机制非常便利,但也非常脆弱。只要有一个异步线程池忘记清理 MDC,traceId 就会串线;只要有一个 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 去日志平台翻一天日志,保证记忆深刻。这当然是玩笑话,但这个小小的字段,确确实实是整个分布式系统排查效率的生命线。希望你们不要再踩同样的坑。

返回列表