diff --git a/.changeset/stall-guard-self-test.md b/.changeset/stall-guard-self-test.md new file mode 100644 index 0000000000..b5492b6a54 --- /dev/null +++ b/.changeset/stall-guard-self-test.md @@ -0,0 +1,8 @@ +--- +--- + +ci: the stall guard now proves it still fires (`pnpm check:stall-guard`), and a stalled run's SIGKILL escalation actually runs (#4250). CI-only — releases nothing. + +`scripts/run-with-stall-guard.mjs` gains a `--self-test` that drives it against synthetic stalls — an idle hang, a sync-spinning hang, a hang that never prints a first line, and a descendant that traps SIGTERM — asserting the exit-75 verdict, the idle/ON-CPU classification, the SIGUSR2 stack harvest including the "no report = blocked event loop" inference, full process-group teardown, and the negative direction (a healthy run keeps its own exit status; steady output is never called a stall). Six jobs across five workflows depend on this guard, and until now nothing exercised its firing path between real stalls. + +Writing that harness surfaced a real defect, since fixed: the SIGKILL escalation was armed as an unref'd timer and the guard exited from the direct child's `exit` handler, so the timer never fired. The direct child (`pnpm` → `turbo`, or `sh`) dies on SIGTERM immediately, so any **descendant** that traps SIGTERM outlived the guard — the shape `ObjectKernelConfig.gracefulShutdown` installs in every kernel a test boots. The guard now waits for the process group to actually empty and SIGKILLs the holdouts, naming them in the log. diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 233ad944ab..705916236d 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -385,6 +385,25 @@ jobs: - name: Check every driver runs the shared conformance cases run: pnpm check:driver-conformance + # Stall-guard self-test (#4250). scripts/run-with-stall-guard.mjs is what + # turns a frozen Test Core into a labeled red; six jobs across five + # workflows now route their test steps through it. But it only executes its + # interesting path during an event that is rare (~5-10% of days) and not + # reproducible on demand — so between real stalls there was nothing at all + # asserting it still works, and a guard that has never fired is + # indistinguishable from a guard that does not. A refactor could have + # disarmed CI's only stall detector and every run would have stayed green. + # + # This runs the guard against SYNTHETIC stalls — an idle hang, a + # sync-spinning hang, a hang with no output at all, a SIGTERM-trapping + # descendant — and asserts the verdict, the idle/ON-CPU classification, the + # SIGUSR2 stack harvest (including the "no report = blocked event loop" + # inference), full process-group teardown, and the negative direction: a + # healthy run still propagates its own exit status and steady output is + # never called a stall. ~50s, no build, no network. + - name: Stall-guard self-test + run: pnpm check:stall-guard + - name: Type check (@objectstack/spec) run: pnpm --filter @objectstack/spec exec tsc --noEmit diff --git a/package.json b/package.json index c27935d953..61b65f7b99 100644 --- a/package.json +++ b/package.json @@ -55,7 +55,8 @@ "check:published-files": "node scripts/check-published-files.mjs --self-test && node scripts/check-published-files.mjs", "check:type-check-coverage": "node scripts/check-type-check-coverage.mjs --self-test && node scripts/check-type-check-coverage.mjs", "check:driver-conformance": "node scripts/check-driver-conformance.mjs --self-test && node scripts/check-driver-conformance.mjs", - "check:engine-double-contract": "node scripts/check-engine-double-contract.mjs --self-test && node scripts/check-engine-double-contract.mjs" + "check:engine-double-contract": "node scripts/check-engine-double-contract.mjs --self-test && node scripts/check-engine-double-contract.mjs", + "check:stall-guard": "node scripts/run-with-stall-guard.mjs --self-test" }, "keywords": [ "objectstack", diff --git a/scripts/run-with-stall-guard.mjs b/scripts/run-with-stall-guard.mjs index 42d6d88fa5..c02a217b57 100644 --- a/scripts/run-with-stall-guard.mjs +++ b/scripts/run-with-stall-guard.mjs @@ -47,18 +47,64 @@ // Forensics are best-effort (Linux /proc; every step try/caught) and never // delay the kill by more than ~6s. // +// ## Teardown: SIGTERM, then SIGKILL for real +// +// A stall verdict must leave nothing behind. SIGTERM goes to the whole process +// group; the guard then WAITS for the group to actually empty (polling /proc) +// and SIGKILLs whatever is still standing before it exits. +// +// The wait is the point. The previous shape armed an unref'd +// `setTimeout(SIGKILL, 10s)` and exited from the direct child's 'exit' handler +// -- but the direct child (pnpm -> turbo, or sh) dies on SIGTERM immediately, so +// the guard exited first and the SIGKILL timer never fired. Any DESCENDANT that +// traps SIGTERM outlived the guard. That is not hypothetical here: +// `ObjectKernelConfig.gracefulShutdown` defaults on and registers exactly such a +// handler in every kernel a test boots (#4250's own root-cause pass counted 47 +// kernels and 48 SIGTERM interceptions in a single objectql suite run), so the +// stall most likely to leak workers is the one this guard exists for. +// +// ## Verifying the guard (--self-test) +// +// node scripts/run-with-stall-guard.mjs --self-test +// +// A guard that has never fired is indistinguishable from a guard that does not +// work, and this one only fires on an event that is rare and not reproducible on +// demand. So its firing is exercised on every CI run against SYNTHETIC stalls: +// an idle hang, a sync-spinning hang, a hang that never emits a first line, and +// a SIGTERM-trapping descendant. The self-test asserts the verdict (exit 75), +// the classification (idle vs ON-CPU), the SIGUSR2 harvest including the "no +// report = blocked event loop" inference, full group teardown, and -- in the +// other direction -- that a healthy run still propagates its own exit status and +// that steady output is never mistaken for a stall. +// // Exit status: the child's own code when it finishes; 75 on a declared stall; // 1 when the child dies on a signal this guard did not send. import { spawn } from 'node:child_process'; -import { createWriteStream, readFileSync, readdirSync, existsSync } from 'node:fs'; +import { + createWriteStream, + readFileSync, + readdirSync, + existsSync, + mkdtempSync, + mkdirSync, + rmSync, + writeFileSync, +} from 'node:fs'; import { join } from 'node:path'; +import { tmpdir } from 'node:os'; +import { fileURLToPath } from 'node:url'; const STALL_EXIT_CODE = 75; // EX_TEMPFAIL const CHECK_INTERVAL_MS = 5_000; const SIGKILL_GRACE_MS = 10_000; const argv = process.argv.slice(2); + +// Handled before the option loop below: --self-test takes no --log and must not +// spawn a wrapped command. selfTest() never returns. +if (argv.includes('--self-test')) await selfTest(); + let logPath = ''; let stallMinutes = 10; let reportDir = ''; @@ -130,7 +176,16 @@ function killGroup(signal) { } } -const sleep = (ms) => new Promise((r) => setTimeout(r, ms)); +// A declaration, not a `const`: --self-test runs before the module body +// finishes initializing, and an arrow-const would be in its temporal dead zone. +function sleep(ms) { + return new Promise((r) => setTimeout(r, ms)); +} + +/** Close the log and exit. Hoisted out of the child's 'exit' handler because on + * a stall it is the teardown sequence, not the child's death, that decides when + * the guard may leave. */ +const finish = (status) => log.end(() => process.exit(status)); /** One /proc sample of every process in the child's process group. * Returns Map. */ @@ -237,6 +292,32 @@ async function collectForensics() { return lines.length ? `\n${lines.join('\n')}\n` : ''; } +/** Wait for the process group to actually empty after SIGTERM, then SIGKILL the + * holdouts. Returns the pids that had to be killed (empty = clean shutdown), so + * the log can name them: a process that ignored SIGTERM during a stall is + * evidence about the stall, not noise. */ +async function reapGroup(graceMs) { + const deadline = Date.now() + graceMs; + if (!existsSync('/proc')) { + // Off-Linux we cannot observe the group; wait out the grace, then escalate. + await sleep(graceMs); + killGroup('SIGKILL'); + return []; + } + let survivors = []; + while (Date.now() < deadline) { + try { + survivors = [...sampleGroup().keys()]; + } catch { + survivors = []; + } + if (survivors.length === 0) return []; + await sleep(250); + } + killGroup('SIGKILL'); + return survivors; +} + const watchdog = setInterval(() => { const silentMs = Date.now() - lastOutputAt; if (silentMs < stallMs) return; @@ -264,15 +345,29 @@ ${'═'.repeat(72)} `; process.stdout.write(banner); log.write(banner); - void collectForensics().then((forensics) => { + void collectForensics().then(async (forensics) => { if (forensics) { process.stdout.write(forensics); log.write(forensics); } + // Own the teardown AND the exit: waiting for the group to empty is the only + // way SIGKILL escalation can ever run (the direct child dies on SIGTERM at + // once, and exiting on its death is what used to strand every descendant + // that traps SIGTERM). The child's 'exit' handler defers to this path. killGroup('SIGTERM'); - setTimeout(() => killGroup('SIGKILL'), SIGKILL_GRACE_MS).unref(); + const survivors = await reapGroup(SIGKILL_GRACE_MS); + if (survivors.length) { + const note = + `\n ${survivors.length} process(es) ignored SIGTERM for ${SIGKILL_GRACE_MS / 1000}s ` + + `and were SIGKILLed: ${survivors.join(', ')}\n` + + ' (a stalled process that also refuses SIGTERM is itself a clue — check\n' + + ' the forensics above for what those pids were doing.)\n'; + process.stdout.write(note); + log.write(note); + } + finish(STALL_EXIT_CODE); }); -}, CHECK_INTERVAL_MS); +}, Math.min(CHECK_INTERVAL_MS, Math.max(250, stallMs / 2))); child.on('error', (err) => { clearInterval(watchdog); @@ -282,13 +377,290 @@ child.on('error', (err) => { child.on('exit', (code, signal) => { clearInterval(watchdog); - const finish = (status) => log.end(() => process.exit(status)); if (stalled) { - finish(STALL_EXIT_CODE); - } else if (signal) { + // The stall path owns the exit — it is still reaping the group. Returning + // here is what gives SIGKILL escalation a chance to run at all. + return; + } + if (signal) { console.error(`run-with-stall-guard: command killed by ${signal}`); finish(1); } else { finish(code ?? 1); } }); + +// --------------------------------------------------------------------------- +// Self-test +// --------------------------------------------------------------------------- + +/** SIGKILL every process whose command line mentions `marker`. + * + * The marker is this run's mkdtemp path, which is threaded through the argv of + * every synthetic child — so this matches ONLY processes this self-test + * started. Matching on a program name instead (`node`, `vitest`) would reach + * into whatever else shares the machine, including a parallel agent's test run. + */ +function killByMarker(marker) { + if (!existsSync('/proc')) return 0; + let killed = 0; + for (const entry of readdirSync('/proc')) { + if (!/^\d+$/.test(entry)) continue; + const pid = Number(entry); + if (pid === process.pid) continue; + try { + const cmdline = readFileSync(`/proc/${pid}/cmdline`, 'utf8'); + if (!cmdline.includes(marker)) continue; + process.kill(pid, 'SIGKILL'); + killed++; + } catch { /* vanished, or not ours to read */ } + } + return killed; +} + +/** Run this script as a subprocess and capture its verdict. + * + * 'close' (not 'exit') so the captured output is complete. + * + * The case timeout is not boilerplate. Every stall case here wraps a child that + * hangs FOREVER by construction, so a guard that fails to detect the stall + * never exits — and an unbounded self-test would then hang exactly the way + * #4250 hangs, needing a job timeout and a human to interpret it. That is the + * failure mode this whole script exists to abolish; the verifier must not + * reproduce it. On timeout the case is a labeled red, and the orphaned + * synthetic children are reaped by marker. + */ +function runGuard(args, env = {}, { timeoutMs = 90_000, marker = '' } = {}) { + const selfPath = fileURLToPath(import.meta.url); + return new Promise((resolve) => { + const p = spawn(process.execPath, [selfPath, ...args], { + env: { ...process.env, ...env }, + stdio: ['ignore', 'pipe', 'pipe'], + }); + let out = ''; + let timedOut = false; + const timer = setTimeout(() => { + timedOut = true; + try { p.kill('SIGKILL'); } catch { /* already gone */ } + if (marker) killByMarker(marker); + }, timeoutMs); + p.stdout.on('data', (c) => (out += c)); + p.stderr.on('data', (c) => (out += c)); + p.on('close', (code) => { + clearTimeout(timer); + // Deliberately NO marker sweep here. The teardown case asserts that a + // descendant did NOT survive the guard, and reaping on the way out would + // erase the very leak it looks for — a mutation restoring the pre-fix + // teardown went green while this sweep was in place. Survivors are swept + // once, after every case has been judged. + resolve({ code, out, timedOut }); + }); + }); +} + +/** Exercise the guard against synthetic stalls. Exits 0 / 1; never returns. */ +async function selfTest() { + const dir = mkdtempSync(join(tmpdir(), 'stall-guard-selftest-')); + const linux = existsSync('/proc'); + const failures = []; + const results = []; + + // 3s stall window. The watchdog's poll interval tracks the window + // (min(5s, window/2)), so detection lands ~3-4.5s in rather than waiting out + // a fixed 5s tick — the production 10-minute window still polls every 5s. + const WINDOW = ['--stall-minutes', '0.05']; + + const check = (label, cond, detail) => { + if (cond) { + results.push(` ✓ ${label}`); + } else { + failures.push(label); + results.push(` ✗ ${label}${detail ? ` — ${detail}` : ''}`); + } + }; + + // Arms the SIGUSR2 stack harvest in the synthetic children, exactly as the + // CI steps do. Without this the "no report = blocked loop" inference cannot + // be distinguished from "reports were never enabled". + const reportEnv = (d) => ({ + NODE_OPTIONS: `--report-on-signal --report-signal=SIGUSR2 --report-directory=${d}`, + }); + + try { + // -- 1. A healthy run is untouched: real exit status, both streams tee'd. -- + { + const log = join(dir, 'healthy.log'); + const { code, out } = await runGuard([ + '--log', log, ...WINDOW, '--', + process.execPath, '-e', + "console.log('suite passed'); console.error('a warning on stderr');", dir, + ], {}, { marker: dir }); + const logged = readFileSync(log, 'utf8'); + check('healthy run exits 0', code === 0, `got ${code}`); + check('healthy run is not called a stall', !out.includes('STALL')); + check('stdout and stderr both reach the log', + logged.includes('suite passed') && logged.includes('a warning on stderr'), logged); + } + + // -- 2. A red suite stays red: the child's status, not the wrapper's. -- + // This is the invariant that replaced `| tee` + `set -o pipefail`; if it + // regresses, every failing suite in CI reports green. + { + const { code } = await runGuard([ + '--log', join(dir, 'failing.log'), ...WINDOW, '--', + process.execPath, '-e', "console.log('3 tests failed'); process.exitCode = 3;", dir, + ], {}, { marker: dir }); + check('failing suite propagates its exit code', code === 3, `got ${code}`); + } + + // -- 3. Slow but alive is NOT a stall. Output resets the clock. -- + { + const { code, out } = await runGuard([ + '--log', join(dir, 'slow.log'), ...WINDOW, '--', + process.execPath, '-e', + "let n = 0; const t = setInterval(() => { console.log('still running ' + n); " + + 'if (++n > 12) { clearInterval(t); } }, 400);', dir, + ], {}, { marker: dir }); + check('steady output past the stall window is not a stall', + code === 0 && !out.includes('STALL'), `exit ${code}`); + } + + // -- 4. Idle hang: event loop alive, nothing will ever settle. -- + // The "await-type" stall — a promise that never resolves. + { + const reports = join(dir, 'reports-idle'); + mkdirSync(reports, { recursive: true }); + const res = await runGuard( + ['--log', join(dir, 'idle.log'), ...WINDOW, '--report-dir', reports, '--', + process.execPath, '-e', + "console.log('RUN alpha.test.ts'); console.log('RUN beta.test.ts'); " + + 'setTimeout(() => {}, 1e9);', dir], + reportEnv(reports), { marker: dir }, + ); + const { code, out } = res; + check('idle hang: the guard exits on its own', !res.timedOut, + 'the guard never exited — detection is broken'); + check('idle hang is declared a stall', code === STALL_EXIT_CODE, `exit ${code}`); + check('the verdict quotes the last line seen', + out.includes('last line : RUN beta.test.ts')); + if (linux) { + check('idle hang is classified idle, not on-CPU', + out.includes('idle -- waiting on something that never settles')); + check('a live event loop answers SIGUSR2 with a report', + /SIGUSR2 -> \d+ node process\(es\), [1-9]\d* responded/.test(out)); + } + } + + // -- 5. Sync-spinning hang: event loop BLOCKED. -- + // The inverse inference, and the subtlest claim the script makes: the + // ABSENCE of a diagnostic report is the diagnosis. If report-on-signal + // ever starts answering from off-loop, this is what notices. + if (linux) { + const spinDir = join(dir, 'reports-spin'); + mkdirSync(spinDir, { recursive: true }); + const res = await runGuard( + ['--log', join(dir, 'spin.log'), ...WINDOW, '--report-dir', spinDir, '--', + process.execPath, '-e', + "console.log('RUN gamma.test.ts'); const t = Date.now(); let x = 0; " + + 'while (Date.now() - t < 600000) { x += Math.sqrt(x + 1); }', dir], + reportEnv(spinDir), { marker: dir }, + ); + const { code, out } = res; + check('sync-spinning hang: the guard exits on its own', !res.timedOut, + 'the guard never exited — detection is broken'); + check('sync-spinning hang is declared a stall', code === STALL_EXIT_CODE, `exit ${code}`); + check('sync-spinning hang is classified ON-CPU', + out.includes('ON-CPU -- sync-spinning or GC-thrashing')); + check('a blocked event loop is diagnosed by its SILENCE', + out.includes('NO report -- its event loop is BLOCKED')); + } + + // -- 6. A hang that never prints a first line. -- + // The #4322 shape: a suite wedged during module load emits nothing at + // all, so there is no "last line" to anchor on and nothing for a human + // to notice. The clock must start at spawn, not at first output. + { + const res = await runGuard([ + '--log', join(dir, 'silent.log'), ...WINDOW, '--', + process.execPath, '-e', 'setTimeout(() => {}, 1e9);', dir, + ], {}, { marker: dir }); + const { code, out } = res; + check('no-output hang: the guard exits on its own', !res.timedOut, + 'the guard never exited — detection is broken'); + check('a hang with no output at all is still caught', code === STALL_EXIT_CODE, `exit ${code}`); + check('the no-output case says so instead of quoting a stale line', + out.includes('last line : (no output yet)')); + } + + // -- 7. Teardown reaches a descendant that traps SIGTERM. -- + // ObjectKernelConfig.gracefulShutdown installs exactly this handler in + // every kernel a test boots, so "dies on SIGTERM" cannot be assumed. + // Before the reap loop, the guard exited on the direct child's death and + // left such a descendant running. + if (linux) { + const pidFile = join(dir, 'descendant.pid'); + const script = join(dir, 'traps-sigterm.sh'); + writeFileSync( + script, + 'echo "turbo: running 2 packages"\n' + + `${process.execPath} -e '\n` + + ' require("fs").writeFileSync(process.argv[1], String(process.pid));\n' + + ' process.on("SIGTERM", () => {});\n' + + ' setTimeout(() => {}, 1e9);\n' + + `' "${pidFile}" &\nwait\n`, + ); + const res = await runGuard([ + '--log', join(dir, 'group.log'), ...WINDOW, '--', 'sh', script, + ], {}, { marker: dir }); + const { code, out } = res; + check('SIGTERM-trapping descendant: the guard exits on its own', !res.timedOut, + 'the guard never exited — teardown is broken'); + check('stall with a SIGTERM-trapping descendant still exits 75', + code === STALL_EXIT_CODE, `exit ${code}`); + // "Dead" means gone OR a zombie: SIGKILL leaves the entry in /proc until + // the (now reparented) process is reaped, and in a container PID 1 may be + // slow to do it. A zombie runs no code and holds no handles — the thing + // this asserts is that it is not still RUNNING. Poll briefly so the + // verdict does not depend on reap latency. + const pid = Number(readFileSync(pidFile, 'utf8').trim()); + let state = null; + for (let i = 0; i < 20; i++) { + try { + const stat = readFileSync(`/proc/${pid}/stat`, 'utf8'); + state = stat.slice(stat.lastIndexOf(')') + 2).split(' ')[0]; + } catch { + state = null; // reaped + } + if (state === null || state === 'Z') break; + await sleep(100); + } + const alive = state !== null && state !== 'Z'; + check('the descendant does not outlive the guard', !alive, + `pid ${pid} still running (state=${state}) after the guard exited`); + check('the SIGKILL escalation is reported, not silent', + out.includes('ignored SIGTERM')); + if (alive) { + try { process.kill(pid, 'SIGKILL'); } catch { /* already gone */ } + } + } + } finally { + // Every synthetic child hangs by construction, so the sweep is not optional + // housekeeping — without it a failed run leaves spinning processes on a + // machine that other agents' suites share. Marker-scoped: only ours. + const swept = killByMarker(dir); + if (swept) results.push(` · swept ${swept} leftover synthetic process(es)`); + try { rmSync(dir, { recursive: true, force: true }); } catch { /* best effort */ } + } + + console.log('run-with-stall-guard --self-test'); + for (const line of results) console.log(line); + if (!linux) { + console.log(' (process-classification cases skipped: /proc not available)'); + } + if (failures.length) { + console.error(`\n✗ ${failures.length} self-test case(s) failed — the stall guard does not do what its callers assume.`); + process.exit(1); + } + console.log(`\n✓ ${results.length} case(s) passed — the guard fires, classifies and tears down.`); + process.exit(0); +}