From 86774c7116fe1b86614d1314204068f39c54a548 Mon Sep 17 00:00:00 2001 From: Taleef Date: Wed, 9 Sep 2026 15:46:55 -0400 Subject: [PATCH 1/2] fix(run): a run is orphaned when it predates the process, not when it is 30 minutes old MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- backend-ts/src/routes/runs.ts | 22 +++- backend-ts/src/run/backfill-scale.ts | 6 +- backend-ts/src/run/recover-stuck-runs.test.ts | 105 +++++++++++++++++- backend-ts/src/run/recover-stuck-runs.ts | 100 ++++++++++++++++- backend-ts/src/server.ts | 67 +++++++++++ backend-ts/src/stores/run-store.ts | 19 +++- docs/DEPLOY.md | 22 +++- docs/JOURNAL.md | 61 ++++++++++ 8 files changed, 387 insertions(+), 15 deletions(-) diff --git a/backend-ts/src/routes/runs.ts b/backend-ts/src/routes/runs.ts index 702751a0..e619cf60 100644 --- a/backend-ts/src/routes/runs.ts +++ b/backend-ts/src/routes/runs.ts @@ -122,10 +122,24 @@ function externalTriggeredBy(raw: unknown): string { // The store factory selects the SQLite floor or the Postgres ceiling (when DATABASE_URL is set) and // runs schema init once per env. CANONICAL schema/migrations stay Taleef-owned (CLAUDE.md). // -// Boot recovery: an ALL_PROGRAMS/SITE run is advanced by an in-process `ctx.waitUntil` task that does -// NOT survive a container restart, so a run interrupted by a restart is stuck RUNNING forever. The -// first runs access in a process fires a best-effort sweep that fails such stuck runs. It is -// fire-and-forget (never blocks or fails the request) and time-thresholded (never touches a live run). +// Boot recovery, SECOND trigger. An ALL_PROGRAMS/SITE run is advanced by an in-process +// `ctx.waitUntil` task that does NOT survive a container restart, so a run interrupted by a restart is +// stuck RUNNING forever. `server.ts` sweeps once at startup on a Postgres stack; this fires on the +// first runs access in a process, and is the ONLY trigger on a stack without DATABASE_URL. +// +// Both run on a Postgres boot, because they hold different `env` objects and the `WeakSet` below is +// keyed on identity. That is harmless: `failStuckRuns` re-checks `status = 'RUNNING'` under the row +// lock, so the loser returns no rows and writes no duplicate RUN_RECOVERED. +// +// It was the ONLY trigger until 2026-09-09, and that had two consequences. An orphan stayed visible as +// RUNNING until somebody happened to open the runs page — sixteen hours, once. And because the cutoff +// was a flat 30 minutes sized for a "~5-6 min" run, the sweep failed a HEALTHY six-measure nightly at +// 98.7% complete the moment the page was opened. `orphanThresholdMs` now ANCHORS the cutoff to this +// process's boot, so neither trigger can reach past the moment the process booted. ("Anchors", not +// "widens": on a fresh boot the window is about a second wide, and it only exceeds the old 30 minutes +// once the process has been up that long.) +// +// Fire-and-forget: never blocks or fails the request. const sweptForOrphans = new WeakSet(); async function store(env: RunsEnv): Promise { const stores = await getStores(env); diff --git a/backend-ts/src/run/backfill-scale.ts b/backend-ts/src/run/backfill-scale.ts index bd08d212..7fa5f831 100644 --- a/backend-ts/src/run/backfill-scale.ts +++ b/backend-ts/src/run/backfill-scale.ts @@ -63,8 +63,10 @@ export async function backfillScalePopulation(deps: ScaleBackfillDeps, args: Sca // double-writes. To re-seed with a different --subjects, roll back first (see header). // Only treat COMPLETED runs as fully seeded. A run in RUNNING or FAILED status means a prior // invocation crashed between createRun and finalizeRun — we must not skip that measure, or the - // dashboard will aggregate a partial population. The orphaned partial run will be marked FAILED - // by failStuckRuns after 30 min; the new COMPLETED run then becomes the rollup source. + // dashboard will aggregate a partial population. The orphaned partial run is marked FAILED by the + // recovery sweep on the NEXT process start (the cutoff is that process's boot — not a 30-minute + // age, which is what this said before 2026-09-09); the new COMPLETED run then becomes the rollup + // source either way, since this filter only counts COMPLETED. const seededMeasures = new Set( (await deps.runStore.listRuns(100_000)) .filter((r) => r.triggeredBy === SCALE_TRIGGER && r.status === "COMPLETED" && r.scopeId) diff --git a/backend-ts/src/run/recover-stuck-runs.test.ts b/backend-ts/src/run/recover-stuck-runs.test.ts index 3a455722..a1d91017 100644 --- a/backend-ts/src/run/recover-stuck-runs.test.ts +++ b/backend-ts/src/run/recover-stuck-runs.test.ts @@ -15,7 +15,7 @@ import { SqliteRunStore } from "../stores/sqlite/run-store-sqlite.ts"; import { SqliteCaseEventStore } from "../stores/sqlite/case-event-store-sqlite.ts"; import type { CreateRunInput } from "../stores/run-store.ts"; import type { AlertChannel, RunAlert } from "./alert-channel.ts"; -import { recoverStuckRuns } from "./recover-stuck-runs.ts"; +import { recoverStuckRuns, orphanThresholdMs } from "./recover-stuck-runs.ts"; const sampleRun = (): CreateRunInput => ({ scopeType: "ALL_PROGRAMS", @@ -234,3 +234,106 @@ test("Fable M15: finalizeRun does not resurrect a run already FAILED by the swee } } }); + +/** + * Drive `recoverStuckRuns` against the real SQLite store with NO explicit threshold, so the wiring's + * default (`orphanThresholdMs`) is what decides. Returns the ids it recovered plus each run's status. + */ +async function sweepWith( + bootedAt: number, + runsToCreate: readonly { label: string; startedAt: number }[], +): Promise<{ recovered: string[]; statusOf: Record }> { + const dbPath = join(tmpdir(), `workwell-recover-${crypto.randomUUID()}.sqlite`); + const db = await createSqliteD1(dbPath); + await db.exec(RUN_STORE_FLOOR_DDL.replace(/\n/g, " ")); + const runs = new SqliteRunStore(db); + const events = new SqliteCaseEventStore(db); + try { + const ids = new Map(); + for (const r of runsToCreate) { + const created = await runs.createRun({ ...sampleRun(), startedAt: new Date(r.startedAt).toISOString() }); + await runs.markRunning(created.id); // QUEUED → RUNNING, leaving claimed_by NULL as the real path does + ids.set(r.label, created.id); + } + const recovered = await recoverStuckRuns({ runs, events, bootedAt }); + const statusOf: Record = {}; + for (const [label, id] of ids) statusOf[label] = (await runs.getRun(id))?.status; + const labelOf = new Map([...ids].map(([label, id]) => [id, label])); + return { recovered: recovered.map((r) => labelOf.get(r.id) ?? r.id), statusOf }; + } finally { + try { + rmSync(dbPath, { force: true }); + } catch { + /* best effort */ + } + } +} + +// The two halves of the 2026-09-09 incident need OPPOSITE fixtures — demonstrating that the flat +// 30-minute default misses a young orphan requires a recent boot, and that it kills a healthy long +// run requires an old one — so they cannot share a test. The previous 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 claimed a mechanism it did not test. + +test("a run created BEFORE boot is swept even when it is far younger than the old flat threshold", async () => { + // The deploy-mid-run case, and the one the flat 30-minute default provably missed: the orphan is + // 25 minutes old, so `failStuckRuns`'s own default would leave it RUNNING for ever (both triggers + // are one-shot per process). Reverting the wiring to `failStuckRuns(olderThanMs, …)` fails here. + const bootedAt = Date.now() - 20 * 60 * 1000; + const { recovered, statusOf } = await sweepWith(bootedAt, [ + { label: "orphan", startedAt: bootedAt - 5 * 60 * 1000 }, // 25 min old — under the flat 30 min + ]); + assert.deepEqual(recovered, ["orphan"], "a pre-boot run is orphaned at ANY age, not only past 30 minutes"); + assert.equal(statusOf.orphan, "FAILED"); +}); + +test("a run created AFTER boot survives however long it has been running", async () => { + // The half that broke the pilot: an 88-minute nightly is healthy, and the flat 30-minute default + // failed it at 98.7% complete. Setting CUTOFF_MARGIN_MS or the age term so the cutoff lands after + // boot fails here. + const bootedAt = Date.now() - 90 * 60 * 1000; + const { recovered, statusOf } = await sweepWith(bootedAt, [ + { label: "live", startedAt: bootedAt + 2 * 60 * 1000 }, // 88 min old, started after boot + ]); + assert.deepEqual(recovered, [], "a long-running LIVE run is never swept"); + assert.equal(statusOf.live, "RUNNING"); +}); + +test("the cutoff sits BEFORE boot, not after: a run started moments after boot survives", async () => { + // Pins the SIGN of CUTOFF_MARGIN_MS, which nothing else does. With the margin inverted the cutoff + // lands a second AFTER boot and this run — started 200ms into the process — is swept. + const bootedAt = Date.now() - 10 * 60 * 1000; + const { recovered, statusOf } = await sweepWith(bootedAt, [ + { label: "justAfterBoot", startedAt: bootedAt + 200 }, + { label: "justBeforeBoot", startedAt: bootedAt - 60 * 1000 }, + ]); + assert.deepEqual(recovered, ["justBeforeBoot"], "the boundary falls between the two, on the pre-boot side"); + assert.equal(statusOf.justAfterBoot, "RUNNING"); +}); + +test("a clock that moved BACKWARDS sweeps nothing, rather than sweeping everything", async () => { + // The critical guard, and the only one whose failure is unbounded. `Math.max(0, …)` — the previous + // clamp — turned a negative age into a threshold of 0, which makes the store's cutoff `Date.now()` + // and matches EVERY unclaimed RUNNING row: the 2026-09-09 incident reproduced by an NTP step. The + // fixture puts boot an hour in the future of `now`, which is what a backward step looks like. + const bootedAt = Date.now() + 60 * 60 * 1000; + const { recovered, statusOf } = await sweepWith(bootedAt, [ + { label: "live", startedAt: Date.now() - 5 * 60 * 1000 }, + { label: "old", startedAt: Date.now() - 10 * 60 * 60 * 1000 }, + ]); + assert.deepEqual(recovered, [], "an untrustworthy clock must sweep NOTHING"); + assert.equal(statusOf.live, "RUNNING"); + assert.equal(statusOf.old, "RUNNING"); +}); + +test("orphanThresholdMs with no arguments measures THIS process's real boot", async () => { + // The production default `BOOTED_AT` is otherwise never evaluated under assertion: every test above + // injects `bootedAt`, so `const BOOTED_AT = 0` (or a sign slip, or seconds-for-milliseconds) ships + // green while production sweeps nothing at all — or everything. + const uptimeMs = process.uptime() * 1000; + const threshold = orphanThresholdMs(); + assert.ok( + threshold >= uptimeMs - 50 && threshold <= uptimeMs + 5_000, + `expected a threshold within a few seconds of this process's uptime (${Math.round(uptimeMs)}ms), got ${threshold}ms`, + ); +}); diff --git a/backend-ts/src/run/recover-stuck-runs.ts b/backend-ts/src/run/recover-stuck-runs.ts index fa6555b6..abd12630 100644 --- a/backend-ts/src/run/recover-stuck-runs.ts +++ b/backend-ts/src/run/recover-stuck-runs.ts @@ -21,6 +21,13 @@ export interface RecoverStuckRunsDeps { events: CaseEventStore; /** Optional alert fan-out (#264). Default = console-only when omitted. */ alertChannels?: readonly AlertChannel[]; + /** + * The process boot instant the cutoff is measured from. Production leaves it unset and the real one + * is used. It exists so a test can drive the DEFAULT threshold path against a real store: passing + * the threshold in as an argument instead leaves `orphanThresholdMs()` unexercised, which is how the + * first version of that test passed with the wiring removed. + */ + bootedAt?: number; } /** @@ -31,12 +38,103 @@ export interface RecoverStuckRunsDeps { * Best-effort: callers run it fire-and-forget on boot. Emits one WORKWELL_ALERT per recovered run * (#264) so orphaned failures are not silent. */ +/** + * When THIS process started, from the runtime's own uptime rather than module-load time. + * + * Module load is close enough on both current entrypoints (each imports this eagerly), but a lazily + * loaded route would stamp a module-load constant at FIRST REQUEST, putting the cutoff after boot and + * sweeping this process's own live runs — the exact bug this file exists to fix, reintroduced + * silently. `process.uptime()` closes that specific hole. + * + * It is NOT a general guarantee, and the previous wording here claimed one. `process.uptime()` is + * monotonic while `Date.now()` is not, so the two disagree after anything that moves the wall clock: + * an NTP step, a hypervisor clock correction, or a host suspend (Linux `CLOCK_MONOTONIC` does not + * advance while suspended, so after a 2h suspend this lands 2h AFTER the real boot). Every such case + * makes the computed age wrong, which is why `orphanThresholdMs` refuses to sweep rather than + * trusting it. + */ +const BOOTED_AT = Date.now() - Math.round(process.uptime() * 1000); + +/** + * The threshold returned when the clock cannot be trusted: 100 years, so `now - threshold` lands in + * the 1920s and matches no real `started_at`. It is a value rather than a null return so the QUEUED + * half of `failStuckRuns` — which has its own independent 6-hour threshold — still runs. + */ +const SWEEP_NOTHING_MS = 100 * 365 * 24 * 60 * 60 * 1000; + +/** + * How much earlier than boot to place the cutoff, absorbing the gap between computing this age and the + * store applying it against its own `Date.now()`. Without it the effective cutoff lands a fraction of + * a millisecond AFTER boot — the dangerous direction, because it can sweep a run this process started + * in that instant. A second early can only miss an orphan that began in the final second of the + * previous process, which the next restart picks up. + */ +const CUTOFF_MARGIN_MS = 1000; + +/** + * The age a RUNNING run must exceed to be treated as orphaned, for a sweep happening now. + * + * The whole rule is "started before this process booted". A run that began earlier cannot be advanced + * by this process — its in-process task died with whatever process created it — so it is orphaned at + * any age. A run that began later is live and must never be swept however long it runs. + * + * There is deliberately NO minimum. A floor can only push the cutoff EARLIER than boot, and earlier + * than boot protects nothing: everything after boot is already protected by the age term. All a floor + * does is suppress legitimate recoveries — with the old 30-minute one, a container that redeployed 20 + * minutes into a nightly booted, swept with a cutoff 30 minutes before boot, and left the orphan it + * was there to catch. Both triggers are one-shot per process, so nothing caught it afterwards either. + * + * THE CUTOFF DOES NOT ADVANCE. `now` cancels: the effective cutoff is `bootedAt - CUTOFF_MARGIN_MS` + * for the whole life of the process, however long it runs. So that margin is also this process's + * entire tolerance for clock skew BETWEEN HOSTS: if a restart reschedules the container onto a host + * whose clock is more than a second behind the previous one, an orphan the previous container started + * has `started_at` after the cutoff and is not swept — for as long as this process lives. The old + * flat threshold, whose cutoff did advance, tolerated that; this trades it away for never killing a + * live run, which is the direction the 2026-09-09 incident argues for. The exposure is bounded by the + * next restart (every push to `main` redeploys), not permanent. + * + * NOT covered, and stated rather than implied: a run orphaned by its own task dying inside a process + * that keeps running. Its `started_at` is after boot, so this never sweeps it. A timestamp cannot + * distinguish it from a healthy long run — but a PROGRESS signal can, and one already exists without + * any schema change: `outcomes.evaluated_at` is written continuously by a running evaluation and + * `outcomes` is indexed on `run_id`, so "RUNNING and no outcome row in N minutes" is available at the + * cost of a per-run scan. (`run_logs` is NOT that signal — it is event-driven, and a healthy chunk + * loop writes almost nothing.) That is the cheap follow-up, deliberately not in this change. The + * previous flat threshold "handled" this case only by also killing healthy runs, which is what broke + * the pilot's nightly on 2026-09-09. + * + * `started_at` is stamped at `createRun` (QUEUED), not at `markRunning`, so "started before boot" is + * really "was CREATED before boot". Nothing today promotes a pre-existing QUEUED row to RUNNING in a + * later process — the one path that would, `claimNextQueuedRun`, stamps `claimed_by`, which the sweep + * excludes. That is luck rather than design: a claiming worker added on a path that does not stamp + * `claimed_by` would make this sweep a live run whose row was queued before the restart. + * + * ASSUMES ONE CONTAINER at a time, the same assumption `admin/scheduler.ts` documents for its + * debounce: with two replicas, the newer one's boot cutoff would sweep runs the older one is still + * advancing. `claimed_by` is no protection there — the `ctx.waitUntil` path leaves it NULL. + * + * A NEGATIVE age means the wall clock moved backwards since `BOOTED_AT` was stamped, and in that + * state the process cannot tell its own runs from a previous process's. It sweeps NOTHING. The + * previous version clamped to `Math.max(0, …)`, which chose the opposite: a threshold of 0 makes the + * store's cutoff `Date.now()`, and `started_at < now` matches EVERY unclaimed RUNNING row — the + * 2026-09-09 incident reproduced exactly, by a clock step 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. + */ +export function orphanThresholdMs(now = Date.now(), bootedAt = BOOTED_AT): number { + const age = now - bootedAt; + if (!Number.isFinite(age) || age < 0) return SWEEP_NOTHING_MS; + return age + CUTOFF_MARGIN_MS; +} + export async function recoverStuckRuns( deps: RecoverStuckRunsDeps, olderThanMs?: number, unclaimedQueuedOlderThanMs?: number, ): Promise { - const recovered = await deps.runs.failStuckRuns(olderThanMs, unclaimedQueuedOlderThanMs); + const recovered = await deps.runs.failStuckRuns( + olderThanMs ?? orphanThresholdMs(Date.now(), deps.bootedAt), + unclaimedQueuedOlderThanMs, + ); const channels = deps.alertChannels ?? resolveAlertChannels({}); const successful: RecoveredRun[] = []; diff --git a/backend-ts/src/server.ts b/backend-ts/src/server.ts index 53923e18..0e04c472 100644 --- a/backend-ts/src/server.ts +++ b/backend-ts/src/server.ts @@ -86,6 +86,73 @@ async function main(): Promise { // `official-measures=on` on the boot line the whole time. WORKWELL_OFFICIAL_MEASURES: process.env.WORKWELL_OFFICIAL_MEASURES, }; + + // Boot recovery, HERE, once, because this is the only place that actually knows the process just + // started. A run is advanced by an in-process task that does not survive a restart, so a run left + // RUNNING by the previous process is orphaned and must be failed and audited. + // + // It also runs lazily on the first `/api/runs` access (`routes/runs.ts`), which is what covers a host + // that does not boot through this file — `mieweb dev`, the tests. That lazy trigger was the ONLY + // trigger until 2026-09-09, and the incident had two halves: an orphan stayed visible as RUNNING for + // sixteen hours because nobody opened the runs page, and when somebody did, the flat 30-minute + // cutoff failed a HEALTHY nightly at 98.7%. Both paths now share `orphanThresholdMs`, which is + // anchored to this process's boot. + // + // Deliberately NOT on the scheduler tick: that function opens with a compute-cost guardrail + // (`shouldSkipTickWithoutDb`) precisely to keep a serverless Postgres asleep, and a sweep on every + // 15-minute tick would undo it. Once per process is the right cadence — a run can only be orphaned + // by a restart, and a restart is what gets us here. + // + // Gated on DATABASE_URL for ONE reason: `schedulerEnv` is built from `process.env` and carries no + // `DB` binding, so on a stack without DATABASE_URL (`MIEWEB_TARGET=local`, the PR1 smoke test) + // `getStores` throws "StoresEnv.DB is required for the SQLite floor" — a permanent red line in the + // boot log of a supported configuration, and a false lead during triage. Those hosts are covered by + // the lazy trigger in `routes/runs.ts` instead. + // + // The gate passes on exactly the stacks that have a serverless Postgres, so this is now the first + // thing to touch the database: it opens the pool and runs the DDL at boot, waking Neon earlier than + // the scheduler's cost guardrail otherwise would. That is an accepted cost of having a boot sweep at + // all, not something the gate avoids — an earlier version of this comment claimed the opposite. + if ((process.env.DATABASE_URL ?? "").trim()) { + void (async () => { + const { getStores } = await import("./stores/factory.ts"); + const { recoverStuckRuns } = await import("./run/recover-stuck-runs.ts"); + const { resolveAlertChannels } = await import("./run/alert-channel.ts"); + + // Retried, because the most likely failure here is the most likely state of a serverless + // Postgres at boot: a cold start refusing the first connection. Without a retry that single + // rejection loses the sweep for the ENTIRE process — the scheduler tick deliberately does not + // sweep, so the only remaining trigger is somebody opening the runs page, which is exactly the + // sixteen-hour failure this boot sweep was added to remove. Three attempts over ~90s; the + // cutoff is anchored to boot, so a later attempt is no less correct than the first. + const delaysMs = [15_000, 30_000, 45_000]; + for (let attempt = 0; attempt < delaysMs.length; attempt++) { + try { + const stores = await getStores(schedulerEnv); + const recovered = await recoverStuckRuns({ + runs: stores.runs, + events: stores.events, + alertChannels: resolveAlertChannels(schedulerEnv), + }); + if (recovered.length > 0) { + console.warn(`[workwell] boot recovery: ${recovered.length} orphaned run(s) failed and audited`); + } + return; + } catch (e: unknown) { + const msg = e instanceof Error ? e.message : String(e); + const last = attempt === delaysMs.length - 1; + console.error( + `[workwell] boot recovery attempt ${attempt + 1}/${delaysMs.length} failed${last ? "" : ", retrying"}: ${msg}`, + ); + if (last) return; + await new Promise((r) => setTimeout(r, delaysMs[attempt]).unref()); + } + } + })().catch((e: unknown) => + console.error("[workwell] boot recovery failed", e instanceof Error ? e.message : e), + ); + } + const schedulerInterval = setInterval(() => { void schedulerTick(schedulerEnv).catch((e: unknown) => console.error("[workwell] scheduler tick error", e instanceof Error ? e.message : e), diff --git a/backend-ts/src/stores/run-store.ts b/backend-ts/src/stores/run-store.ts index 185e40c8..d4bad078 100644 --- a/backend-ts/src/stores/run-store.ts +++ b/backend-ts/src/stores/run-store.ts @@ -71,9 +71,16 @@ export interface RunLogRow { } /** - * Runs left RUNNING longer than this are treated as orphaned by a restart (see - * {@link RunStore.failStuckRuns}). Far beyond the longest real run (~5-6 min for ALL_PROGRAMS on - * the Postgres ceiling), so the boot-time sweep can never fail a legitimately in-flight run. + * The store-level DEFAULT age for treating a RUNNING run as orphaned (see + * {@link RunStore.failStuckRuns}), used only when a caller passes no threshold. + * + * **The recovery sweep does not use it.** `recoverStuckRuns` always passes `orphanThresholdMs` + * (`run/recover-stuck-runs.ts`), which is this process's own age: a run that started before this + * process booted cannot be advanced by it and is orphaned at any age, and a run that started after is + * live however long it runs. This constant was once justified as "far beyond the longest real run + * (~5-6 min for ALL_PROGRAMS)", which stopped being true — the pilot's six-measure nightly runs for + * over an hour, and a flat cutoff failed a healthy one at 98.7% complete. Any NEW caller relying on + * this default inherits that hazard; pass an explicit threshold instead. */ export const STUCK_RUN_THRESHOLD_MS = 30 * 60 * 1000; @@ -121,8 +128,10 @@ export interface RunStore { * by a `ctx.waitUntil` task that does NOT survive a container restart, leaving the run RUNNING * forever. Furthermore, without a claiming worker, bare QUEUED runs sit indefinitely. Scoped to * **unclaimed** runs (`claimed_by IS NULL`): `claimNextQueuedRun` stamps claimed_by, so a - * legitimately CLAIMED worker job is never recovered. `seed:%` runs are excluded. Run once per - * process on the first runs access; thresholds guard against failing a live run. Returns the + * legitimately CLAIMED worker job is never recovered. `seed:%` runs are excluded. Swept once per + * process, from two triggers (`server.ts` at boot on a Postgres stack, and the first runs access); + * both pass `orphanThresholdMs`, which is what guards a live run — this interface's own + * `olderThanMs` default does NOT, and once failed a healthy nightly at 98.7%. Returns the * recovered runs with their previous status so the caller can write an `audit_event` per run * distinguishing the two cases. */ diff --git a/docs/DEPLOY.md b/docs/DEPLOY.md index 9881b507..18e61f8f 100644 --- a/docs/DEPLOY.md +++ b/docs/DEPLOY.md @@ -943,8 +943,26 @@ events `SEGMENT_UPDATED`/`SEGMENT_DELETED`) from the Configure Groups editor or Evidence bytes deliberately remain on the in-container `fs` binding for now; the Maui workflow omits the four `WORKWELL_BUCKET_S3_*` variables, so evidence is lost whenever the container is recreated. -**Unclaimed QUEUED run recovery:** In addition to recovering in-process `RUNNING` runs orphaned by a container -restart (30-minute threshold), boot recovery (`failStuckRuns`) sweeps unclaimed `QUEUED` runs whose +**Stuck-run recovery runs ONCE PER PROCESS, and its cutoff is that process's boot.** A `RUNNING` run +created before the current process started cannot be advanced by it (the in-process job died with the +previous container), so it is failed and audited at any age; a run created after boot is live and is +never swept, however long it runs. It fires at startup (`server.ts`, Postgres stacks) and on the first +`/api/runs` access. Until 2026-09-09 the cutoff was a flat 30 minutes, which both missed orphans +younger than that and failed a healthy 88-minute nightly at 98.7% complete. + +Two operational consequences worth knowing before changing the deployment shape: + +- **One container at a time is assumed.** With two replicas, a newly booted one would sweep runs the + older one is still advancing — `claimed_by` is no defence, because the async run path leaves it + NULL. Rolling deploys that overlap replicas need a liveness signal first (see + `run/recover-stuck-runs.ts`). +- **The cutoff does not advance during a process's life**, so the one-second margin is also the whole + tolerance for clock skew between hosts. If a restart lands the container on a host whose clock is + more than a second behind the previous one, an orphan from the previous container is not swept until + the next restart. Deliberate: the alternative direction kills live runs. + +**Unclaimed QUEUED run recovery:** In addition to the `RUNNING` sweep above, boot recovery +(`failStuckRuns`) sweeps unclaimed `QUEUED` runs whose `claimed_by` worker ID is null and whose timestamp is older than 6 hours (`UNCLAIMED_QUEUED_THRESHOLD_MS`). Because live deployments do not run a separate claiming worker daemon, any run left queued without a worker is recovered to `FAILED` with an audited `RUN_RECOVERED` event and alert. An audit failure restores the run so the next boot retries. diff --git a/docs/JOURNAL.md b/docs/JOURNAL.md index b97eb476..c56cfd43 100644 --- a/docs/JOURNAL.md +++ b/docs/JOURNAL.md @@ -73,6 +73,67 @@ and still runs the case upsert, so it would have bought little while the writes next lever now that they do not, and it should be turned on as a measured step rather than folded in here. +### The stuck-run sweep, and two rewrites before it was right + +Both of the day's nightly failures had already been diagnosed, and neither was the worker restarting on +its own: 2026-09-08 was a merge redeploying mid-run, and 2026-09-09 was the recovery sweep marking a +HEALTHY run FAILED at 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 identical `completedAt` of `14:29:19.919Z`. + +The cutoff was a flat 30 minutes, justified in a comment as "far beyond the longest real run (~5-6 min +for ALL_PROGRAMS)". That justification expired when the six-measure nightly started taking 88 minutes, +and nothing in the query distinguished 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 earlier stayed visible as +RUNNING for about sixteen hours — nobody opened the runs page — and why the healthy run died the moment +somebody did. + +**The first fix was a net regression, and two reviewers independently refused it.** It kept the 30 +minutes as a floor under a process-age term. But 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. Adding a guaranteed boot sweep made it worse by moving the +one sweep to process age ≈ 0, where the floor is entirely in control: a run started 02:00 with a +redeploy at 02:20 gets a cutoff of 01:50, and the orphan is missed. Both triggers are one-shot per +process, so nothing catches it afterwards. For the commonest orphan — a deploy mid-run, the 2026-09-08 +incident exactly — the "fix" made a recoverable case permanently unrecoverable. + +The rule is now just "created before this process booted", with no floor at all, measured from +`process.uptime()` so a lazily loaded module cannot stamp it at first request instead of at boot. + +**The second version was rejected too, by all three reviewers on the same line.** `Math.max(0, …)` +looks like a bounds check and is actually a fail-open: it binds only when the wall clock has moved +BACKWARDS since boot was stamped — an NTP step, a hypervisor correction, a suspend — and in that state +the process cannot tell its own runs from a previous process's. A threshold of 0 makes the store's +cutoff `Date.now()`, and `started_at < now` matches every unclaimed RUNNING row. The clamp reproduced +the very incident it sits inside, triggered by a clock instead of by a stale constant. An untrustworthy +clock now sweeps nothing: missing a sweep costs a stale row until the next restart, while taking the +wrong one kills the nightly. + +**Two properties are worth recording because they are traded away deliberately.** The cutoff does not +advance — `now` cancels, leaving `boot - 1s` for 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. And a run +whose task dies inside a still-live process is not covered at all, because no timestamp can separate it +from a healthy long run. A progress signal can, and one exists without any schema change: +`outcomes.evaluated_at` is written continuously and `outcomes` is indexed on `run_id`. That is the cheap +follow-up. `run_logs` is not that signal — it is event-driven, and a healthy chunk loop writes almost +nothing to it. + +**The test was vacuous three times, which is the fourth instance of that shape this week.** The first +version never called the code under test. The second drove the real store but passed the threshold in +explicitly, so the default path stayed unexercised — it passed with the wiring removed. The third looked +right and still could not fail for either constant it existed to protect: `BOOTED_AT = 0` left it green +while production would sweep nothing ever, and a margin anywhere in `[-5min, +10min)` left it green +while a negative one places the cutoff after boot. Its own comment also described its fixture wrongly — +the "young orphan" was 55 minutes old, so the flat threshold would have swept it too. + +The two halves of the incident need opposite fixtures — showing that a flat 30 minutes misses a young +orphan needs a recent boot, showing that it kills a healthy long run needs an old one — so they cannot +share a test. There are now five, and each was verified to FAIL under the specific mutation it exists to +catch: the wiring reverted, `BOOTED_AT` zeroed, the margin inverted, and the fail-open clamp restored. +Worth noting that the first mutation run reported the clamp as caught when it was not: the `perl` +pattern had silently failed to match, so the harness checking for vacuous tests was itself vacuous. A +mutation script needs to assert that its pattern matched before it reports anything. + ## 2026-09-08 (evening) — the first six-measure run, a rate that was the wrong measure's, and an e2e suite that had stopped testing the pilot The flip deployed, and the programs page still read 0.0% on the four new measures. That part was From 203facd3699910e1ae1d2ced6a33a9dfd7497377 Mon Sep 17 00:00:00 2001 From: Taleef Date: Wed, 9 Sep 2026 16:33:05 -0400 Subject: [PATCH 2/2] fix(run): the retry loop cannot outlive shutdown, and the tests catch six mutations instead of three MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- backend-ts/src/routes/runs.ts | 6 +- backend-ts/src/run/recover-stuck-runs.test.ts | 95 ++++++++++++++++--- backend-ts/src/run/recover-stuck-runs.ts | 29 ++++-- backend-ts/src/server.ts | 54 ++++++++--- docs/JOURNAL.md | 40 +++++++- 5 files changed, 187 insertions(+), 37 deletions(-) diff --git a/backend-ts/src/routes/runs.ts b/backend-ts/src/routes/runs.ts index e619cf60..94822268 100644 --- a/backend-ts/src/routes/runs.ts +++ b/backend-ts/src/routes/runs.ts @@ -135,9 +135,9 @@ function externalTriggeredBy(raw: unknown): string { // RUNNING until somebody happened to open the runs page — sixteen hours, once. And because the cutoff // was a flat 30 minutes sized for a "~5-6 min" run, the sweep failed a HEALTHY six-measure nightly at // 98.7% complete the moment the page was opened. `orphanThresholdMs` now ANCHORS the cutoff to this -// process's boot, so neither trigger can reach past the moment the process booted. ("Anchors", not -// "widens": on a fresh boot the window is about a second wide, and it only exceeds the old 30 minutes -// once the process has been up that long.) +// process's boot, so neither trigger can reach past the moment the process booted. "Anchors", not +// "widens": the swept set is everything created before boot, back to the epoch — an eighteen-hour-old +// orphan goes on the first sweep — while everything created after boot is spared however old it gets. // // Fire-and-forget: never blocks or fails the request. const sweptForOrphans = new WeakSet(); diff --git a/backend-ts/src/run/recover-stuck-runs.test.ts b/backend-ts/src/run/recover-stuck-runs.test.ts index a1d91017..7595523c 100644 --- a/backend-ts/src/run/recover-stuck-runs.test.ts +++ b/backend-ts/src/run/recover-stuck-runs.test.ts @@ -15,7 +15,12 @@ import { SqliteRunStore } from "../stores/sqlite/run-store-sqlite.ts"; import { SqliteCaseEventStore } from "../stores/sqlite/case-event-store-sqlite.ts"; import type { CreateRunInput } from "../stores/run-store.ts"; import type { AlertChannel, RunAlert } from "./alert-channel.ts"; -import { recoverStuckRuns, orphanThresholdMs } from "./recover-stuck-runs.ts"; +import { recoverStuckRuns, orphanThresholdMs, bootInstant } from "./recover-stuck-runs.ts"; + +/** Captured at module load, to prove the production boot instant precedes it (see the last test). */ +const TEST_MODULE_LOADED_AT = Date.now(); +/** Mirrors CUTOFF_MARGIN_MS; kept local so the test states the value it expects rather than importing it. */ +const CUTOFF_MARGIN_MS_FOR_TEST = 1000; const sampleRun = (): CreateRunInput => ({ scopeType: "ALL_PROGRAMS", @@ -299,16 +304,73 @@ test("a run created AFTER boot survives however long it has been running", async assert.equal(statusOf.live, "RUNNING"); }); -test("the cutoff sits BEFORE boot, not after: a run started moments after boot survives", async () => { - // Pins the SIGN of CUTOFF_MARGIN_MS, which nothing else does. With the margin inverted the cutoff - // lands a second AFTER boot and this run — started 200ms into the process — is swept. +test("the cutoff sits BEFORE boot by the full margin, not at boot and not after it", async () => { + // Pins the margin's SIGN and its MAGNITUDE. An earlier version only placed a run 200ms after boot, + // which left `CUTOFF_MARGIN_MS = 0` (and anything up to 199) green — the cutoff exactly at boot, + // with no absorption at all for the gap between computing the threshold and the store applying it + // against its own clock. `withinMargin` sits 500ms BEFORE boot and must survive, which is only true + // while the margin actually pushes the cutoff back past it. const bootedAt = Date.now() - 10 * 60 * 1000; const { recovered, statusOf } = await sweepWith(bootedAt, [ { label: "justAfterBoot", startedAt: bootedAt + 200 }, - { label: "justBeforeBoot", startedAt: bootedAt - 60 * 1000 }, + { label: "withinMargin", startedAt: bootedAt - 500 }, + { label: "beforeMargin", startedAt: bootedAt - 60 * 1000 }, ]); - assert.deepEqual(recovered, ["justBeforeBoot"], "the boundary falls between the two, on the pre-boot side"); + assert.deepEqual(recovered, ["beforeMargin"], "only the run older than boot MINUS the margin is swept"); assert.equal(statusOf.justAfterBoot, "RUNNING"); + assert.equal(statusOf.withinMargin, "RUNNING", "the margin must place the cutoff strictly before boot"); +}); + +test("recoverStuckRuns with NO injected bootedAt uses this process's real boot", async () => { + // The production signature. Every other store-driven test passes `bootedAt` in, so the wiring's + // `deps.bootedAt` default — and with it the real `BOOTED_AT` — was never exercised end to end. + const dbPath = join(tmpdir(), `workwell-recover-${crypto.randomUUID()}.sqlite`); + const db = await createSqliteD1(dbPath); + await db.exec(RUN_STORE_FLOOR_DDL.replace(/\n/g, " ")); + const runs = new SqliteRunStore(db); + const events = new SqliteCaseEventStore(db); + try { + // The live run is placed just after the REAL boot instant rather than at `now`, and that is the + // whole point of the test. A run created at `now` survives under any cutoff at or before now, so + // it cannot tell the real boot from a substitute — `deps.bootedAt ?? Date.now()` (a cutoff one + // second back) spares it too, and passed an earlier version of this test. A run sitting just + // after boot is spared ONLY by a cutoff actually anchored to boot. + // + // That requires this process to have more uptime than the margin, or "just after boot" and "just + // before now" are the same instant. Waited for explicitly so the discrimination is deterministic + // rather than dependent on how long the suite happened to take to get here. + while (process.uptime() * 1000 < 2 * CUTOFF_MARGIN_MS_FOR_TEST) { + await new Promise((r) => setTimeout(r, 100)); + } + const realBoot = bootInstant(Date.now(), process.uptime()); + + // Created an hour before this process existed: orphaned under the real boot instant. + const orphan = await runs.createRun({ ...sampleRun(), startedAt: new Date(Date.now() - 60 * 60 * 1000).toISOString() }); + await runs.markRunning(orphan.id); + // Created 100ms after this process booted — after boot, but further back than the margin. + const live = await runs.createRun({ ...sampleRun(), startedAt: new Date(realBoot + 100).toISOString() }); + await runs.markRunning(live.id); + + const recovered = await recoverStuckRuns({ runs, events }); // no bootedAt, no threshold + + assert.deepEqual(recovered.map((r) => r.id), [orphan.id]); + assert.equal((await runs.getRun(live.id))?.status, "RUNNING"); + } finally { + try { + rmSync(dbPath, { force: true }); + } catch { + /* best effort */ + } + } +}); + +test("bootInstant subtracts uptime in SECONDS from a millisecond clock", async () => { + // The arithmetic of `BOOTED_AT` itself, which no runtime assertion can pin precisely (a test's own + // process has only a second or two of uptime, so a wrong sign or a seconds/milliseconds mix-up + // lands within any tolerance loose enough not to be flaky). Extracted so it can be checked exactly. + assert.equal(bootInstant(1_000_000, 30), 970_000, "30s of uptime is 30,000ms BEFORE now"); + assert.equal(bootInstant(1_000_000, 0), 1_000_000, "a just-started process booted now"); + assert.ok(bootInstant(1_000_000, 30) < 1_000_000, "boot is in the past, never the future"); }); test("a clock that moved BACKWARDS sweeps nothing, rather than sweeping everything", async () => { @@ -326,14 +388,25 @@ test("a clock that moved BACKWARDS sweeps nothing, rather than sweeping everythi assert.equal(statusOf.old, "RUNNING"); }); -test("orphanThresholdMs with no arguments measures THIS process's real boot", async () => { - // The production default `BOOTED_AT` is otherwise never evaluated under assertion: every test above - // injects `bootedAt`, so `const BOOTED_AT = 0` (or a sign slip, or seconds-for-milliseconds) ships - // green while production sweeps nothing at all — or everything. +test("orphanThresholdMs with no arguments measures PROCESS start, not module load", async () => { + // The production default `BOOTED_AT` is otherwise never evaluated under assertion, and a loose band + // here is not enough: `const BOOTED_AT = Date.now()` at module load — the exact regression the + // source comment warns about — lands within a few seconds of uptime and passes it. + // + // What separates the two is that this process necessarily spent time starting (node boot, tsx, + // imports) BEFORE this module was loaded. So a correct boot instant is measurably earlier than the + // moment this test file was evaluated; a module-load stamp is not. const uptimeMs = process.uptime() * 1000; const threshold = orphanThresholdMs(); + const derivedBoot = Date.now() - threshold + CUTOFF_MARGIN_MS_FOR_TEST; + assert.ok( threshold >= uptimeMs - 50 && threshold <= uptimeMs + 5_000, - `expected a threshold within a few seconds of this process's uptime (${Math.round(uptimeMs)}ms), got ${threshold}ms`, + `expected a threshold near this process's uptime (${Math.round(uptimeMs)}ms), got ${threshold}ms`, + ); + assert.ok( + derivedBoot <= TEST_MODULE_LOADED_AT - 50, + `boot (${derivedBoot}) must precede this module's load (${TEST_MODULE_LOADED_AT}) by more than the ` + + `50ms of startup that certainly elapsed; a module-load stamp would make them equal`, ); }); diff --git a/backend-ts/src/run/recover-stuck-runs.ts b/backend-ts/src/run/recover-stuck-runs.ts index abd12630..45c67a0e 100644 --- a/backend-ts/src/run/recover-stuck-runs.ts +++ b/backend-ts/src/run/recover-stuck-runs.ts @@ -46,14 +46,29 @@ export interface RecoverStuckRunsDeps { * sweeping this process's own live runs — the exact bug this file exists to fix, reintroduced * silently. `process.uptime()` closes that specific hole. * - * It is NOT a general guarantee, and the previous wording here claimed one. `process.uptime()` is - * monotonic while `Date.now()` is not, so the two disagree after anything that moves the wall clock: - * an NTP step, a hypervisor clock correction, or a host suspend (Linux `CLOCK_MONOTONIC` does not - * advance while suspended, so after a 2h suspend this lands 2h AFTER the real boot). Every such case - * makes the computed age wrong, which is why `orphanThresholdMs` refuses to sweep rather than - * trusting it. + * It is NOT a general guarantee, and two earlier versions of this comment claimed one. `process.uptime()` + * is monotonic while `Date.now()` is not, so the two disagree after anything that moves the wall clock, + * and the negative-age guard below catches only SOME of that: + * + * - A host suspend. Linux `CLOCK_MONOTONIC` does not advance while suspended, so after a 2h suspend + * this lands 2h AFTER the real boot. The computed age stays POSITIVE, the guard does not fire, and + * the cutoff sits 2h past boot — sweeping live runs started in that window. Not defended against + * here; a container host that suspends is outside the deployment model, and detecting it needs a + * second clock source. + * - A backward wall-clock step (NTP, hypervisor correction). The guard fires only while the clock is + * still behind this stamp. Once real time advances past it the age is positive again, so a run + * CREATED during the stepped-back interval keeps a `started_at` before the cutoff and can be swept + * while live. The exposure is bounded by the size of the step and by the sweep being once-per-process, + * but it is real and it is not covered. + * + * Both are honest residual risk rather than handled cases. What the guard does cover is the + * catastrophic one: an age so wrong it would sweep EVERYTHING. */ -const BOOTED_AT = Date.now() - Math.round(process.uptime() * 1000); +export function bootInstant(nowMs: number, uptimeSeconds: number): number { + return nowMs - Math.round(uptimeSeconds * 1000); +} + +const BOOTED_AT = bootInstant(Date.now(), process.uptime()); /** * The threshold returned when the clock cannot be trusted: 100 years, so `now - threshold` lands in diff --git a/backend-ts/src/server.ts b/backend-ts/src/server.ts index 0e04c472..177e903c 100644 --- a/backend-ts/src/server.ts +++ b/backend-ts/src/server.ts @@ -87,6 +87,12 @@ async function main(): Promise { WORKWELL_OFFICIAL_MEASURES: process.env.WORKWELL_OFFICIAL_MEASURES, }; + // Declared HERE rather than beside `shutdown()` below, because the boot-recovery retry loop reads + // it. It only works by TDZ timing otherwise — the loop's first read happens after an `await`, so + // `main()` has already run the declaration — and a later edit that removes an await ahead of it + // would turn that into a ReferenceError at boot. + let stopping = false; + // Boot recovery, HERE, once, because this is the only place that actually knows the process just // started. A run is advanced by an in-process task that does not survive a restart, so a run left // RUNNING by the previous process is orphaned and must be failed and audited. @@ -117,22 +123,36 @@ async function main(): Promise { void (async () => { const { getStores } = await import("./stores/factory.ts"); const { recoverStuckRuns } = await import("./run/recover-stuck-runs.ts"); - const { resolveAlertChannels } = await import("./run/alert-channel.ts"); + const { resolveAlertChannels, emitAlert } = await import("./run/alert-channel.ts"); // Retried, because the most likely failure here is the most likely state of a serverless // Postgres at boot: a cold start refusing the first connection. Without a retry that single // rejection loses the sweep for the ENTIRE process — the scheduler tick deliberately does not // sweep, so the only remaining trigger is somebody opening the runs page, which is exactly the - // sixteen-hour failure this boot sweep was added to remove. Three attempts over ~90s; the - // cutoff is anchored to boot, so a later attempt is no less correct than the first. - const delaysMs = [15_000, 30_000, 45_000]; - for (let attempt = 0; attempt < delaysMs.length; attempt++) { + // sixteen-hour failure this boot sweep was added to remove. THREE attempts, at t=0s, t=15s and + // t=45s (the backoffs BETWEEN them are 15s and 30s — one delay fewer than there are attempts, + // which an earlier version got wrong, leaving a third delay that could never be reached and a + // comment claiming ~90s for what is 45s). The cutoff is anchored to boot, so a later attempt is + // no less correct than the first. + const backoffsMs = [15_000, 30_000]; + const attempts = backoffsMs.length + 1; + const channels = resolveAlertChannels(schedulerEnv); + for (let attempt = 0; attempt < attempts; attempt++) { + // Never START a sweep once shutdown has begun. `shutdown()` force-exits after the grace + // window without awaiting this, so a sweep begun here can flip rows to FAILED and be killed + // before `recoverStuckRuns` writes their RUN_RECOVERED events — a state change with no audit + // entry, which the hard rule does not allow. Abandoning the sweep is free: the cutoff belongs + // to this process, and the next process sweeps from its own boot. + if (stopping) { + console.warn("[workwell] boot recovery abandoned — shutdown in progress; the next boot sweeps"); + return; + } try { const stores = await getStores(schedulerEnv); const recovered = await recoverStuckRuns({ runs: stores.runs, events: stores.events, - alertChannels: resolveAlertChannels(schedulerEnv), + alertChannels: channels, }); if (recovered.length > 0) { console.warn(`[workwell] boot recovery: ${recovered.length} orphaned run(s) failed and audited`); @@ -140,12 +160,25 @@ async function main(): Promise { return; } catch (e: unknown) { const msg = e instanceof Error ? e.message : String(e); - const last = attempt === delaysMs.length - 1; + const last = attempt === attempts - 1; console.error( - `[workwell] boot recovery attempt ${attempt + 1}/${delaysMs.length} failed${last ? "" : ", retrying"}: ${msg}`, + `[workwell] boot recovery attempt ${attempt + 1}/${attempts} failed${last ? "" : ", retrying"}: ${msg}`, ); - if (last) return; - await new Promise((r) => setTimeout(r, delaysMs[attempt]).unref()); + if (last) { + // Exhaustion is ALERTED, not just logged. Returning quietly here would leave the process + // serving traffic with no sweep having run and nothing anywhere saying so — the failure + // is invisible precisely when an orphan is most likely to exist. + await emitAlert(channels, { + kind: "RUN_RECOVERED", + at: new Date().toISOString(), + status: "FAILED", + message: + `Boot recovery failed after ${attempts} attempts (${msg}). No stuck-run sweep ran in this ` + + `process; an orphaned run stays RUNNING until the next restart.`, + }).catch(() => {}); + return; + } + await new Promise((r) => setTimeout(r, backoffsMs[attempt]).unref()); } } })().catch((e: unknown) => @@ -164,7 +197,6 @@ async function main(): Promise { // can actually reach the suspended state instead of being re-woken on every period. }, 15 * 60 * 1000); - let stopping = false; const shutdown = (signal: string): void => { if (stopping) return; stopping = true; diff --git a/docs/JOURNAL.md b/docs/JOURNAL.md index c56cfd43..0dd04581 100644 --- a/docs/JOURNAL.md +++ b/docs/JOURNAL.md @@ -128,11 +128,41 @@ the "young orphan" was 55 minutes old, so the flat threshold would have swept it The two halves of the incident need opposite fixtures — showing that a flat 30 minutes misses a young orphan needs a recent boot, showing that it kills a healthy long run needs an old one — so they cannot -share a test. There are now five, and each was verified to FAIL under the specific mutation it exists to -catch: the wiring reverted, `BOOTED_AT` zeroed, the margin inverted, and the fail-open clamp restored. -Worth noting that the first mutation run reported the clamp as caught when it was not: the `perl` -pattern had silently failed to match, so the harness checking for vacuous tests was itself vacuous. A -mutation script needs to assert that its pattern matched before it reports anything. +share a test. Worth noting that the first mutation run reported the fail-open clamp as caught when it +was not: the `perl` pattern had silently failed to match, so the harness checking for vacuous tests was +itself vacuous. A mutation script must assert that its pattern matched before it reports anything. + +**A fourth review, after the PR was open, found three more mutations that were still green** — and the +fix for each is the same shape. `CUTOFF_MARGIN_MS = 0` passed, because the only run placed 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 it. `BOOTED_AT = Date.now()` at module load passed — the exact +regression the source comment warns about — because a band drawn around `process.uptime()` is loose +enough to contain a module-load stamp; what separates them is that this process necessarily spent time +starting before the module loaded, so the test now asserts the derived boot instant precedes the test +file's own load. And `deps.bootedAt ?? Date.now()` passed, because a run created at `now` is spared by +any cutoff at or before now: the live run is now placed just after the REAL boot instant, which only a +cutoff genuinely anchored to boot spares, and the test waits until the process has more uptime than the +margin so that discrimination is deterministic rather than luck. The `BOOTED_AT` arithmetic itself moved +into an exported `bootInstant(nowMs, uptimeSeconds)` so a sign flip or a seconds-for-milliseconds slip +can be caught exactly, which no runtime tolerance loose enough to be stable ever could. + +Six mutations, six failures, verified individually. + +The same review found the retry loop had three defects of its own, all in code written to satisfy an +earlier review finding: a third backoff that could never be reached (three attempts need two gaps, so +the loop ran 45 seconds while its comment claimed 90), exhaustion that returned silently so a process +could serve traffic with no sweep and nothing anywhere saying so, and no check for shutdown — 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. Exhaustion now alerts, the +loop refuses to start a sweep once shutdown has begun, and `stopping` moved above the block rather than +being reachable only by TDZ timing. + +Two clock hazards are now stated as residual rather than handled, because the previous comment claimed +the negative-age guard covered them and it does not. After a host suspend the computed age stays +positive and the cutoff lands past boot; and after a backward clock step, a run created during the +stepped-back interval keeps a `started_at` before the cutoff and can be swept while live once real time +advances again. Both are bounded and neither is defended against. What the guard does cover is the +catastrophic case — an age so wrong it would sweep everything. ## 2026-09-08 (evening) — the first six-measure run, a rate that was the wrong measure's, and an e2e suite that had stopped testing the pilot