记录一下那天晚上的排查过程。网关给每个请求生成了 request id,应用日志里也有 trace_id,但检索服务的日志里这一列是空的,排查一个跨三个服务的慢请求只能靠时间戳硬对。
刚开始盯着「日志格式里打的是本地 span id 而不是 trace_id」,折腾了半个多小时,排掉了。
排查方向其实有限,先把可能性排一排。HTTP 客户端重建了请求头,自定义头没带上。少数情况下是异步任务与线程池没有继承上下文。
不容易想到的是,中间件顺序在鉴权之后就返回了,注入根本没执行。
上来先在每一跳打印收到的追踪头
python -c "print({'traceparent':'00-abc-def-01'})"
然后让 HTTP 客户端默认带上上下文载体
python -c "print('headers.update(carrier)')"
接着统一日志格式里的追踪字段
python -c "print('%(trace_id)s %(message)s')"
剩下的就是用一条请求串三个服务验证
curl -H "traceparent: 00-abc-def-01" http://127.0.0.1:8000/v1/chat/completions
怎么算真的好了,看的是同一批现象。同一条 trace_id 在三个服务的日志里都能 grep 到,时间顺序与调用顺序一致,缺失条数为 0。
trace_id 要跟着消息队列与异步任务一起走,只在 HTTP 头里传,后台消费那一段一定断。拖得越久,排查成本越高,因为现场状态会被后续操作覆盖。
