Skip to content
Published on

像侦探一样读懂日志和堆栈跟踪

🇰🇷KO🇺🇸EN🇯🇵JA🇨🇳ZH
필사 모드
分享
Authors

引言 — 日志是案发现场

凌晨 3 点，寻呼机响了。生产环境挂了。你手上只有一个无法复现的故障、数十万行日志，还有一个红色的堆栈跟踪。好消息是，这些其实都是证据。堆栈跟踪是案发现场的照片，日志是目击者们的证词记录。侦探要做的事，就是读懂这些证据，指认出真凶。

问题是，许多开发者并不能好好地读懂这些证据。一看到堆栈跟踪就眼花缭乱，只看上面几行就跳去猜测；日志太多，索性放弃、随便 grep 一下了事。但读证据是有方法的。这篇文章要梳理的，就是像侦探一样——系统地、基于证据地——阅读堆栈跟踪和日志的技术。

读懂堆栈跟踪 — 一端是现场，一端是起因

第一次遇到堆栈跟踪时，人会被它压倒。但只要知道结构，它就是一座信息宝库。记住一条核心规则就够了：一端是事件爆发的地方，另一端是这个事件开始的地方。

我们以一个 Python 堆栈跟踪为例。

Traceback (most recent call last):
  File "app.py", line 42, in <module>
    result = process_order(order_id)
  File "services/order.py", line 18, in process_order
    total = calculate_total(items)
  File "services/pricing.py", line 7, in calculate_total
    return sum(item.price for item in items)
  File "services/pricing.py", line 7, in <genexpr>
    return sum(item.price for item in items)
AttributeError: 'NoneType' object has no attribute 'price'

阅读顺序，以及要提取的信息：

  1. 先读最下面的异常行。 AttributeError: 'NoneType' object has no attribute 'price'。这是对发生了什么的概括：有什么东西是 None，却试图从它身上取出 .price。
  2. 紧接在上面的那一帧，就是出事的地点。 pricing.py 的第 7 行，item.price。这里的 item 是 None。这就是案发现场。
  3. 向上追溯调用链。 app.py(42) → process_order(18) → calculate_total(7)。它展示了这个请求是沿着什么路径走到这里的，也就是起因。

这里有一个重要的判断要做：哪一帧才是"我的代码"。 堆栈跟踪里常常混杂着大量框架、库内部的帧。异常虽然是在库的深处爆发的，但真正的原因，十有八九出在我的代码——是它把一个奇怪的值传给了库。所以扫视整个堆栈，找出"最后一次出现我项目路径的那一帧"。十有八九，那里就是该开始调查的地方。

不同语言的方向可能会让人混淆。Python 是 "most recent call last"，所以最下面是出事的地方；但 JavaScript 或 Java 通常是最上面是出事的地方，越往下越接近起因。规则本身("一端是现场，另一端是起因")是一样的，只需要确认这门语言是哪个方向就行。

"Caused by" 链条 — 真正的根本原因

在 Java 系语言中尤其常见、也必须掌握的一种模式，就是 "Caused by" 链条：一个错误包裹着另一个错误，层层叠加而成。

Exception in thread "main" com.example.OrderProcessingException: Failed to process order 4821
    at com.example.OrderService.process(OrderService.java:52)
    at com.example.Main.main(Main.java:14)
Caused by: java.sql.SQLException: Connection timed out
    at com.example.db.Pool.getConnection(Pool.java:88)
    at com.example.OrderService.process(OrderService.java:48)
    ... 1 more
Caused by: java.net.SocketTimeoutException: connect timed out
    at java.base/java.net.Socket.connect(Socket.java:507)
    at com.example.db.Pool.getConnection(Pool.java:85)
    ... 2 more

这里新手常犯的错误是只看最上面的异常就下判断。 OrderProcessingException: Failed to process order 4821 其实只是最外层的包装纸。"订单处理失败"是症状，不是原因。

真正的原因，在于顺着链条一路追到底的最后一个 "Caused by"。 在上面这个例子里：

  • 最上层：订单处理失败(症状)
  • Caused by：SQL 异常，连接超时(中间原因)
  • Caused by：套接字连接超时(根本原因 — 网络上连不上数据库)

所以看到 "Caused by" 时，一直滚动到底。 最下面的根本异常，才是真正要修的对象。上面那些异常，不过是它在经过每一层时被重新包装的样子。把这条链条读作"因为这样 → 因为这样 → 归根结底是因为这个"，就是侦探式的因果追溯。

结构化日志 — 用数据说话，而不是句子

如果说堆栈跟踪是"爆发那一刻"的快照，那日志就是"随时间展开的事件"的记录。而日志怎么记，会彻底决定日后能不能调查得起来。核心在于，把日志记成机器可以解析的结构化数据，而不是给人读的句子。

传统的日志长这样。

2026-06-28 03:14:22 ERROR Failed to process order 4821 for user 91 after 3 retries

人眼能读，但要用程序处理它就得用正则表达式来解析，一旦多加一个字段，解析器就会崩掉。相比之下，结构化日志(JSON)是这样的。

{
  "timestamp": "2026-06-28T03:14:22.481Z",
  "level": "ERROR",
  "service": "order-service",
  "message": "failed to process order",
  "order_id": 4821,
  "user_id": 91,
  "retries": 3,
  "duration_ms": 2140,
  "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736"
}

结构化日志的好处是压倒性的。

  • 搜索与过滤：可以精确查询"order_id 为 4821 的日志"或"duration_ms 超过 2000 的日志"。这是字段查询，不是字符串匹配。
  • 聚合：直接从日志里拉出"按服务统计的错误数"、"retries 平均值"之类的统计。
  • 解析稳定性：即使新增字段，现有流水线也不会崩。
  • 关联性：只要埋下 trace_id 这样的字段，就像后面会看到的那样，可以把多个服务的日志串成同一个请求。

原则：想记录的值不要硬塞进字符串里，要留成独立的字段。 不要写成 "order 4821 failed"，而是把 message 留成 "order failed"，再把 order_id: 4821 作为字段附上去。日后调查时，这个差别就是生与死的区别。

关联 ID 与 trace_id — 串起一个请求

在微服务环境中，一个用户请求要经过好几个服务：API 网关 → 订单服务 → 支付服务 → 通知服务……如果每个服务各自记各自的日志，出问题时要怎样把"这一个请求留下的日志"全部收集起来?答案就是关联 ID(correlation ID)，其中标准化的形式就是 trace_id。

原理很简单。请求第一次进入系统时签发一个唯一 ID，此后这个请求经过的每一个服务，都把这个 ID 一并写进自己的日志里。 服务间相互调用时，就把这个 ID 装进 HTTP 头之类的地方传播下去。这样一来，日后只需用这一个 ID 过滤，散落在多个服务里的日志，就能重新拼成一个请求的时间线。

{ "service": "gateway", "trace_id": "abc123", "message": "request received", "path": "/checkout" }
{ "service": "order-service", "trace_id": "abc123", "message": "order created", "order_id": 4821 }
{ "service": "payment-service", "trace_id": "abc123", "message": "charge failed", "reason": "card_declined" }
{ "service": "gateway", "trace_id": "abc123", "message": "responded 402", "duration_ms": 890 }

只过滤出 trace_id 为 abc123 的记录，从网关进入、订单被创建、支付被拒绝、最终以 402 响应的整个过程就一目了然。没有关联 ID 的话，这四行会散落在数十万行之中，彼此失联，被埋没掉。

实务技巧：关联 ID 应该在请求的最前线(网关或中间件)签发一次，之后自动注入到所有日志里。不必每条日志手动添加——只要在日志记录器的上下文里埋一次，处理这个请求期间的所有日志就会自动带上它。再把这个 ID 暴露在展示给用户的错误页面上(比如"联系我们时请提供此代码：abc123")，就能把用户的问询立刻和日志对应起来。

grep、jq、ripgrep — 挖掘日志的工具

就算把日志全都收集齐了，如果没法从里面抽出想要的东西，也是白搭。命令行里有专门为此而生的强大工具。

grep / ripgrep(rg)：在文本日志里查找模式的基本功。ripgrep 比 grep 更快，默认设置也更顺手。

# 特定 trace_id 的所有日志
rg "abc123" app.log

# 仅 ERROR 级别
rg '"level":"ERROR"' app.log

# 连同匹配行前后 3 行一起查看(确保上下文)
rg -C 3 "card_declined" app.log

# 多个条件：支付服务的错误
rg '"service":"payment-service"' app.log | rg '"level":"ERROR"'

这里的 -C(context)选项对侦探来说尤其重要。只看错误那一行，和连同前后几行一起看、了解紧接着之前发生了什么，两者是天壤之别。因为一起事件，往往是由紧邻它之前的那起事件引发的。

jq：处理 JSON 日志的专用刀。如果用了结构化日志，jq 会比 grep 精准得多。

# 只抽出 ERROR 级别日志的 order_id
jq 'select(.level == "ERROR") | .order_id' app.log

# duration_ms 超过 2000 的慢请求
jq 'select(.duration_ms > 2000)' app.log

# 特定 trace_id 的日志，只看 service 和 message
jq 'select(.trace_id == "abc123") | {service, message}' app.log

# 按原因统计错误数
jq -r 'select(.level=="ERROR") | .reason' app.log | sort | uniq -c | sort -rn

这就是结构化日志的回报。像 duration_ms > 2000 这样的数值比较，或者按字段做聚合，用字符串 grep 几乎不可能做到，但换成 JSON，一行 jq 就搞定。

如果你的服务处理 HTTP，日志里就会频繁出现状态码。搞不清 402 是什么意思、或者 499 和 500 有什么区别时，去HTTP 状态码参考页快速确认每个码的含义，先准确判断日志里的状态码到底是"客户端的错还是服务端的错"。

日志级别 — 控制噪音的旋钮

如果不加区分地把所有日志都记下来，真正需要信号的时候，它就会被淹没在噪音里。所以才有了日志级别。给每条日志标上严重程度，再根据情况调整只看某个级别以上的内容。标准的层级是这样的。

  • DEBUG：用于开发、调试的详细信息。"这个变量的值是这个"这种级别。生产环境里通常是关掉的。
  • INFO：正常的重要事件。"订单 4821 已创建"、"服务器已启动"。是系统在做什么的记录。
  • WARN：眼下还不是问题，但值得留意的事。"重试 3 次后成功"、"配置值缺失，使用默认值"。是潜在问题的早期预警。
  • ERROR：某件事失败了、需要处理。"支付处理失败"、"数据库连接断开"。

用好级别，既是礼貌也是实力。两个常见的反模式：

  • 什么都打成 ERROR：连鸡毛蒜皮的小事都是 ERROR，真正的 ERROR 就会被淹没。"狼来了"喊多了，等狼真的来了也没人理。
  • 什么都不打：正常路径上连一条 INFO 都没有，等出问题时就没法知道到底走到这一步了没有。

调查的时候，把级别当作过滤器来用。先只看 ERROR，抓住大事件；如果某个时间点显得可疑，就下沉到那附近的 INFO、DEBUG 去补上下文。从宽(ERROR)收窄到窄(那个时间点的全部级别)，是其中的诀窍。

采样 — 无法全部保留的时候

在流量巨大的服务里，把所有日志 100% 保留下来，要么不可能，要么不划算。每秒数万次请求，各自留下好几行日志，存储成本和处理负载都会扛不住。所以要做采样：只留一部分作为代表。

核心原则是：正常情况做采样，但问题要全量保留。

  • 成功的正常请求：没必要全部保留。比如说，哪怕只采样 1%，也足够掌握整体趋势。
  • 错误、慢请求：100% 保留。真正需要调查的正是这些，而它们相对稀少，全量保留也承受得住。

这样一来，存储量会大幅下降，但真正需要深挖的事件(错误、异常)一个都不会漏掉。前一篇文章(可观测性)中提到的追踪(trace)的尾部采样(tail sampling)，正是这套哲学在追踪层面的版本。也就是"结束后一看，是错误或者慢，就无条件保留"这条规则。

要当心的陷阱是：做采样时，必须以 trace_id 为单位来决定，让同一个请求的日志要么一起保留，要么一起丢弃。 如果一个请求里有的日志留下、有的被丢掉，日后按那个 trace_id 去调查时，时间线上就会出现空洞。要把整个请求当作一个原子单元来处理——"这条 trace 被选中采样"，就保留这条 trace 的全部日志。

综合运用 — 追踪凌晨 3 点的故障

把到目前为止的工具，编织成一次完整的侦查吧。警报来了："支付成功率暴跌。"

  1. 拿到堆栈跟踪：在错误报告工具里打开一个具有代表性的堆栈跟踪。顺着最下面的 "Caused by" 一路追到底，是 SocketTimeoutException。说明网络上连不上数据库或外部 API。
  2. 是哪一边：看堆栈里"我的代码"那一帧，是支付网关客户端。范围缩小到连不上的不是我们的数据库，而是外部发卡机构的 API。
  3. 用日志交叉验证：抓住一个失败请求的 trace_id，用 jq 拉出这个请求的完整时间线。在 payment-service 里，对发卡机构的调用恰好死在超时值上。
  4. 摸清范围：按原因聚合错误(jq ... | sort | uniq -c)。全都是同一个发卡机构端点的超时。很可能不是我们的 bug，而是发卡机构那边出了故障。
  5. 补上下文：用 rg -C 5 查看第一次超时之前的日志。从某个具体时刻起，延迟开始骤增。查一下发卡机构的状态页面，正好那个时刻有故障公告。

堆栈跟踪回答了"是什么"(网络超时)，基于 trace_id 的日志回答了"在哪里"(发卡机构的 API)，聚合回答了"多严重"(全量)，上下文回答了"从什么时候开始"(那个时刻)。没有靠猜测，仅凭证据就查明了真凶在我们的边界之外。

结语

日志和堆栈跟踪，不是烦人的红色文字，而是事件留下的证据。把侦探的技艺再归纳一遍：

  • 堆栈跟踪是一端是现场，另一端是起因。找出"我的代码"那一帧。
  • "Caused by" 要追到底。 根本原因在最下面。
  • 日志要记成结构化数据(JSON)，而不是句子。
  • 用 trace_id 把散落的日志串成一个请求。
  • 用 grep/rg/jq 挖掘，但要连同上下文(-C)一起看。
  • 用日志级别控制噪音，用采样减少正常情况、但把问题全量保留。

下次遇到堆栈跟踪时，不要闭上眼睛靠猜测。那是一份供词，请读到最后。下次遇到日志的海洋时，不要绝望。那是目击者的证词，用 trace_id 把它传唤出来。证据早就都在那里了。你只需要去读。

参考资料

Discuss on Twitter • View on GitHub