☰
生产日志极速排障:用rea解析多行堆栈并生成错误指纹
2026/10/13 20:44:11 网站建设 项目流程

先交代一下,rea不是哪个框架的缩写,也不是为了凑三个字母好看。它是runtime error analysis的简写,是我某次被线上日志折腾到半夜之后,花了半小时写出来的一个本地脚本。用到现在大概两周,它已经成了我排障时第二个跑的指令——第一个是看告警,第二个就是它。

它能解决的事情其实特别朴素:把一堆日志文件丢进去,吐出一张按出现次数排好序的异常清单。告诉你哪类报错最多、集中在哪个文件哪一行、消息长什么样。不接数据库,不部署服务,不搞可视化大屏,就是纯命令行工具,适合谁呢?适合那些没有完整日志平台、或者平台太笨重懒得开的后端研发、SRE、以及一人扛一个服务的独立开发者。如果你已经习惯了grep -E "ERROR" | sort | uniq -c这种临时办法,那这篇文里踩过的坑你几乎都会遇到。

1. 从凌晨告警里翻日志:三个字母的项目名是怎么来的

那次起因是某个内部服务半夜开始持续告警。起床打开电脑,先看进程还活着,再翻日志目录,发现单日日志已经滚到了两三百兆。我本来想先看错误频率,于是习惯性地开始敲命令:grep ERROR肯定不行,因为堆栈追踪里大量行根本带不上ERROR标点,有些日志框架还会把异常第一行写成WARN;grep -A 20 Exception倒是能捞到一些,但捞出来的结果没有统计,只有一屏又一屏的重复文本。

真正让我崩溃的是这一步:我发现同一类错误散落在一整晚的日志里,每次报错的完整堆栈有十几行,手动滚屏根本看不出哪个才是大头。想按错误类型统计,就得先知道都有哪些错误类型;想知道错误类型,就得先把日志读完。这是个死循环,普通命令行工具很难优雅解开。

1.1 我踩过的日志分析三类痛点

第一类痛点是多行堆栈。grep按行过滤,碰上换行结构的堆栈,要么漏掉后半段,要么把整个堆栈当作一大块一起输出,既不好看也不好数。第二类痛点是变量噪声。同一个异常,因为请求参数不同,消息里带着一堆用户 ID、订单 ID、IP 地址,直接让uniq失去意义——你以为有一百种错误,其实是同一个错带了一百个参数。第三类痛点是缺少时间窗。很多临时命令只能统计整个文件,没法快速回答“过去十分钟哪一种错误涨得最快”,而半夜排障最关键的就是这个。

当时我就想,干脆写一个专门的脚本处理这三件事:把堆栈当成一个整体来切,把消息里的动态值全部归一化,再按固定时间窗口做聚合。写完之后发现它比我想象的通用得多,于是保留了rea这个名字,当常用工具养着。

1.2 为什么不直接依赖现成日志平台

你可能会说,直接上 ELK、Loki 之类的不是更省事吗?我承认,有平台当然好,但不是每个环境都有条件接。日志平台至少需要部署收集端、存储端、查询端,还要配索引策略和权限体系。而rea的场景是:日志就在本地磁盘,或者是从某台机器上随手拷下来的压缩包,我只想快速看结论,不想先搭一套“基建”再排障。

这次我选择手写而不是调用云端工具,还有一个现实原因:很多内网环境下,日志不能随便往外传。本地离线分析反而是最稳妥、最不折腾的那条路。工具可以简单到没有第三方依赖,只要能跑 Python 就行。

2. rea 的解析模型:怎样把一行行日志变成可统计的错误指纹

如果只是写个循环,抓取含Exception的行,然后Counter一下,那和grep没区别。真正有价值的设计在于:什么算“同一个错误”。

我最后定的策略是三层组合,叫做“错误指纹”:

  • 第一层:异常类型,例如ConnectionError、KeyError、ValueError;
  • 第二层:异常被抛出的位置,精确到文件名的最后一段加上行号;
  • 第三层:异常消息经过归一化之后的前半段内容。

一个指纹长这样:

ConnectionError @ conn_pool.py:182 in _create_conn || "<host>" connect timeout after 5s

为什么必须用三层而不是只看异常消息?因为有些异常消息是空的,有些异常类型烂大街,比如RuntimeError,只看类型完全没有信息量。而如果把完整堆栈也带上,又会过度区分——同一个错误,调用链里只要多一帧,就会被拆成两条记录,统计就碎了。取“异常类 + 抛错位置 + 消息前缀”是一个比较稳的中间值,既能合并重复,又能保留足够线索。

2.1 多行堆栈的状态机读取

日志不是 JSON 时,最常见的形态就是一段缩进堆栈。rea不追求解析一切格式,只做了一种假设:异常分组由Traceback (most recent call last)开始,后续缩进行都属于这个组,直到出现一个顶格的非空行,分组才结束。

我用一个极简状态机实现,核心代码如下。

import re from collections import Counter from pathlib import Path _STACK_START = re.compile(r"Traceback \(most recent call last\)") _FILE_LINE = re.compile(r'File "(.+?)", line (\d+), in (\w+)') def iter_error_groups(path): current = [] started = False for raw in open(path, encoding="utf-8", errors="replace"): if _STACK_START.search(raw): if current: yield current current = [raw] started = True continue if started: # 缩进行继续收纳,顶格行认为分组结束 if raw[:1] in (" ", "\t"): current.append(raw) else: yield current current = [] started = False if current: yield current

你可能注意到,这样只要堆栈中间出现一个顶格的信息,分组就会断掉。实际日志里确实会混进一些奇怪的中间行。后面我会补讲这个问题,真实使用中它坑过我一次,后来我加了更严格的收尾条件。

2.2 用归一化处理“看起来不同其实是同一个错”

拿到一组堆栈后,我需要从最后一行提取异常类型,从File "…", line …, in …行提取最后一个位置。这一步大家都会写,真正容易绕进去的是消息归一化。原始消息长这样:

Failed to load user_id=12345 Failed to load user_id=67890

归一化之后必须是:

Failed to load user_id=<ID>

这样统计才不会散。我维护了一组通用替换规则,示例代码如下。

_NORM_RULES = [ (re.compile(r"\b\d{6,}\b"), "<LONG_ID>"), (re.compile(r"\b(id|user_id|order_id|task_id|request_id)=?[:= ]\s*[\w.-]+", re.I), r"\1=<ID>"), (re.compile(r"\b(\d+\.){3}\d+\b"), "<IP>"), ] def normalize_message(message: str) -> str: for pattern, repl in _NORM_RULES: message = pattern.sub(repl, message) return message.strip()

注意两条:顺序很重要,先把 IP 替换掉,再处理 ID,否则127.0.0.1会被 ID 规则拦一半;替换后的占位符不要用{},因为后续如果真的接入模板渲染,{}会和格式化语法撞车。我用的占位符统一是<ID>、<IP>这些尖括号风格。

2.3 统计与输出格式的设计

统计核心就三行代码:

counter = Counter() for group in iter_error_groups(log_path): fp = extract_fingerprint(group) counter[fp] += 1 for fp, count in counter.most_common(10): print(f"{count:8d} {fp}")

输出样式刻意做得像sort | uniq -c的增强版,因为命令行工具越贴近现有习惯,学习成本就越低。列宽固定,数字左对齐靠右,不看帮助文档也能一眼读懂。这个“小而克制”的设计很重要,我见过太多内部工具输出五彩斑斓的表格,真正排障时反而没人看。

3. 一个实际案例:数据库连接池异常是这样被 rea 揪出来的

工具写得再顺手,也得在真实排障里验证价值。这里分享一个我实际遇到的案例,为了说明过程,我用的是脱敏后的日志结构。

3.1 当时的日志长什么样

某服务的日志文件是经典一行一事件格式,异常出现时自带完整堆栈,前端还包了一层请求路径和时间戳。截取关键片段大致是这样:

2025-01-08 03:12:22 ERROR request_id=9a2f1e66 api=/v1/order/query Traceback (most recent call last): File "/srv/app/db.py", line 214, in query_users return self.conn.execute(sql) File "/srv/app/conn_pool.py", line 182, in _create_conn raise ConnectionError("server has gone away") ConnectionError: server has gone away 2025-01-08 03:12:23 ERROR request_id=3b1a0d21 api=/v1/order/query

注意,这里日志框架把Traceback直接打在了 ERROR 后面,如果用“只取含 ERROR 的行”再grep,后面的堆栈就断了,根本拼不回去。所以解析时必须以Traceback为锚点,而不是以日志级别为锚点。

3.2 命令行和输出

当时的分析命令就一条:

python rea.py \ --path /var/log/app \ --since "2025-01-08 03:00:00" \ --until "2025-01-08 04:00:00" \ --top 10

输出是:

7342 ConnectionError @ conn_pool.py:182 in _create_conn || "<host>" connect timeout after 5s 196 KeyError @ cache.py:57 in get_ttl || "ttl" not found 42 ValueError @ serializer.py:31 in loads || unexpected token "<TOKEN>"

看到没有:第一名瞬间把问题暴露出来。7342 次,一小时内的绝对大头,位置直接指向conn_pool.py:182,连猜都不用猜。相比之前手动翻日志,这个分析从跑命令到出结果也就两三秒。

3.3 从统计第一个冲到根因只需要三步

拿到这个输出后,我的排障路径变得非常清晰。

第一步,看位置。conn_pool.py:182是创建连接的地方,而不是真正执行 SQL 的地方。说明连接建立时就已经失败,和业务 SQL 无关。第二步,看时间窗。这个错误从 03:00 到 04:00 一直稳定高频,不是请求尖峰触发的偶发问题。第三步,看配套指标。配合服务端连接数监控,能发现服务端把空闲连接清理掉了,但客户端连接池不知道,仍然把失效连接拿出去跑。

根因确定后,修复方向就不是提高连接池上限,而是让连接池在获取连接时先做一次探活,或者调整客户端空闲回收周期,让它短于服务端的空闲淘汰周期。一个统计工具能帮你把范围缩到这个程度,后面定位就是顺手的事。

3.4 结果不直观时的两个检查点

rea也不是每次都准。我遇到过输出结果排序很诡异,第一名竟然是KeyError之类看着不像会刷屏的异常。这时候我会先做两个检查。

第一个检查是时间窗口。如果日志里某些行没有时间戳,或者时间格式歪了,--since过滤会把这些行全部丢弃,导致结果和真实分布不一致。第二个检查是消息归一化规则是否过度替换。比如某个业务字段本身就叫id,归一化把它变成了<ID>,结果两个完全不同的业务异常被合并到了一起。遇到这种情况,我不会立刻改规则,而是先用--show-samples 3参数,把某个指纹对应的前几条原始堆栈打出来,人工确认它是不是同一个错。样本确认比盲目改规则更可靠。

4. 用了一周之后,我补上的三个坑

工具写出来是一回事,真正在线上用一周是另一回事。这一周里我陆续踩到三个坑,每一个都让脚本的结果出现过偏差,折腾完才明白,写日志解析工具的真正难点全在边界情况。

4.1 坑一:被截断的堆栈让状态机误开分组

第一个坑出现在日志上传到分析环境时被切割过的情况。某段堆栈的最后一行丢了,下一条日志的INFO开头直接顶格出现,我的状态机误以为当前分组已经结束,把这个不完整堆栈单独记成了一条“独立异常”。结果输出里多出一堆长度为 1 的幽灵指纹。

修复方式是增加分组结束的严格条件:不只是遇到顶格行就结束,还要要求当前分组内至少包含异常类型行,也就是最后一个非缩进行必须以Error:、Exception:等已知后缀收尾;不满足的,继续往下吸收,直到堆栈特征行出现。简单说,宁可把相邻两段堆栈合并,也好过把一个完整堆栈拆成两半。

4.2 坑二:动态参数把同一类错误拆成几千组

第二个坑是归一化规则覆盖不足。一开始我只替换了长数字和常见 ID,后来发现某个业务异常的消息里带了一段完整的 URL,URL 路径中包含查询参数,参数值每次都不一样。结果一个真正的根因被拆成了几百条指纹,排序时完全没有优势。

后来我在规则集合里补了两条通用表达式:一条匹配 URL,整体替换成<URL>;一条匹配键值对,把key=value统一洗成key=<V>。补完再跑,同一类错误立刻汇聚成了一个指纹。这里想提醒一点:归一化规则不是越激进越好,我一般只对高熵字段动手,比如长数字、IP、URL,而对业务状态码、数据库错误码保持原样,因为这些值恰恰是你想保留的差异。

4.3 坑三:日志文件大起来之后,单遍扫描也能变慢

第三个坑来自性能。最初版本为了计算时间窗口,我先把整个文件按行读进内存,再做正则。结果日志两三百兆时,内存直接冲上去,机器开始交换页面。后来改成流式逐行读取,所有正则表达式在启动时统一编译,统计用Counter,整个分析过程只保留当前分组和最终计数,内存占用稳定在几十 MB。这一改动对排障场景很关键,因为半夜你不想因为一个工具把服务弄得更糟。

4.4 容易被忽略的时区问题

最后一个不算代码坑,而是使用姿势问题。日志时间戳如果写的是 UTC,而我本机是本地时间,--since "03:00:00"就会完整错位一小时。我的处理方式是在脚本里读日志头部取时区标记,然后统一转成时间戳做过滤;如果日志里没有时区,就在参数里显式声明。现在我会强制要求自己写--tz utc或--tz local,避免半夜被自己坑到。

5. 下一步我打算给 rea 加的两个观察维度

rea现在满足了我 80% 的日志快筛需求,但用久了明显感觉有两个维度还缺。第一个是时间趋势,第二个是请求链路。

5.1 时间趋势比累计次数更能暴露异常突变

只看累计次数,可能漏掉“某类错误正在猛涨”的趋势。比如某个错误累计排名第三,看起来很温和,但过去十分钟它出现了 400 次,而前一个小时只有 10 次,这种突变才是告警最该关心的。我计划让rea支持把时间窗切分成固定粒度的桶,默认按分钟或十分钟输出一个简易直方图。不需要什么前端图表,直接用等宽字符打印柱状条就能快速看出斜率。

5.2 把 trace_id 作为第二维度,减少“重试刷屏”

另一个更值得做的改进是引入请求链路 ID。现在的统计把所有错误都当成独立事件,但很多错误其实是同一次请求的自动重试造成的:第一次超时,重试又超时,再重试又超时。最终日志里同一个堆栈刷出三次,统计数字虚高。如果能把每个分组的错误按request_id去重,或者在结果里增加一列“涉及的请求数”,排障时就会少一层误判。这也是我下一步最先要加的字段。

这个工具本身不大,但它的价值恰恰在于把“看日志”这个过程从手工活变成了统计活。如果你也经常被生产日志淹没,与其翻来覆去敲临时命令,不如花半小时写一个统一指纹规则的小脚本,得到的回报会比预期高很多。

需要专业的网站建设服务?

联系我们获取免费的网站建设咨询和方案报价,让我们帮助您实现业务目标

立即咨询