背景：六小时排查，卡在"没有证据"这一环
事情发生在一个普通工作日的下午。有人反馈：某批推送消息在两点到三点之间集体延迟，部分用户到四点多才收到。不算严重故障，但用户能感知到，所以要给出说明。我从下午三点二十开始查，一直查到晚上九点半。四个多小时后，我在日志里什么都没找到。注意，不是"找到的日志说明没问题"，而是"根本没有那个时间段的日志"。日志目录里只有从当天十六点开始的文件，再往前的都被轮转删掉了。那六个小时的产出是一份三行的说明，而且上面这句话我写得非常心虚——因为我没有证据，我只有"没找到证据"。### 我先猜错了方向：以为问题在队列我的初始假设是队列积压。理由是延迟是"集体"的，一批用户同时受影响，这通常意味着某个共享资源被卡住了。我先看了消费端的处理速率，正常。又看了队列的堆积深度，那个时间段的曲线确实有一个小凸起，但很快就回落了。我甚至写了个脚本去对比消息的入队时间和出队时间，做差值分布，差值的中位数是 42 毫秒，尾部 P99 也就 800 多毫秒。这个数据看起来非常健康，健康到让我怀疑反馈本身是不是搞错了。后来我才意识到，这份"健康"的数据本身就是残缺的——我只统计了那段时间里"还在日志里"的消息。没能进日志的那些，恰好就是有问题的那些。用幸存者偏差去证明系统没问题，这是我在这件事上犯的第一个方法性错误。### 真正的问题：证据在那三个小时里被删掉了晚上八点多，我放弃了从应用日志里找线索，转而去翻文件系统的修改记录。日志目录下当时的文件列表是这样的：app.log 2026-09-24 21:04 48.2 MBapp.log.1 2026-09-24 18:11 50.0 MBapp.log.2 2026-09-24 15:02 50.0 MBapp.log.3 2026-09-24 11:37 50.0 MBapp.log.4 2026-09-24 08:02 50.0 MB问题一眼就看出来了。app.log.2 的时间戳是 15:02，也就是说十四点到 fifteen 点这个窗口的内容，跨越了 app.log.2 和 app.log.3 的边界——而 app.log.3 是 11:37 到 15:02 的内容。但我用 grep 去搜那批延迟消息的标识，一条都没有。再仔细看：这五个文件加起来是 248 MB，而我当天的写入量按速率反推，大约是每小时 62 MB。也就是说，这个日志目录能容纳的内容不到四小时。故障发生在十四点，我开始查是十五点二十。等到我晚上八点真正去翻文件的时候，十四点的日志已经滚了两轮，被覆盖掉了。我盯着那五个文件看了很久。感受不是"日志不够多"，而是"我们明明配了日志，但它在关键的那几小时里是个摆设"。这一篇记录的就是从那次事故开始，我陆续改掉的三个盲区。图：日志系统的三个盲区与对应处置## 盲区一：日志轮转把关键证据覆盖了日志轮转是我以前从没认真想过的东西。它太常规了，几条配置写上去就再也没人碰。但它的默认行为里藏着一条很硬的规则：轮转的存储空间是有限的，超出部分必然被丢弃。### 轮转策略是怎么把证据吃掉的当时的配置大致是这样：
/path/app.log { size 50M rotate 5 missingok notifempty compress delaycompress copytruncate}这里面有三个参数共同决定了"证据能活多久"：-size 50M：单个文件到 50 MB 就切-rotate 5：保留 5 个历史文件-compress+delaycompress：压缩的是从.2开始的文件所以理论上限就是 50 × 6 = 300 MB，实际上因为压缩，已归档的部分会小一些，但热数据仍然是 50 MB 一个文件。真正致命的是后面两条：rotate 5决定了只有 5 份历史，而写入速率决定了这 5 份能撑多久。### 按大小轮转的算术题把这件事算清楚，只需要三个数：写入速率、单文件上限、保留份数。写入速率 R = 62 MB/h单文件上限 S = 50 MB保留份数 N = 6（含当前文件）可回溯时长 T = S × N / R = 50 × 6 / 62 ≈ 4.84 小时4.84 小时。这是一个我在配置轮转时从没算过的数。更糟的是这个数字会随着系统负载漂移：业务量翻倍，或者某天多打了一些调试日志，R 涨到 120 MB/h，T 就掉到 2.5 小时。我在事故之后做了件很简单的事：把这三个数写进配置文件旁边的一行注释，并且加了一个定时任务，每小时把当前的回溯窗口算出来打到监控指标里。回溯窗口低于 8 小时就告警。这个改动一共没写二十行代码，但它把"日志能留多久"从一个没人知道的隐变量变成了一个被监控的数。### 正确做法：环形缓冲 + 关键事件单独落库改法分两层。一层是把轮转从"保留份数"改成"保留时长"。按大小切文件，但归档文件按日期命名，只删超过 N 天的。这样负载高的时候文件数量自动变多，而不是把时间窗口压缩掉。另一层才是关键：不再指望主日志承担关键事件的举证责任。我给自己定了一个判据——“如果这条记录丢了，我需要用什么去重建它？“如果要靠它去证明某个副作用发生过（比如"这条消息确实发出去了”），那它就不该只躺在会被覆盖的文件里。它应该写进一张表。所以现在的结构是：热日志（文本/JSON，滚动，保留 7 天） └── 用于排查过程性问题：为什么慢了、为什么重试了环形缓冲（内存，固定 4096 条，进程内有界队列） └── 用于崩溃瞬间的快照：进程挂掉时把缓冲刷到磁盘审计表（数据库，不参与轮转） └── 用于证明关键动作发生过：发送、状态变更、异常环形缓冲那段代码很短，核心是"写满就覆盖头部，永远不报错、永远不阻塞”：pythonfrom collections import dequeclass RingTrace: def __init__(self, cap=4096): self._buf = deque(maxlen=cap) self._dropped = 0 def push(self, item): if len(self._buf) == self._buf.maxlen: self._dropped += 1 # 不阻塞 self._buf.append(item) def dump(self, path): # 异常退出时落盘 with open(path, "a", encoding="utf-8") as f: for rec in self._buf: f.write(rec + "\n") f.write(f"# dropped={self._dropped}\n")这里有个细节值得说：deque(maxlen=N)在满员时自动丢弃头部，而且这个操作是 O(1) 的，不会因为日志写入把业务线程拖慢。我一开始自己用 list 加切片实现，每次满了做一次self._buf = self._buf[1:]，在高频写入下这部分的开销吃掉了 3% 左右的 CPU，换成 deque 之后这个数字降到了噪声水平。## 盲区二：时区错乱，让我查了一个空的时间段如果说轮转是"证据被删了"，那时区问题就是"我站在错误的地方找证据"。它的表现更隐蔽，因为查询会正常返回结果——返回零行。零行和"没有异常"长得一模一样。### 八小时偏差是怎么被发现的还是那次十四点的故障。我在轮转改好之后，回头补查历史问题时踩到了这个坑。我按运维同事给的时间"下午两点十分左右"去查日志，查询语句大概是：sqlSELECT ts, msg_id, status, latency_ms FROM app_logs WHERE ts >= '2026-09-24 14:10:00' AND ts < '2026-09-24 14:20:00' AND msg_id LIKE 'MSG20260924%';返回 0 行。我的判断是"那段时间没有这个批次的消息"。于是在结论里写了"两点十到二十之间没有相关记录，问题可能发生在更早的环节"。这个结论后来被证明是错的。转折来自一个很偶然的动作：我不死心，直接把时间范围放大到整个下午，再按分钟聚合看分布。sqlSELECT substr(ts, 12, 5) AS minute, count(*) FROM app_logs WHERE msg_id LIKE 'MSG20260924%' AND ts >= '2026-09-24 00:00:00' AND ts < '2026-09-25 00:00:00' GROUP BY minute ORDER BY minute;结果里 06:10 到 06:20 这一段有个明显的尖峰，计数是其余分钟的四倍多。六点十分。我当时想的是"早上六点有另一批消息，和这件事无关"。直到我把那条记录的完整内容打出来看了一眼，发现它的msg_id里嵌着0924，而且处理耗时字段是 5 万多毫秒——这和反馈里的"延迟了很久"对得上。到这里八小时偏差才对上：**应用写库时用的是 UTC，运维同事报的时间是本地时间（UTC+8），我按本地时间去查 UTC 字段，正好查到了八小时前。**我一开始没有怀疑时区，理由说出来有点丢人：我看了下表结构，字段名是ts，类型是timestamp，没有时区信息，我就默认它是本地时间了。数据库里存的值其实一直是 UTC，只是从来没人把它写出来过。### 三个时区同时存在的现场把这次排查涉及的环节列一遍，就知道为什么会乱：环节 1 应用进程 写库用 UTC（datetime.now(timezone.utc)）环节 2 数据库 字段类型无时区，存进去的值原样保留（UTC 数值）环节 3 命令行客户端 会话时区为 UTC，显示出来还是 UTC环节 4 图形化查询工具 默认按操作系统本地时区渲染，显示成 +8 小时环节 5 日志文件 用的是本地时间（因为 logging 默认用 localtime）环节 6 运维同学报障 说的是墙上的钟，本地时间六个环节，三种时间基准。同一个事件，在应用日志里是"14:12"，在数据库里是"06:12"，在图形工具里又显示成"14:12"。而我去 grep 文本日志的时候搜的是"06:12"，当然搜不到。我当时的错误是把"两个地方显示的时间一样"当成了"它们存的是同一个东西"。图形工具显示 14:12 是因为它自己加上了 8 小时，和文本日志里的 14:12 完全是两回事。### 统一时区的三条硬规定改完之后我定了三条规矩，写进了团队约定：1.存储层只存 UTC，字段名带_utc后缀。不再是含糊的ts，而是created_at_utc。名字本身就是文档。2.日志输出带明确的时区偏移。格式串从%Y-%m-%d %H:%M:%S改成%Y-%m-%dT%H:%M:%S%z，输出形如2026-09-24T06:12:31+0000。多出来的 5 个字符换来的是"不需要猜"。3.只在展示层做换算，而且换算的位置集中在一个函数里。pythonfrom datetime import datetime, timezone, timedeltaCST = timezone(timedelta(hours=8))def to_local(dt_utc: datetime) -> str: """只在展示时调用；入库、比对、聚合一律用 UTC""" if dt_utc.tzinfo is None: raise ValueError("naive datetime is not allowed") return dt_utc.astimezone(CST).strftime("%Y-%m-%d %H:%M:%S%z")# 入库row["created_at_utc"] = datetime.now(timezone.utc).isoformat()那个raise是故意留的。朴素时间（不带时区的时间对象）在系统里出现过两次，每次都是 bug。与其在比较时静默出错，不如在写入时就崩掉。## 盲区三：按时刻筛选会捞进前一天同一时刻的行时区改完之后，我以为时间相关的问题都解决了。结果第三个坑紧接着就来了，而且它比前两个更难发现——因为它返回的数据是"看起来正常"的。### 一次典型的误捞现场场景是这样的：我要统计某天上午十点到十一点之间，某个接口的失败次数。日志是滚动文件，一天有二十多个文件。我用一个通配把多天的文件一起 grep：bash# 统计 09-24 10:00-11:00 的失败grep -h '10:[0-9][0-9]:[0-9][0-9]' app.log.2026-09-2[0-9] \ | grep -c 'status=FAIL'输出的数是 312。我拿这个数去做同比，感觉"那天失败偏多"。后来为了写报告，我按天拆开统计，得到的是这样的：09-22 10:00-11:00 FAIL = 4709-23 10:00-11:00 FAIL = 5309-24 10:00-11:00 FAIL = 4909-25 10:00-11:00 FAIL = 5109-26 10:00-11:00 FAIL = 112五天加起来正好 312。也就是说，我那条 grep 根本没有按天筛选——它匹配的是"小时:分钟:秒"这个形状，而通配符把所有天的文件都读进来了。我算的是五天的合计，却当成了当天的数。更麻烦的是，当天的 112 也不一定干净：按大小轮转时，一个文件跨越午夜是常态。09-24 03:00 创建的那个文件里既没有 09-24 凌晨的内容，也可能混进 09-25 凌晨的行。### 为什么时间戳不足以做归因把这件事抽象一下：时间戳是值，不是身份。两行日志如果有相同的"时分秒"，它们在按时刻筛选时是不可区分的。而在跨天拼接的场景里，这种碰撞是必然发生的，不是小概率。我算过这个碰撞的概率有多高。假设一次查询的时间窗口是 1 小时，日志跨越 D 天的文件，采样精度到秒：那窗口内的每一秒，在每一天都有一行。窗口有 3600 秒，D = 5 天，那你捞到的行数是单个日期的 5 倍——误捞率是 400%。这就是为什么"312"这个数看起来像模像样，实际上没有意义。### 正确做法：行号 / 递增序号 + 会话标识改法是把"归因依据"从时间戳换成必然单调的东西。第一个是文件内的行号。大多数文本日志都能拿到行内偏移或者行号；如果是自己控制格式，就在每行前面加一个进程内单调递增的序号：json{"seq":1042871,"ts_utc":"2026-09-24T06:12:31.402+0000","lvl":"ERROR","mod":"dispatcher","msg_id":"MSG20260924...","status":"FAIL","latency_ms":51204}有了seq，跨文件拼接之后我可以按seq排序，判断"这一行是不是在上一次的断点之后"。断点续读、去重、定位都能做，而且不依赖时间。第二个是批次标识。跨进程、跨文件、跨机器的场景里，seq不够用（两个进程的seq会互相穿插）。所以每个业务批次带一个独立标识，所有相关日志行都打上它：sql-- 按批次标识归因，而不是按时间SELECT count(*) AS fail_cnt FROM app_logs WHERE batch_id = 'B20260924-1410-A' AND status = 'FAIL';-- 需要当天统计时，显式带上日期边界SELECT date(created_at_utc) AS d, count(*) FROM app_logs WHERE status = 'FAIL' AND created_at_utc >= '2026-09-24T00:00:00Z' AND created_at_utc < '2026-09-25T00:00:00Z' GROUP BY d;注意第二个查询里日期边界是写死的，不是靠LIKE去匹配文本形状。写死边界这件事看起来很笨，但它把"我要的是哪一天"变成了一个显式参数，而不是一个隐含在正则里的假设。## 日志分级与采样：不是所有日志都值得落盘前面三个盲区都和"日志不够用"有关。但第四个问题正好相反：日志太多了。### 四级分级的具体判据我用的分级不是照搬教科书，而是按"这条日志在什么场景下会被读"来定的：ERROR 需要人介入，或有副作用失败。任何一条都必须能独立看懂 判据：如果不处理，会有人受影响WARN 自动恢复但值得计数。不单独告警，只看速率 判据：出现了但系统还活着，且我能忍受到它一直存在INFO 关键路径的状态迁移。是排障时的主要读物 判据：能回答"走到哪一步了"，且每个请求不超过 5 条DEBUG 参数细节。默认关闭，只在定位到具体模块后临时开 判据：单独一行没有意义，必须和其他行一起看判据里作用明显的是 INFO 那一条。以前我们把 INFO 当"什么都打"，一个请求打十几行，结果真正的状态迁移被淹在参数打印里。改成"每个请求不超过 5 条 INFO"之后，日志总量降了 68%，但排障时读起来反而更快——因为跳跃感消失了，从上到下能顺着读完一条链路。### 采样比例怎么定：高频重复日志的抑制有些日志天然高频且高度重复，比如"轮询未发现新数据"“缓存命中”。这类日志不该按条写，该按统计写。我用的方式是按窗口聚合：pythonimport timefrom collections import Counterclass Sampler: """同一 key 在一个窗口内只记首条，其余计数""" def __init__(self, window_sec=60): self.window = window_sec self._state = {} # key -> (window_id, cnt) def hit(self, key): wid = int(time.time() // self.window) cur = self._state.get(key) if cur is None or cur[0] != wid: self._state[key] = (wid, 1) return True # 落盘 self._state[key] = (wid, cur[1] + 1) return False # 抑制 def flush(self, emit): for key, (wid, cnt) in self._state.items(): if cnt > 1: emit(f"{key} suppressed={cnt - 1} window={wid}")采样比例方面，我按类别定了几档：调试类（参数明细） 采样 1/20，且在 DEBUG 关闭时全部丢弃轮询类（空转探测） 每 60 秒保留 1 条 + 抑制计数重试类（单次重试） 全部保留（重试是异常信号）批量类（批处理进度） 按 10% 进度点保留，其余丢弃审计类（副作用发生） 不采样，100% 落表这五档里"重试类全部保留"是刻意定高的一档。因为重试率很能反映下游健康，采样会直接破坏它的可计算性。反过来，轮询类占日志量的比例当时是 41%，抑制之后降到 2% 以下。## 结构化日志的收益：从 grep 到字段查询从文本日志换成 JSON 行之后，感受明显的是排查节奏变了。文本时代我需要先想"这条日志长什么样"，再用正则去描述它的形状；结构化之后我只需要想"我要哪个字段"。### 改造前后的对比数据同一类排查任务（在两周日志里定位某批消息的处理链路），我记录了两组数据：文本 grep JSON 字段查询定位到首条相关行 11 分钟 40 秒平均尝试的正则条数 6.3 条 0（不需要）漏捞（事后发现） 3 次 / 20 次 0 次 / 20 次准确率 85% 100%（同一口径）单次查询耗时（全量） 18-35 秒 2-4 秒跨字段关联 不支持 原生支持准确率那一项的差别，主要来自构造正则时的"形状假设"。文本时代我写了 6.3 条正则里，至少有 2 条是因为字段顺序变了或者多了个空格而失效的——它们不报错，只是安静地少返回几行。查询耗时从 20 多秒降到 3 秒左右，原因不在解析，而在可以只扫需要的字段。文本模式必须读全行；字段模式下，如果底层是按列存的，过滤只需要读少数字段。### 字段命名踩过的坑换成 JSON 之后我们踩了几个命名上的坑，这些坑不大但会反复咬人：坑 1 同一含义用多个名字：msg_id / messageId / mid 同时存在 → 约定：一律 snake_case，全小写下划线，写进 lint坑 2 时间字段不带时区后缀，见第二部分的那个坑 → 约定：时间字段一律 _utc 后缀，值为带偏移的 ISO 串坑 3 布尔字段用字符串："true" / "True" / "1" 都有 → 约定：真正的布尔，且禁止用字符串表达坑 4 数值字段混入单位：latency 有的毫秒有的秒 → 约定：字段名带单位，latency_ms / size_bytes坑 5 可选字段缺失时整个 key 消失，查询要写很多 IS NULL → 约定：缺失时写 null，保持 schema 稳定字段缺失和字段为 null，在查询层面是两回事：前者会让"按字段存在性过滤"的逻辑失效。我们有次统计retry_count > 0的行数，因为大部分行没有这个字段，聚合直接少算了一大截。后来改成所有行的 schema 一致、缺值写 null，这类问题就没了。## 关键事件审计表设计这是那六个小时教给我的东西里，落成代码的部分。### 哪些事件必须单独存表筛选标准只有一个：这个事件发生后，我需要能证明它发生过。具体落到四类：1. 副作用成功 消息已发出、文件已写、外部调用已返回2. 副作用失败 调用被拒、超时耗尽、状态不允许3. 状态变更 从 A 到 B，何时、由谁触发、依据什么4. 异常 未预期分支、断言失败、数据不一致这四类的共同点是"不可从其他数据推导出来"。比如"消息已发出"这个事实，从消息表的状态字段能推断出结果，但推断不出"什么时候发的、发了几次、每次的结果"。审计表存的是过程。### 字段设计与索引取舍建表语句大致是这样：sqlCREATE TABLE event_audit ( id INTEGER PRIMARY KEY AUTOINCREMENT, event_id TEXT NOT NULL, -- 事件自身标识 occurred_at_utc TEXT NOT NULL, -- ISO8601 带偏移 event_type TEXT NOT NULL, -- send_ok / send_fail / state_change ... subject_type TEXT NOT NULL, -- 主体类型 subject_id TEXT NOT NULL, -- 主体标识 from_state TEXT, -- 变更前（可空） to_state TEXT, -- 变更后（可空） attempt INTEGER NOT NULL DEFAULT 1, detail TEXT, -- JSON 快照，只放排查需要的 batch_id TEXT, actor TEXT NOT NULL -- 触发来源);CREATE INDEX idx_ea_subject ON event_audit(subject_type, subject_id, occurred_at_utc);CREATE INDEX idx_ea_batch ON event_audit(batch_id);CREATE INDEX idx_ea_type_t ON event_audit(event_type, occurred_at_utc);三个索引对应三种问法：按主体查它的完整历史、按批次查一次作业的全部动作、按类型和时间查总体速率。detail字段存 JSON 是个折中：它让我不用为每种事件建一张表，代价是查不了里面的字段。判断标准是"这个字段只用来给人看，还是也要参与查询"——只给人看的放 detail。写入时机上我犯过一次错：一开始我是在业务事务里同步写审计表。结果外部调用超时的时候，事务回滚，审计记录也一起没了——恰好丢的是需要的那条。后来改成审计先写、业务后做，审计表不参与业务事务：pythondef send_with_audit(conn, msg): # 先落意图，崩掉也有痕迹 conn.execute( "INSERT INTO event_audit(event_id, occurred_at_utc, event_type," " subject_type, subject_id, attempt, actor) VALUES(?,?,?,?,?,?,?)", (msg.id, now_utc_iso(), "send_attempt", "message", msg.id, msg.attempt, "dispatcher")) conn.commit() try: resp = do_send(msg) except Exception as e: write_audit(conn, msg, "send_fail", detail=str(e)) raise write_audit(conn, msg, "send_ok", detail=resp.summary())这里有个取舍要说明：审计表不参与业务事务，意味着可能出现"审计说尝试了，但业务其实没开始"的记录。对排查来说这是可以接受的——多一条痕迹比少一条痕迹代价小得多。## 排障时段的准备：先备份再动手这一节和日志本身没太大关系，但它是那次事故里另一件我学到的、收益立竿见影的事。### 一次"装包之后原始状态没了"的教训那次排查进行到一半，我为了加一些临时日志，打了个新包替换上去。替换的时候顺手把旧包删了，日志目录也没动。问题在于：新包启动时会重新初始化本地存储。它的初始化逻辑是"如果表不存在就建表，如果存在就跳过"——听起来很安全。但当时那份存储是旧版本创建的，字段少两个；新版本检测到表存在就跳过了建表，于是启动之后每次写都报字段不存在的错。更麻烦的是，新进程在启动阶段把几份陈旧状态做了"修复"，其中一步是把一个计数表清零了。等我发现要回退的时候，旧包没了，原始数据也被改过了。那次之后我给自己定了条规矩：事故现场的处置顺序永远是备份 → 快照 → 再动手。顺序不能换，也不能合并。### 备份清单现在我的备份清单是固定的五步：1. 进程元信息 ps 输出、启动参数、环境变量（脱敏后）、当前工作目录 → 这些决定了"当时的进程到底是怎么起来的"2. 配置快照 应用配置文件、日志轮转配置、数据库连接配置 → 现场改了配置之后，你就再也回不到原来的解释3. 数据快照 本地库文件整体复制（不是导出，是文件级复制） → 导出会丢索引和 WAL，也丢"当时的状态"4. 日志整体归档 整个日志目录打包，包含已经轮转的历史文件 → 打包，不要 gzip 单文件后再删原文件5. 时间锚点 记录当前 UTC 时间、本地时间、各机器的时钟偏移 → 这一条是给时区坑买的保险执行就是几行命令：bashTS=$(date -u +%Y%m%dT%H%M%SZ)mkdir -p /backup/$TScp -a /srv/app/config /backup/$TS/configcp -a /srv/app/data /backup/$TS/datatar -czf /backup/$TS/logs.tar.gz -C /srv/app logps -ef > /backup/$TS/ps.txtdate -u > /backup/$TS/clock_utc.txtdate >> /backup/$TS/clock_utc.txtsha256sum /backup/$TS/data/* > /backup/$TS/data.sha256最后一行是校验和。它不是为了安全，是为了事后能证明"我分析的就是当时那份数据"。有一次我基于备份得出的结论被人质疑，把校验和拿出来核对之后争议就结束了。## 踩坑：日志写得太详细，把磁盘写满导致服务不可用前面说日志不够用，但过度记录的代价我同样付过，而且那次的后果比"查不到"严重得多。### 日志量与磁盘配额的算术那次是我给一个批量处理模块加了逐条明细日志，一条记录约 380 字节，单批处理 12 万条：单批日志量 = 380 B × 120000 = 45.6 MB批次数（高峰期）= 每小时 8 批每小时日志量 = 45.6 MB × 8 = 364.8 MB磁盘剩余空间 = 12 GB理论上限 = 12288 / 364.8 ≈ 33.7 小时理论值看着还行，但实际只撑了 26 小时。差在哪里？因为中途有两个批次的输入数据异常膨胀，单个批次写进了 3 倍的数据量；而且磁盘上还同时住着数据库文件和它的临时文件。26 小时，正好是一个工作日加一个晚上。后果是磁盘写满，数据库无法写入，服务整体不可用。恢复过程本身不难（清日志就好），但服务停摆的那段时间和连带的数据修复，比前面那次"查不到证据"的代价大得多。改法上有三层限制，分别落在容量、速率和单条长度上：第一层 日志总量硬上限 日志目录独立挂载，配额限定，达到 85% 就按天删旧归档第二层 单模块速率限制 每个模块每秒写入上限（例如 200 行/秒），超限只计数第三层 描述长度上限 单条日志的 detail 字段截断到 2 KB，超长打省略标记第二层的实现是令牌桶，超限时丢弃并累计一个计数器，每隔一分钟把丢弃数汇总成一条：pythonclass RateLimitedLogger: def __init__(self, sink, rate=200): self.sink = sink self.rate = rate self.tokens = rate self.last = time.monotonic() self.dropped = 0 def log(self, line): now = time.monotonic() self.tokens = min(self.rate, self.tokens + (now - self.last) * self.rate) self.last = now if self.tokens >= 1: self.tokens -= 1 self.sink(line) else: self.dropped += 1 # 只加计数，不写盘 def report(self): if self.dropped: self.sink(f"# log_throttled dropped={self.dropped} rate={self.rate}/s") self.dropped = 0这里有个容易忽略的点：丢日志这件事本身要留下痕迹。如果只丢不记，事后看到的就是一份"看起来完整但缺了几行"的日志，比明显缺失更危险。所以每轮上报一行丢弃计数，让"缺失"变成可观测的。## 复盘：可观测性不是"有日志"回头看那六个小时，我的时间分布大致是这样：排查方向猜测（队列、网络、数据库） 3 小时 10 分翻找日志（包括反复扩大时间范围） 1 小时 40 分怀疑数据本身有问题（写脚本验证） 50 分确认是日志系统的问题 20 分一百九十分钟花在了错误的猜测上，而这些猜测之所以无法被快速证伪，是因为每一次验证都缺少可靠的数据。不是没有数据——数据量其实很大，一个日志目录有 248 MB。缺的是"在需要的时候、对的时间范围里、可信的数据"。我后来把这件事的教训压成一句话：可观测性不是"有日志"，是"关键路径上每一步都能被证明"。### 关键路径上每一步都能被证明具体到执行上，我现在的检查方式是问三组问题：第一组，关于时间：- 这条记录的时间是 UTC 还是本地时间？边界写死了吗？- 我查的时间窗口，日志真的还在吗？回溯窗口是几小时？- 日志文件会不会跨天混装？我按什么归因？第二组，关于身份：- 这批动作有没有独立标识？能否用它把整条链路串起来？- 没有标识时，我用什么保证不会捞进无关的行？第三组，关于留存：- 如果这条记录丢了，我要用什么重建它？- 这个磁盘能写多久？写满的后果是什么？三组问题一共九个，没有一个需要新技术，全都是改配置和加字段就能覆盖的。但从那以后，类似规模的问题我在一小时以内都能给出带证据的结论，而不是写"没找到相关记录"。那三行心虚的说明，我到现在还留着。## 相关实现这套做法来自一个本地运行的消息处理工具：单机进程、带本地存储、负责把一批批消息按计划投递出去，界面就是一个普通的桌面窗口，没有服务端集群。它起先只有一份滚动文本日志，正是上面这几次事故之后，才长出了环形缓冲、UTC 命名规范、独立审计表和限额写入这几块。整套东西的形态很朴素——一个能在你手边把消息按点发出去、并且事后能被自己证明做过什么的小工具。dingdang.asia
