TT Lab
开始
学习 学习路径 课程

从日志里找原因

一笔订单不见了,而服务有五个

在 TT Lab 中继续学习

目标

在五个服务的日志中,把一个订单的路径从头到尾串起来。把 W3C traceparent 拆成四段并隔离无效的值,把同一个 trace-id 的日志行按时间排好,用 parent-id 建立跨度树,求出各跨度的耗时,用业务键把头部断掉的位置接上,然后用掩码读取 sampled 标志。

为什么重要

客户说“一个订单不见了”,而服务有五个。如果凭时间去猜,在每秒几十个请求中,没有依据来挑出哪一个是那个订单。关联 id 能填补这个空缺,但现场真正碰到的问题不是没有 id,而是 id 在中间某一处断掉。找出断掉的位置,并用业务键把它前后重新接起来加以证明,这才是完整的调查。这个证明就是促使下次部署传递头部的依据。

步骤

  1. 创建并运行 /root/trace/gen_trace.py,在 /root/trace/raw/ 下生成五个服务的日志。
  2. /root/trace/parsed.ndjson 和 /root/trace/badtp.ndjson——把所有 traceparent 拆成四段,把不符合规范的值连同原因隔离起来。
  3. /root/trace/one_trace.ndjson——找到订单 ORD-2026-4117 的 trace-id,把该跟踪的所有日志行按时间排好。
  4. /root/trace/tree.ndjson——用 parent-id 建立父子关系,做出跨度树。
  5. /root/trace/elapsed.json——求出各跨度的耗时和自身耗时。
  6. /root/trace/bridge.ndjson 和 /root/trace/gap.json——找到头部断掉的服务,用订单号把它前后接起来。
  7. /root/trace/sampled.json——用掩码读取 sampled 标志,区分被记录的跟踪和没有被记录的跟踪。
  8. /root/trace/trace_report.md——把调查结果写成报告。

参考

拿到五个服务的日志

创建并运行 /root/trace/gen_trace.py,在 /root/trace/raw/ 下生成 edge.jsonl(58 行)、orders.jsonl(72 行)、payments.jsonl(48 行)、stock.jsonl(48 行)、ledger.jsonl(48 行)。

五个文件都是每行一个 JSON 对象(JSON Lines)。大多数行都带有 traceparent_in 和 traceparent_out,但有一个服务的行一条也没有——这个服务就是本实验的主角。edge 中还混有健康检查行,以及旧的移动网关打出的错误头部。

把 traceparent 拆成四段

在 /root/trace/parsed.ndjson 中,为每个符合规范的 traceparent,按 svc、line_no(从 1 开始)、field(traceparent_in|traceparent_out)、version、trace_id、parent_id、trace_flags 每行写一条。不符合规范的值,以 svc、line_no、field、raw(原文原样)、reason 的形式保存到 /root/trace/badtp.ndjson。

材料是第 1 步在 /root/trace/raw/ 下生成的全部五个文件。traceparent 是定长的——用连字符分开的四段,长度依次是 2、32、16、2,字符只允许小写十六进制。reason 请按说明中规定的检查顺序附上。读取文件时,行号要在原始文件中从 1 开始计数,完全没有 traceparent 的行,哪一边都不放。

把那个订单的跟踪按时间排好

客户所说的订单是 ORD-2026-4117。在 edge 日志中找到该订单的 traceparent,得到 trace-id,然后在 /root/trace/one_trace.ndjson 中,把带有这个 trace-id 的所有行,按 ts、svc、trace_id、span_id、parent_span_id、msg 以 ts 升序写入。span_id 是该行 traceparent_out 的 parent-id,parent_span_id 是 traceparent_in 的 parent-id(没有则为空字符串)。

材料是 /root/trace/raw/ 下的五个文件。trace-id 指向整个跟踪,parent-id 指向一个请求。所以收集的依据是 trace-id。这是一个有五个服务参与的订单,请数一数这里出现了几个服务——这个数字就是本实验的问题所在。

用 parent-id 建立跨度树

在 /root/trace/tree.ndjson 中,为第 3 步的跟踪中出现的每个跨度,按 span_id、parent_span_id、svc、depth(根为 0)、child_count 每行写一条。按 depth 升序,相同则按 span_id 升序。根必须只有一个。

材料是第 3 步生成的 /root/trace/one_trace.ndjson。一个跨度会留下多行,所以要先按 span_id 折叠。depth 顺着 parent_span_id 往上数即可。child_count 是以我为父的跨度的数量——如果这个数字是 0,而你知道那个服务会调用其他服务,那个位置就是断掉的位置。

按跨度测出时间花在了哪里

在 /root/trace/elapsed.json 中写入 spans(每个跨度含 span_id、svc、ms、self_ms,按 span_id 升序)、slowest_self_svc、slowest_self_ms。ms 是该跨度首行与末行的时间差(毫秒整数),self_ms 是从中减去各子跨度 ms 之和所得的值。

材料是第 3 步生成的 /root/trace/one_trace.ndjson。只看耗时,最上面的跨度总是最大——因为它包含着子跨度,这是理所当然的。想知道的是每个服务自己花的时间,所以必须减去子跨度的时间。时间已经固定成同样的写法,换算成毫秒再相减即可。如果出现自身耗时格外大的跨度,在断定它就是元凶之前,请先看第 6 步。

找到断掉的位置,用订单号接起来

在 /root/trace/bridge.ndjson 中,把写有订单 ORD-2026-4117 的所有服务的所有行,按 ts、svc、trace_id(没有则为空字符串)、order_id、linked_by(traceparent|order_id),以 ts 升序写入。另外在 /root/trace/gap.json 中写入 dropped_at(一行 traceparent 都没有留下的服务)、restarted_at(在其后以新的 trace-id 创建了根跨度的服务)、trace_ids(这个订单涉及的 trace-id,按首次出现的顺序)。

材料还是 /root/trace/raw/ 下的五个文件。第 3 步的跟踪中只出现了三个服务,但这个订单经过了五个服务。找到其余两个的钥匙,不是跟踪上下文,而是业务键。dropped_at 是在其日志的任何一行中都没有 traceparent 的服务,restarted_at 是因为没有收到头部而自己创建了新的 trace-id 的服务。

用掩码读取 sampled 标志

在 /root/trace/sampled.json 中写入 total_traces、sampled_traces、unsampled_traces、flag_values(每个 trace-flags 值对应的跟踪数)、naive_equal_01(trace-flags 为字符串 01 的跟踪数)。统计的对象是第 2 步生成的 /root/trace/parsed.ndjson 中出现的所有不同的 trace-id,同一个跟踪内的 trace-flags 全都相同。

trace-flags 是一个 8 位字段。规范明确要求,不要把十六进制当作数字来解读并与该值比较,而要使用掩码。在 Python 中是 int(flags, 16) & 1。naive_equal_01 是有意用错误的方法统计出来的数字,所以把两个值并排放在一起,就是这一步的目的。

把调查结果写成报告

在 /root/trace/trace_report.md 中分四节书写:## 고객은 무엇을 물었나、## 추적이 어디서 끊겼나、## 시간은 어디서 갔나、## 다음 배포에서 고칠 것(韩文,依次意为“客户问了什么”“跟踪在哪里中断了”“时间花在了哪里”“下次部署要修复的内容”)。必须原样包含订单号、头部断掉的服务名称、最大的 self_ms、无效的 traceparent 数量、sampled 跟踪的数量。

要回复给客户的话有两句:“订单没有消失,它走到了哪里”和“为什么在工具里看不到”。数字不要编造,请从前面各步的产出物(/root/trace/gap.json、/root/trace/elapsed.json、/root/trace/sampled.json、/root/trace/badtp.ndjson、/root/trace/bridge.ndjson)中取用。最后一节要写明,下次部署改变什么,就不再需要这项调查。