用关联 ID 追踪一次跨服务请求

目标

跨服务延迟问题往往藏在服务之间的缝隙里。在入口注入一个请求 ID，并要求每一跳显式转发它，就能把“总共九秒但每个服务都宣称自己只花了几十毫秒”的悬案变成一条可 grep 的线索。本食谱不依赖任何链路追踪平台，只用日志、时间戳和一个唯一字符串即可定位最慢的一跳。

步骤要点

1. 生成唯一请求 ID（如 req-时间戳-随机数），用 x-request-id 头调用入口接口，确认网关回显该 ID。
2. 在各服务日志目录中 grep 这个 ID，用 jq 提取时间戳、级别与消息，确认每一层都至少记录了一条带该 ID 的日志。
3. 按时间戳排序后按服务分组，计算每个服务首末事件的时间差，得到逐跳耗时表，找出间隙最大的那一跳。
4. 检查中间代理与代码里出站调用是否显式复制了该头：HTTP 客户端不会自动透传未知头，必须封装进共享辅助函数。

排错提示

只有网关有日志多半是中间代理默认剥掉了未知头，把 x-request-id 加入其允许头列表即可；跨服务时间戳乱序通常是主机时钟漂移，先比对 date -u 或改用逐跳时长而非绝对时间；日志里混有纯文本行导致 jq 报错时，先按 ID grep 再只把命中行送进 jq。

适用边界

关联 ID 只能说明顺序，不能证明因果，需要精确父子关系时应配合 span 追踪；按 ID 抽样日志依赖每一层都记录该 ID，中间件升级可能悄悄破坏这一点，需在发布清单里保留检查项。

代码示例

REQ_ID="req-$(date +%s)-$RANDOM"
curl -s "https://staging.example.com/api/checkout" \
  -H "x-request-id: $REQ_ID"

grep "$REQ_ID" /var/log/*/app.log \
  | jq -sr 'sort_by(.ts)
    | group_by(.service)
    | map({svc: .[0].service,
           spanMs: ((map(.ts)|max|tonumber) - (map(.ts)|min|tonumber))})
    | sort_by(-.spanMs)
    | .[] | "\(.svc): \(.spanMs) ms"'