A green test is not a running reflex, and a running one is not a placed one

A green test is not a running reflex, and a running one is not a placed one

“绿色”测试不代表运行正常,运行正常也不代表部署到位

We run about 283 scheduled jobs across a handful of machines. Each one is a shell script that declares its own schedule in a header comment, ships its own —test, and gets wired into cron automatically once that test passes. It is a tidy arrangement and it has a hole in it that took us five separate incidents to see, because every one of those incidents looked healthy from every angle we had built. 我们在几台机器上运行着大约 283 个定时任务。每个任务都是一个 shell 脚本,在头部注释中声明自己的调度时间,自带 --test 测试,一旦测试通过,就会自动挂载到 cron 中。这是一个整洁的安排,但它存在一个漏洞,我们经历了五次独立的事故才发现它,因为从我们构建的每一个监控角度来看,这些事故发生时系统看起来都很健康。

Every number, command and file listing below was re-measured on one 16-core Ubuntu 24.04 box while writing this, not quoted from the commit that fixed it. Two of the numbers came out different, and one of the mechanisms did not reproduce at all. Those are the interesting parts. The hole is that “green” is a conjunction pretending to be a single fact. For a scheduled job to be doing its work, at least four things have to be true at once: the test passes, the test asserts the thing the job does, the job is actually scheduled, it is scheduled where its consumer exists. We had instrumentation for (1). We had a habit — a good one — of insisting on (2). We had nothing whatsoever for (4), and it turns out (4) is the one that runs silently for weeks. 下面列出的每一个数字、命令和文件列表都是在撰写本文时在一台 16 核 Ubuntu 24.04 机器上重新测量的,而不是引用自修复该问题的提交记录。其中两个数字结果不同,有一个机制完全无法复现。这些才是最有趣的部分。这个漏洞在于,“绿色”(测试通过)是一个伪装成单一事实的合取命题。一个定时任务要正常工作,必须同时满足至少四个条件:测试通过、测试验证了任务的功能、任务确实被调度了、任务被调度到了其消费者所在的机器上。我们有针对 (1) 的监控手段。我们有一个好习惯,即坚持执行 (2)。但我们对 (4) 毫无防备,而事实证明,(4) 恰恰是那个会悄无声息地运行数周的问题。

1. The edge detector that compared the state against itself

1. 将状态与自身进行比较的边缘检测器

The first one is almost embarrassing in the diff and was invisible for six weeks in production. We have a job that fuses four inputs into one node health label — HEALTHY, DEGRADED, CRITICAL — writes it to a state file, and with —edge prints a line only when the label changes. Cron runs it every five minutes; a separate log records the transitions. The —edge path did this: 第一个问题在代码差异(diff)中看起来几乎令人尴尬,但在生产环境中却隐形了六周。我们有一个任务,将四个输入融合为一个节点健康标签(HEALTHY, DEGRADED, CRITICAL),将其写入状态文件,并使用 --edge 参数仅在标签发生变化时打印一行日志。Cron 每五分钟运行一次该任务;另一个独立的日志记录状态转换。--edge 的逻辑如下:

write_state "$label" # $STATE now holds the new label
prev=$(cat "$STATE") # ...and prev is read from it
[ "$prev" = "$label" ] && exit 0

prev is read after the write. It equals $label by construction. The equality test held on every single run, —edge exited 0 with empty output on every real transition, and the transition log could not append. What makes it worth writing about is not the ordering bug — you can see that one — it is that every liveness signal we had said the job was fine, and each of those signals was correct. The cron entry existed. The process ran every five minutes. The state file’s mtime was current, because the reflex touches it unconditionally on every successful evaluation, which is deliberate and right: we separate ran from changed precisely so that a long stable value doesn’t read as a dead job. Exit code 0. Nothing to alert on. The only observable was a log that had stopped growing — and a transition log that is quiet looks exactly like a machine that is behaving. prev 是在写入之后读取的。根据逻辑,它必然等于 $label。相等性测试在每次运行时都成立,--edge 在每次实际状态转换时都以退出码 0 且无输出结束,导致转换日志无法追加内容。值得一提的不是这个顺序错误(你一眼就能看出来),而是我们所有的活跃度信号都显示任务运行正常,且每一个信号都是正确的。Cron 条目存在,进程每五分钟运行一次,状态文件的修改时间(mtime)也是最新的,因为反射机制在每次成功评估时都会无条件触碰它——这是刻意且正确的做法:我们将“运行”与“变更”分开,正是为了防止长时间稳定的值被误读为任务已死。退出码为 0,没有任何报警。唯一可观察到的现象是日志停止增长——而一个安静的转换日志看起来就像机器运行正常一样。

The fix is to read before writing and to serialize the pair. But the second half of that fix is the part I’d have missed: 修复方法是先读取再写入,并对这对操作进行序列化。但修复的后半部分是我可能会忽略的:

$ python3 -c " a={m for m in range(2,60,5)}; b={m for m in range(2,60,15)} print(sorted(a & b))"
[2, 17, 32, 47]

This job is scheduled 2-59/5. A different job — a vitality roll-up — is scheduled 2-59/15, and force-refreshes the health label by invoking the same tool. So at minutes 2, 17, 32 and 47 of every hour, two writers of the same state file fire in the same second. Four times an hour, by schedule, not by luck. With no lock, an interleave that catches the state file truncated hands the reader an empty prev, and an empty prev never equals a real label — a spurious edge. Those are the only lines the log ever managed to produce. 该任务的调度时间是 2-59/5。另一个任务(活力汇总任务)的调度时间是 2-59/15,它通过调用同一个工具强制刷新健康标签。因此,在每小时的第 2、17、32 和 47 分钟,同一个状态文件的两个写入者会在同一秒触发。每小时四次,这是由调度决定的,而不是巧合。由于没有锁,如果交错执行导致读取时状态文件被截断,读取者就会得到一个空的 prev,而空的 prev 永远不会等于真实的标签——从而产生了一个虚假的边缘。这些就是日志中仅存的几行记录。

2. The honesty gate that could go red because the reflex ran

2. 因为反射运行而变红的“诚实门”

We landed that fix and the deployed —test immediately failed with: live-fusion leg stamped a LIVE artifact. Nothing was wrong. The test runs the tool in a sandboxed HOME and asserts that no live sense file moved — a leak detector, so a sandboxed run can’t corrupt real state. All five “moved” artifacts had mtime 20:02:01. This tool’s cron is 2-59/5. The 20:02 tick had fired during the test. The gate compares five mtimes across a sandbox run, and a move there has two causes it cannot tell apart from one sample: a leaking sandbox, or the job’s own scheduled run stamping the same five files. 我们部署了修复程序,但部署后的 --test 立即失败,报错:live-fusion leg stamped a LIVE artifact。其实并没有问题。测试在沙盒 HOME 环境中运行该工具,并断言没有实时感知文件被移动——这是一个泄漏检测器,确保沙盒运行不会破坏真实状态。所有五个“被移动”的工件修改时间都是 20:02:01。该工具的 cron 调度是 2-59/5。20:02 的触发点正好在测试期间。该门控机制比较沙盒运行前后的五个 mtime,如果发现移动,它无法通过单次采样区分两种原因:是沙盒泄漏,还是任务自身的定时运行触碰了这五个文件。

It reported the first, and structurally could only ever report the first — a detector whose verdict names one of two indistinguishable causes is not measuring, it is asserting. The fix is not a smarter comparison. Distinguish by repeating, not by guessing. A leak fails deterministically — its own writes move the artifacts on every attempt. A collision does not repeat. So on a mismatch, re-arm and run the sandbox once more; only a second mismatch is a verdict, and the pass prints why it was attributed rather than swallowing it. 它报告了第一种情况,而且从结构上讲,它永远只能报告第一种——一个将两种无法区分的原因归咎于其中之一的检测器,不是在测量,而是在断言。修复方法不是进行更聪明的比较,而是通过重复来区分,而不是猜测。泄漏是确定性失败——它的写入在每次尝试时都会移动工件。而碰撞不会重复发生。因此,当出现不匹配时,重新准备并再次运行沙盒;只有第二次不匹配才算作判定,且通过时会打印出归因结果,而不是将其吞掉。