fix(run): a run is orphaned when it predates the process, not when it is 30 minutes old - #545
Merged
Merged
Conversation
added 2 commits
September 9, 2026 15:46
… is 30 minutes old The stuck-run sweep marked a healthy six-measure nightly FAILED at 118,430 of 120,000 (98.7%), at the same instant as an unrelated eighteen-hour-old orphan — one sweep marked both, and the two rows carry an identical completedAt. The cutoff was a flat 30 minutes, justified as "far beyond the longest real run (~5-6 min for ALL_PROGRAMS)". That expired when the nightly began taking 88 minutes, and nothing in the query separated a live run from an orphaned one. The sweep also only fired on the first /api/runs access in a process, which is why a genuine orphan had stayed visible as RUNNING for about sixteen hours, and why the healthy run died the moment somebody opened the page. A run created before this process booted cannot be advanced by it, so it is orphaned at any age; one created after is live however long it runs. There is deliberately no floor: a floor can only push the cutoff earlier than boot, and earlier than boot protects nothing, so it purely suppresses legitimate recoveries. Boot is measured from process.uptime() so a lazily loaded module cannot stamp it at first request instead. A clock that has moved backwards now sweeps nothing. The obvious Math.max(0, ...) is a fail-open: it binds only when the wall clock has stepped back since boot was stamped, and a threshold of 0 makes the store's cutoff Date.now(), matching every unclaimed RUNNING row — this incident, reproduced by a clock rather than a stale constant. Missing a sweep costs a stale row until the next restart; taking the wrong one kills the nightly. Also: sweep at startup in server.ts (Postgres stacks) rather than only on first access, with a bounded retry, because a serverless cold start refusing the first connection would otherwise lose the sweep for the whole process and degrade back to the sixteen-hour failure. Two properties are traded away deliberately and documented in DEPLOY.md: the cutoff does not advance, so the one-second margin is also the whole tolerance for inter-host clock skew; and a run whose task dies inside a live process is not covered, since no timestamp separates it from a healthy long run (outcomes.evaluated_at is the cheap follow-up, no schema change needed). Five tests, each verified to fail under the mutation it exists to catch: the wiring reverted, BOOTED_AT zeroed, the margin inverted, and the fail-open clamp restored. The two halves of the incident need opposite fixtures, so they cannot share a test.
… six mutations instead of three Review of the opened PR found three mutations that still left the suite green, and three defects in the retry loop itself — which was code written to satisfy an earlier review finding, and had not been reviewed. Tests: - CUTOFF_MARGIN_MS = 0 passed, because the only run near the boundary sat 200ms AFTER boot, so nothing required the margin to be non-zero. A run 500ms BEFORE boot, which must survive, now pins both its sign and its magnitude. - BOOTED_AT = Date.now() at module load passed — the exact regression the source comment warns about. A band drawn around process.uptime() is loose enough to contain a module-load stamp; what separates them is that the process spent time starting before the module loaded, so the derived boot instant must precede the test file's own load. - deps.bootedAt ?? Date.now() passed, because a run created at `now` is spared by any cutoff at or before now. The live run now sits just after the REAL boot instant, which only a cutoff anchored to boot spares, and the test waits until the process has more uptime than the margin so the discrimination is deterministic rather than luck. - The BOOTED_AT arithmetic moved into an exported bootInstant(nowMs, uptimeSeconds) so a sign flip or a seconds-for-milliseconds slip is caught exactly. No runtime tolerance loose enough to be stable could do that. Six mutations, six failures, verified individually. Retry loop: - Three attempts need two gaps. The third delay could never be reached, so the loop ran 45s while its comment claimed 90s. - Exhaustion returned silently: the process could serve traffic with no sweep having run and nothing anywhere saying so, which is exactly when an orphan is most likely to exist. It now emits an alert. - No shutdown check. A retry waking during the drain window could flip rows to FAILED and be force-exited before their RUN_RECOVERED events were written — a state change with no audit entry. The loop now refuses to start once shutdown has begun, and `stopping` moved above the block rather than being reachable only by TDZ timing. Comments: the negative-age guard does NOT cover a host suspend (the age stays positive and the cutoff lands past boot) or a run created during a backward clock step (its started_at stays before the cutoff). Both are now stated as residual risk instead of being claimed as handled. "The window is about a second wide" was also false — the swept set reaches back to the epoch.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The incident
The stuck-run recovery sweep marked a healthy six-measure nightly
FAILEDat 118,430 of 120,000 — 98.7% — at the same instant as an unrelated eighteen-hour-old orphan. One sweep marked both; the two rows carry the identicalcompletedAtof14:29:19.919Z.Two defects combined:
STUCK_RUN_THRESHOLD_MSwas a flat 30 minutes, justified in a comment as "far beyond the longest real run (~5-6 min for ALL_PROGRAMS)". That stopped being true when the six-measure nightly began taking 88 minutes, and the query (status='RUNNING' AND started_at < now - threshold) has nothing in it that separates a live run from an orphaned one./api/runsaccess in a process. A genuine orphan had earlier stayed visible as RUNNING for ~16 hours because nobody opened the runs page — and the healthy run died the moment somebody did.The rule
A run created before this process booted cannot be advanced by it — its in-process
ctx.waitUntiltask died with whatever process created it — so it is orphaned at any age. A run created after boot is live and is never swept, however long it runs.There is deliberately no floor. A floor can only push the cutoff earlier than boot, and earlier than boot protects nothing (everything after boot is already covered by the age term), so all it does is suppress legitimate recoveries. A first version of this fix kept the 30 minutes as a floor and was rejected in review: with a boot sweep at process age ≈ 0 the floor is entirely in control, so a run started 02:00 with a redeploy at 02:20 gets a cutoff of 01:50 and the orphan is missed — making the commonest case (a deploy mid-run) permanently unrecoverable, since both triggers are one-shot per process.
Boot is measured from
process.uptime()rather than module-load time, so a lazily loaded module cannot stamp it at first request and silently reintroduce the original bug.A clock that moved backwards sweeps nothing
The obvious
Math.max(0, …)is a fail-open. It binds only when the wall clock has stepped back since boot was stamped (NTP step, hypervisor correction, suspend) — exactly when the process cannot tell its own runs from a previous process's. A threshold of0makes the store's cutoffDate.now(), andstarted_at < nowmatches every unclaimed RUNNING row: this incident, reproduced by a clock rather than by a stale constant.Missing a sweep costs a stale RUNNING row until the next restart. Taking the wrong one kills the nightly.
Stated rather than implied
nowcancels, leavingboot − 1sfor the life of the process — so that one second is also the entire tolerance for clock skew between hosts. A container rescheduled onto a host running more than a second behind will not sweep the previous container's orphan until the next restart. The old advancing cutoff tolerated this; the trade buys never killing a live run.outcomes.evaluated_atis written continuously andoutcomesis indexed onrun_id. That is the cheap follow-up. (run_logsis not that signal — it is event-driven, and a healthy chunk loop writes almost nothing to it.)admin/scheduler.tsalready documents for its debounce.claimed_byis no defence — the async run path leaves it NULL.Both are now in
DEPLOY.md, where an operator would look, not only in code comments.Also
server.ts, Postgres stacks) has a bounded 3-attempt retry: the likeliest failure at boot is a serverless cold start refusing the first connection, and a single rejection would otherwise lose the sweep for the entire process — degrading straight back to the sixteen-hour failure, since the scheduler tick deliberately does not sweep.stores/run-store.ts'sfailStuckRunsinterface doc,run/backfill-scale.ts), both still asserting the retracted 30-minute story.Tests
Five, each verified to fail under the specific mutation it exists to catch — the wiring reverted,
BOOTED_ATzeroed,CUTOFF_MARGIN_MSinverted, and the fail-open clamp restored.The two halves of the incident need opposite fixtures — showing a flat 30 minutes misses a young orphan needs a recent boot; showing it kills a healthy long run needs an old one — so they cannot share a test. An earlier single test used a 45-minute-old boot with a 55-minute-old orphan, which the flat default would also have swept: it failed on revert only because the live run died too, and its comment described a mechanism it did not test.
263 tests, 0 failacrosssrc/run/andsrc/routes/runs*;tsc --noEmitclean.Reviewed by three lanes before opening (Gemini 3.8, GLM 5.3, and the in-repo reviewer); the fail-open clamp was found independently by all three.