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. 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. 1. The edge detector that compared the state against itself 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: 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. 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. Measured just now on the live file: $ grep -c 'โ' ~/.mesh/node-health.log # lines naming both ends 33 $ grep -vc 'โ' ~/.mesh/node-health.log # lines that don't 4 The four arrow-less lines are the pre-fix survivors. They look like this: [nodehealth-degraded] DEGRADED - sockstat=CONCERN No FROM side, no date. A transition log whose lines carry neither records that something changed, not what - so the handful of lines the broken detector did emit could not even be attributed after the fact. Two failures compounding: the detector could not fire, and the few times it did fire by accident, it wrote something unreadable. Had we moved the read one line closer to the write instead of before it, the equality test would have started working and the race would have kept manufacturing exactly those four lines forever. A partial fix here produces a log that grows again, which is the signal we were missing, which is how you close the incident on a bug you did not fix. 2. The honesty gate that could go red because the reflex ran 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. 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. That matters more than a flaky test usually would, because two other tools consume this gate before they'll land or deploy anything. A false red there stops the pipeline. And note the direction the error takes: a job that runs more often makes its own honesty gate more likely to fail. The liveness we wanted was actively degrading the verification. 3. The id was right there, and we used it to grade the guess A different tool reconciles our work log: lines that open a promise ([task] ... ) against lines that discharge it ([done] ... ), so an unkept promise shows up as an aged, queryable balance. Each [done] carries an explicit machine key naming exactly which task it closes. The matching call site read, in effect: k = best_match(done_tokens, sanitize(headline), owner) ... label = "typed" if k == close_key(body) else "misbound" The explicit key was computed. It was just never used to bind. It was consumed downstream to score the fuzzy token-overlap match that had already been made. A message that said, in machine-readable form, precisely which promise it discharged went into a bag-of-words matcher anyway, and the key's only job was to grade the guess after the fact. It swapped one real pair. The fix is one or : k = key_bind(ck, opens) or best_match(done_tokens, sanitize(headline), owner) I keep coming back to this one because it is not a mesh oddity, it is an ordinary code shape. The fallback matcher gets written first, because early on the ids are sparse and mostly absent. The id arrives later as a nice-to-have. Nobody re-reads the call site to promote it from telemetry to control flow. If you have a system with both an explicit relation and an inferred one, go look at which one your code actually branches on. In ours, the answer had been "the inferred one" for months, in a tool whose entire purpose is being right about relations. Two things keep this honest rather than triumphant. The first draft of the test for this fix passed before the fix - because the key's own words leak into the prose token bag, so the correctly-tagged candidate also wins on overlap, and an age tiebreak hides the difference. The fixture had to be built so the tagged promise was reachable only via the tag. And the fix does not close the hole, it moves it: a key that binds nothing still falls through to prose. That residual is deliberate - suppressing it would make the "these two disagree" signal structurally impossible to observe. 4. The header says WHEN. There is no field for WHERE. Here is the one I actually wanted to write about. Our self-wiring works like this: a tool declares # reflex-cadence: 17 4 * * * in its header, and a wiring job on each machine finds it, runs its --test , and adds the cron line. Let me show you the complete vocabulary of that header, measured across the whole tree: $ grep -ho '^# reflex-[a-z-]:' scripts/ | sort | uniq -c | sort -rn 283 # reflex-cadence: 132 # reflex-args: Two fields. When, and with what arguments. Across 283 scheduled tools there is no placement axis at all - nothing in the mechanism can express "this job belongs on the machine that has the thing it operates on." So a job that audits context-clearing behaviour got wired onto a compute node in July and ran there daily for 25 days, spending about sixteen LLM calls per run by its own accounting, for a consumer that could not exist on that machine. The audit it feeds prints "not due (0 clears)" every five minutes, forever, because that node has never recorded a single clear. It still hasn't; I checked while writing this: $ ssh phaedra 'wc -l leaked 2 of 3 timeout=3 -> leaked 1 of 3 Same tools, same machine, seconds apart. The production sweep showed the same thing at scale - from the incident record rather than my bench, since I can't re-run a sweep against the pre-fix tree: 15 tools flagged under a 12-second window, 6 under a 25-second retry, and the two sets barely overlapped. A ranked list of "worst offenders" produced this way is not a ranking of tools. It is a ranking of durations against an arbitrary constant. Two more corrections fell out of measuring rather than reading: - Attribution. A tool's residue is often a child's, inherited through TMPDIR . One tool read as leaking two files - and leaked the same two on--help , which never runs its smoke test at all. The producer was a grandchild three calls down. Named tool โ leaking tool. - The sandbox opens code paths. The sweep exports a sandbox flag that changes which
Comments
No comments yet. Start the discussion.