引子
2026-09-02 周三下午 14:06,我刚把 `6ada1f6` 推到 main,注释写着「Phase 81 自动化审计脚本 + 修复 daily.py 2 处静默 fallback」。但这一行 commit 的真实故事,从 11 天前的类教训 11 沉淀开始。
8/22 我在 `7f8f256` 提交里写了一句:「字段名在写入端/读取端漂移,静默默认 0 — 用户级 bug 但完全没告警。」当时我觉得这只是 Phase 77.J 一次性的复盘,类教训 #11。
9/1 周二早上 11:53,部署机用户发来一段话:
「周报/月报里的『总封禁』永远显示 0,但我看 banned_*.json 文件里有数据啊。」
我打开 `src/event_store.py:57` —— EventStats.to_dict() 写入字段是 `ips_banned`。再打开 `src/report/periodic.py:138` —— WeeklyStats.total_blocked 读取字段是 `total_blocked`。
写入端和读取端的字段名漂移了 6 个月没人发现。`.get('total_blocked', 0)` 永远拿默认值 0。整个『总封禁』指标,从一开始就在假装工作。
我修了。然后修了日报的同类问题。然后用 AST 扫描同文件,发现还有 2 处同源 bug 我没修。11 天、4 个 Phase、7 个守卫测试、1601 passed —— 这就是本期 zheteng-008。
问题:3 个静默失败串谋 11 天
过去 11 天我修了 3 个互相串谋的 bug,每一个看起来都很小,但合起来让 security-monitor 的所有「统计指标」完整地假装在工作。
问题 1 — 周报/月报『总封禁』永远 0(Phase 78.1,2026-09-01)
Bug B 的根因最简单也最致命:
# src/event_store.py:57 (写入端 — 真值在这)
def to_dict(self) -> dict:
return {'ips_banned': self.ips_banned, 'total_events': self.total_events, ...}
# src/report/periodic.py:138 (读取端 — 永远读不到)
stats.weekly.total_blocked += record.get('total_blocked', 0) # ← 永远是 0
字段名漂移:`'ips_banned'` vs `'total_blocked'`。两边都是合法字段名,但同一个概念在两边用了两个名字。`.get('total_blocked', 0)` 拿不到默认值 0,用户看到的就是「封禁数据 = 0」。
修复 — 双 schema fallback + 白名单显式声明:
# src/report/periodic.py:101 _load_stats int_fields 白名单加 'ips_banned'
INT_FIELDS = {'ips_banned', 'total_events', 'unique_ips', 'total_blocked', 'banned_ips'}
# src/report/periodic.py:138/424 累加改读 'ips_banned' 带 fallback 'total_blocked'
stats.weekly.total_blocked += record.get('ips_banned', record.get('total_blocked', 0))
dev box 复现 + 验证:
测试数据: 3 banned IPs + 老 schema (只有 total_blocked=3, 无 ips_banned)
修复前: total_blocked = 0 ❌
修复后: total_blocked = 3 ✅ (回退到 'total_blocked' 字段)
测试数据: 新 schema (ips_banned=3)
修复后: total_blocked = 3 ✅
关键洞察 1:白名单 `INT_FIELDS` 必须包含写入端实际产出的所有字段名,否则白名单过滤会把字段直接吞掉——不是默认值 0,而是键不存在。下游再 `.get('ips_banned', 0)` 拿到 0,又多了一层假象。
问题 2 — 日报『大部分无数据』,但 daemon 日志无任何告警(Phase 78.2,2026-09-01)
这是更隐蔽的同源问题。我修 78.1 时顺手看了一下日报,发现同样的模式,但多了一类第二层静默:
# src/report/daily.py:216-219 (修复前)
def load_today_stats(target_date):
try:
stats = self._load_stats_file(target_date)
...
except Exception as e:
logger.debug(f"无法加载今日统计: {e}") # ← DEBUG 级, daemon 日志默认不显示
return DailyStats() # ← 返回全 0 对象
调用方拿到全 0 DailyStats 继续走 `format_text` 推送 → 用户收到的日报内容『大部分无数据』,但 daemon 日志干净得像没事发生。
更糟糕的是,`format_text` 收到全 0 对象也不会抛错——它会渲染一串 `封禁: 0 / 攻击链: 0 / 高危 IP: 0`,看起来格式正常,但全是 0。
修复 — 3 处同步:
# src/report/daily.py:216-221
except Exception as e:
logger.warning(f"日报-加载今日统计失败 ({target_date}): {type(e).__name__}: {e}")
return DailyStats()
# src/report/daily.py:230 文件不存在时
if not stats_file.exists():
logger.warning(f"日报-统计文件不存在 ({target_date}): {stats_file}")
return DailyStats()
# src/report/daily.py:239 字段白名单过滤后
filtered = {k: v for k, v in raw.items() if k in WHITELIST_FIELDS}
missing = WHITELIST_FIELDS - set(filtered.keys())
if missing:
logger.warning(f"日报-字段缺失: {missing} 现有字段: {set(raw.keys())}")
dev box 验证:
场景1 - 老 schema (有 total_blocked 但无 ips_banned):
WARNING: 字段缺失: {'banned_ips', 'ips_banned'} 现有字段: ['total_blocked', ...]
场景2 - 文件不存在:
WARNING: 日报-统计文件不存在 (2026-09-01): /var/lib/security-monitor/daily_stats/...
关键洞察 2:`logger.debug` 和 `logger.warning` 之间的鸿沟 = 「运维人员能不能定位」。我的 daemon 用 INFO 级日志,DEBUG 级默认丢弃。任何 fallback / except / default-value 路径都必须用 WARNING 以上——否则用户级 bug 永远埋着。
问题 3 — AST 扫描发现 2 处同源漏修(Phase 81,2026-09-02)
78.1 + 78.2 修完后我以为完了。直到我写了 audit 脚本扫描整个 src/report/ 目录。
# scripts/audit_phase_78_79.py (新增, 426 行) — 核心检测器 T1
import ast
def detect_silent_fallback(tree):
"""检测 except Exception + logger.debug/pass/return [] 的反模式"""
findings = []
for node in ast.walk(tree):
if isinstance(node, ast.ExceptHandler):
body_text = ast.unparse(node.body)
if 'logger.debug' in body_text or 'pass' in body_text:
findings.append({
'type': 'T1_silent_fallback',
'lineno': node.lineno,
'body': body_text[:200],
})
return findings
跑了一下:
$ python3 scripts/audit_phase_78_79.py src/report/
扫描 src/report/daily.py:
T1_silent_fallback:
- line 33 _load_top_risky_ips except Exception + logger.debug + return []
- line 61 _load_attack_chains except Exception + logger.debug + return []
T2_dual_schema_fallback: (无)
T3_diag_contract: PASS
T4_dataclass_whitelist: PASS
扫描 src/report/periodic.py:
T1_silent_fallback: (无)
T2_dual_schema_fallback:
- line 138 WeeklyStats.total_blocked 累加读 ips_banned ← Phase 78.1 修复点
- line 424 MonthlyStats.total_blocked 累加读 ips_banned ← Phase 78.1 修复点
T3_diag_contract: PASS
T4_dataclass_whitelist: PASS
总结: T1+T3+T4 = 0, T2 = 2 PASS
我愣了 30 秒。Phase 78.2 修 load_today_stats 时,我漏了同文件同模式的 2 处辅助函数:`_load_top_risky_ips` 和 `_load_attack_chains`。它们失败时同样静默,同样返回 `[]`,同样是用户看不到告警。
这就是类教训 #33:「修复一处后必须 AST 审计同文件其他位置」。
修复 — 同源 2 处同步:
# src/report/daily.py:33 _load_top_risky_ips
except Exception as e:
# Phase 81: 不再静默 — 用户报告 '日报大部分无数据' (Bug A),
# 不只是 load_today_stats 静默, 这两个辅助函数也静默.
logger.warning(f"日报-加载信誉库失败 (top_risky_ips): {type(e).__name__}: {e}")
return []
# src/report/daily.py:61 _load_attack_chains (同上, 改 logger.warning)
关键洞察 3:人工 review 漏掉同源 bug 是必然——我修 load_today_stats 时眼睛盯着那 30 行代码,根本没看同文件的另外 60 行辅助函数。AST 扫描不偏不倚,它看整文件所有 except handler,这是它比人工可靠的根本原因。
排查:3 个失败现场 + 为什么这样排查
排查 1 — 为什么 78.1 先修,而不是先查 audit?
因为 78.1 是用户级 bug,部署机实测反馈。78.2 是同源但用户没单独报告 —— 78.2 是我顺手看日报时发现的。优先级 = 用户可见度。
排查 78.1 的步骤:
# 部署机 (10.2.2.36) 一键验证
ssh [email protected]
sudo cat /var/lib/security-monitor/event_stats.json | jq '.ips_banned' # 输出 3
sudo cat /var/lib/security-monitor/weekly_report_2026-08-29.txt | grep "总封禁" # 输出 "总封禁: 0"
# 同一份数据, 0 vs 3, 不是数据问题, 是字段名漂移
dev box 复现脚本:
# scripts/diag_report_field_fix.py (Phase 78 新增, 78 行)
import json
from pathlib import Path
stats = json.loads(Path('/var/lib/security-monitor/event_stats.json').read_text())
print(f"ips_banned: {stats.get('ips_banned', 'MISSING')}")
print(f"total_blocked: {stats.get('total_blocked', 'MISSING')}")
# 期望: ips_banned=3, total_blocked=missing
# 实际: ips_banned=3, total_blocked=missing ← 用户看到的 0 就是从这里来的
关键排查方法:不要从代码读字段,先从 JSON 文件读——文件是真值源,代码是描述。两边对比才能发现漂移。
排查 2 — 为什么 78.2 是 3 处同步而不是 1 处?
我修 load_today_stats 时只动了那个 except handler,但我的目标是「所有静默失败」,不是「这一个静默失败」。所以修完后立刻 `grep -n 'except Exception' src/report/daily.py`:
30: except Exception as e:
32: logger.debug(f"无法加载信誉库数据: {e}")
58: except Exception as e:
60: logger.debug(f"无法加载攻击链数据: {e}")
216: except Exception as e:
217: logger.debug(f"无法加载今日统计: {e}") ← 我修了这一行
grep 完我才发现还有 30/58 两行。但当时我没继续修 —— 我以为「78.2 是修主路径,辅助函数不重要」。这就是 Phase 81 必修的原因。
关键排查方法:grep 出所有同类位置,但只看主路径 = 漏修。AST 扫描比 grep 更进一步——它还能判断 `body` 内容是不是真的是静默 (`logger.debug` / `pass` / `return []`),不会误报普通 except。
排查 3 — 为什么 audit 脚本要 4 类检测器而不是只 T1?
类教训 11/27 各自对应不同的反模式:
| 反模式 | 检测器 | 触发案例 |
|---|---|---|
| except Exception + logger.debug | T1 silent_fallback | Phase 78.2 (Bug A) |
| `.get('field1', .get('field2', 0))` 双 schema | T2 dual_schema_fallback | Phase 78.1 (Bug B) |
| diag 脚本不读 env var / exit code 不规范 | T3 diag_contract | 类教训 12/14 |
| dataclass 白名单吞字段 | T4 dataclass_whitelist | 类教训 27 |
只做 T1 会漏 78.1。只做 T2 会漏 78.2。4 类一起做 = 覆盖类教训 11/12/14/27。
关键洞察 4:AST + regex 双引擎。AST 用来结构性判断(`isinstance(node, ast.ExceptHandler)`),regex 用来模式匹配(`.get('field1', .get('field2', 0))`)。AST 处理「位置/上下文」类反模式更可靠,regex 处理「字符串字面量」类反模式更简洁。
修复:5 项落盘 + 部署机验证
修复 1 — Phase 78.1 (Bug B 字段漂移) `c272bb8` 2026-09-01:3 处 `INT_FIELDS` 白名单 + 双 schema fallback(见上文)。
dev box 验证:
$ sudo venv/bin/python tests/test_phase78_1_field_drift.py
test_old_schema_fallback PASSED
test_new_schema_primary PASSED
test_white_list_intact PASSED
3 passed in 0.42s
修复 2 — Phase 78.2 (Bug A 日报静默) `15379dc` 2026-09-01:3 处同步(见上文)。
修复 3 — Phase 78.3 守卫测试 `50bd4a2` 2026-09-01:2 项守卫 — 日报加载失败告警 + periodic 无 `logger.debug`。
修复 4 — Phase 78 部署机端到端 diag 脚本 `ca9fbe3` 2026-09-01:`scripts/diag_report_field_fix.sh` 一键验证周报/月报/日报字段名是否一致。
修复 5 — Phase 81 audit 脚本 + 同源 2 处修复 `6ada1f6` 2026-09-02:audit 脚本 (426 行) + daily.py:33/61 修复 + 5 守卫测试。
dev box 全量验证:
$ python3 scripts/audit_phase_78_79.py src/report/
T1_silent_fallback: 0
T2_dual_schema_fallback: 2 (Phase 78.1 修复点保留)
T3_diag_contract: 0
T4_dataclass_whitelist: 0
PASS
$ sudo venv/bin/python tests/test_phase81_audit_silent_fallback.py
5 passed in 1.23s
$ sudo venv/bin/python tests/ # 全量
1597 passed, 1 pre-existing failed (test_phase_sm_e2_doc_sync — 因 doc 还没 commit)
关键洞察 5:audit 脚本自身也必须可审计——`T4 self-check` 检测 audit 脚本自己的 except 块不能有 `logger.debug`。写一个检测别人 bug 的工具,自己不能有同类 bug——这是「测试守护者不能有 bug」原则。
反思:4 个反直觉发现 + 1 个新类教训
反直觉 1 — `logger.debug` 不是「详尽日志」,是「静默失败」。
我用 DEBUG 级 fallback 是因为「失败是预期路径(文件可能不存在)」。但「预期」不代表「应该静默」。用户看到日报『大部分无数据』时,他需要知道是数据没了还是代码坏了——DEBUG 级日志两件事都不告诉他。
修复后我意识到:DEBUG 应该留给「成功路径的细节排查」,WARNING 应该覆盖「失败但可恢复」,ERROR 留给「失败且不可恢复」。fallback / except / default 这三类路径默认就是 WARNING 起。
反直觉 2 — 白名单吞字段比静默默认值更隐蔽。
78.1 的双 schema fallback 是「读不到 → 默认 0」。但白名单过滤会把字段直接抹掉——下游拿到的不是 0,是键不存在。再 `.get('ips_banned', 0)` 又拿默认值 0,两层假象叠加。
修复方案是在白名单过滤后显式检测缺失字段 + 打印当前所有字段——这是把「白名单吞字段」从隐性变成显性的关键。
反直觉 3 — 人工 review 漏同源 bug 是必然,AST 不偏不倚。
修 78.2 时我眼睛盯着那 30 行代码,根本没看同文件其他 60 行辅助函数。这是认知偏差——「我修的就是问题所在」让我的注意力锁定在单点。
AST 扫描没有这个偏差——它机械遍历整文件所有 except handler / .get 链 / dataclass 白名单。机械扫描 + 人工理解 = 最佳组合。Phase 81 之后我的工作流变成:修一处 → AST 扫同文件 → 修第二处 → AST 扫整个 src/ → 直到 audit 返回 0。
反直觉 4 — 「用户级 bug 但完全没告警」比「crash」更可怕。
crash 至少会触发告警 / 报警 / on-call。静默失败不会。它会持续几个月、几年,用户渐渐接受「这就是这个工具的样子」,直到某天有人翻数据才发现。
类教训 11/27 之所以要专门写 audit 脚本——因为人不会主动找「我没收到告警」的反例,只有工具能系统性扫描。
新类教训 #33 — 修复一处后必须 AST 审计同文件其他位置:
任何 fallback / except / default-value 路径修复后,**审计整个文件所有同类位置**。
不要相信「主路径修好了其他不重要」——同源 bug 分散在多处是常态。
**AST 扫描不偏不倚;人工 review 因认知偏差必然漏掉同类位置**。
这个类教训直接来自 Phase 78.2 漏 2 处的事实——我修了 load_today_stats 但漏了 _load_top_risky_ips + _load_attack_chains,两天后用 AST 才发现。
尾声
11 天前我在 Phase 77.J 沉淀类教训 11 时以为这只是 Phase 77.J 一次性复盘。11 天后我才意识到,类教训 11 是 security-monitor 整个统计层的设计缺陷——任何「写入端产出字段 → 读取端累加」的模式都中招。
修复路径:用户级 bug → Phase 78.1 (字段漂移) → Phase 78.2 (静默 except) → Phase 78.3 (守卫测试) → Phase 81 (audit 脚本 + 同源 2 处)。每一个 phase 都是下一个 phase 的前置——没有 78.1 的字段漂移就不会发现 78.2 的静默 except,没有 78.2 的修复就不会想到写 audit。
我现在的工作流固化了一条规则:「任何 except Exception 块必须用 WARNING;修完后立刻跑 audit_phase_78_79.py 直到 T1=0。」
这条规则值得写进 SKILL.md——下一个工程系列如果再遇到「静默 0 / silent skip」三件套,audit 脚本模式直接复用。
11 天、4 个 Phase、7 个守卫测试、1601 passed。类教训 11/27 → 类教训 33,不是终点,是 audit 体系的起点。
评论区