diff --git a/backend-ts/src/routes/runs.ts b/backend-ts/src/routes/runs.ts index 702751a0..94822268 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": 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(); 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..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 } 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", @@ -234,3 +239,174 @@ 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 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: "withinMargin", startedAt: bootedAt - 500 }, + { label: "beforeMargin", startedAt: bootedAt - 60 * 1000 }, + ]); + 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 () => { + // 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 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 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 fa6555b6..45c67a0e 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,118 @@ 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 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. + */ +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 + * 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..177e903c 100644 --- a/backend-ts/src/server.ts +++ b/backend-ts/src/server.ts @@ -86,6 +86,106 @@ async function main(): Promise { // `official-measures=on` on the boot line the whole time. 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. + // + // 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, 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, 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: channels, + }); + 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 === attempts - 1; + console.error( + `[workwell] boot recovery attempt ${attempt + 1}/${attempts} failed${last ? "" : ", retrying"}: ${msg}`, + ); + 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) => + 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), @@ -97,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/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..0dd04581 100644 --- a/docs/JOURNAL.md +++ b/docs/JOURNAL.md @@ -73,6 +73,97 @@ 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. 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 The flip deployed, and the programs page still read 0.0% on the four new measures. That part was