Skip to content

Commit 9760d72

Browse files
os-steveclaude
andauthored
feat(ci): stall guard gets a second signal — source-side write progress, with the CPU inversion designed out (#11915)
The guard's only instrument was output flushes, measured at the wrong end of the pipeline: what it sees is whatever the last buffering layer chose to release. --log-order=stream closed one spelling of that; any future buffering layer re-opens it and kills a healthy suite deterministically on an innocent diff. Second signal: bytes every process in the wrapped group has passed to write(), read from /proc/<pid>/io (wchar) — the same quantity the guard already trusts, sampled at the SOURCE, before any buffering layer can hide it. Measured first, because the card's CPU direction does not survive contact (node 22, 2.5s sample, one process per shape): shape state dCPU(ticks) dwchar(bytes) idle hang (self-test #4) S 0 0 sync-spinning hang (#5) R 251 0 GC-thrash hang R 272 0 HEALTHY silent-but-working S 1 25,542 CPU does not merely fail to separate these shapes, it separates them BACKWARDS: the genuine hangs peg a core while the healthy suite the probe exists to protect is nearly idle, because it is I/O-bound — it is busy writing. wchar separates all four correctly. The probe is a confirming signal in one direction only. No output and no source-side bytes still kills at --stall-minutes with no added latency (idle and spinning hangs write nothing, so neither is ever deferred). No output but bytes still moving defers the kill, announced loudly — a live suite hidden by a buffering layer is a bug to fix, not to tolerate — and only as far as --stall-cap-minutes, after which the group dies under a distinct STALL-CAP verdict. That cap is what stops the probe turning "kills healthy suites" into "never fires on spin hangs", which is strictly worse. A cap <= the window is refused; an unreadable /proc/<pid>/io reports UNAVAILABLE and the guard behaves exactly as before. --stall-minutes is untouched. Claude-Session: https://claude.ai/code/session_015ahemw8RcTgqtxrj15PEZx Co-authored-by: Claude <noreply@anthropic.com>
1 parent c3c72a4 commit 9760d72

1 file changed

Lines changed: 309 additions & 2 deletions

File tree

‎scripts/run-with-stall-guard.mjs‎

Lines changed: 309 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,68 @@
4242
// startup (exit 1, before anything runs). pnpm's recursive runner streams
4343
// with per-package prefixes (measured), so non-turbo callers are untouched.
4444
//
45+
// ## The second signal: source-side write progress (the liveness probe)
46+
//
47+
// Output flushes are the primary instrument and they are measured at the WRONG
48+
// END of the pipeline: what the guard sees is whatever the last buffering layer
49+
// chose to release. `--log-order=stream` closes one spelling of that; any future
50+
// layer -- a reporter change, a new runner, a pnpm output-mode change --
51+
// re-opens it, and the result is a healthy suite killed deterministically on an
52+
// innocent diff.
53+
//
54+
// So there is a second, independent signal: the bytes every process in the
55+
// wrapped group has passed to write(), read from /proc/<pid>/io (wchar). That is
56+
// the SAME quantity the guard already trusts, sampled at the SOURCE -- before
57+
// any buffering layer can hide it.
58+
//
59+
// ### What a genuinely frozen suite looks like to this probe
60+
//
61+
// Zero bytes written by ANY process in the group for the whole stall window.
62+
// Not "no CPU" -- CPU is precisely the signal that does not work here. Measured
63+
// on this repo (node 22, 2.5s sample, one process per shape):
64+
//
65+
// shape state dCPU(ticks) dwchar(bytes)
66+
// idle hang (self-test #4) S 0 0
67+
// sync-spinning hang (#5) R 251 0
68+
// GC-thrash hang R 272 0
69+
// HEALTHY silent-but-working S 1 25,542
70+
//
71+
// Read the CPU column before designing anything on it: the two genuine hangs peg
72+
// a core, while the healthy suite the probe exists to protect is nearly IDLE --
73+
// it is I/O-bound, it is busy WRITING. A naive "burning CPU therefore alive,
74+
// therefore do not kill" probe would have protected the hangs and killed the
75+
// healthy suite. CPU does not merely fail to separate these shapes, it separates
76+
// them BACKWARDS. wchar separates all four correctly.
77+
//
78+
// ### The probe may only ever DELAY a kill, and only to a hard cap
79+
//
80+
// A hang that writes while wedged (a retry loop, a poller, a log spin) would
81+
// look alive to this probe forever, so it is a CONFIRMING signal in exactly one
82+
// direction:
83+
//
84+
// * no output AND no source-side bytes -> stall, killed at --stall-minutes,
85+
// exactly as before. Idle and spinning hangs take this path with no added
86+
// latency, because they write nothing.
87+
// * no output BUT source-side bytes still moving -> the kill is DEFERRED, and
88+
// the deferral is announced loudly: it means a buffering layer is hiding a
89+
// live suite from this guard, and that layer should be FIXED, not tolerated.
90+
// * ...until --stall-cap-minutes, when the group is killed anyway under a
91+
// DISTINCT verdict (STALL-CAP). That cap is what stops the probe from
92+
// converting "kills healthy suites" into "never fires on spin hangs", which
93+
// is strictly worse: a job sitting in_progress until the job timeout is the
94+
// state this guard exists to abolish, and no green run can distinguish that
95+
// regression from success.
96+
//
97+
// The cap's ceiling is not a matter of taste. Every guard-wrapped job in ci.yml
98+
// runs `timeout-minutes: 30` against `--stall-minutes 10`, so a cap set "far
99+
// above" the window would just hand the verdict back to the job timeout. Default
100+
// is 2x the window; a cap <= the window is REFUSED, because it would disable the
101+
// probe silently.
102+
//
103+
// If /proc/<pid>/io cannot be read (not Linux, hardened permissions), the probe
104+
// reports itself UNAVAILABLE and the guard behaves exactly as it did before this
105+
// signal existed. An unreadable probe must never read as liveness.
106+
//
45107
// ## Stall forensics (before the kill)
46108
//
47109
// A declared stall triages itself instead of leaving a mystery for a human:
@@ -114,6 +176,15 @@ import { fileURLToPath } from 'node:url';
114176
const STALL_EXIT_CODE = 75; // EX_TEMPFAIL
115177
const CHECK_INTERVAL_MS = 5_000;
116178
const SIGKILL_GRACE_MS = 10_000;
179+
// How far above --stall-minutes the liveness probe may defer a kill, when it is
180+
// not given an explicit --stall-cap-minutes. Deliberately small: the guard-wrapped
181+
// jobs run `timeout-minutes: 30` against a 10-minute window, so a larger multiple
182+
// would return the verdict to the job timeout -- the outcome the guard abolishes.
183+
const DEFAULT_CAP_MULTIPLE = 2;
184+
// Announce a deferral every N watchdog ticks (the first one always prints). A
185+
// deferral is a bug report about the pipeline, not routine noise -- but repeating
186+
// it every 5s would bury the suite's own output.
187+
const DEFER_NOTE_EVERY = 12;
117188

118189
const argv = process.argv.slice(2);
119190

@@ -123,12 +194,16 @@ if (argv.includes('--self-test')) await selfTest();
123194

124195
let logPath = '';
125196
let stallMinutes = 10;
197+
let stallCapMinutes = 0; // 0 = derive from stallMinutes
198+
let livenessProbe = true;
126199
let reportDir = '';
127200
let command = [];
128201

129202
for (let i = 0; i < argv.length; i++) {
130203
if (argv[i] === '--log') logPath = argv[++i] ?? '';
131204
else if (argv[i] === '--stall-minutes') stallMinutes = Number(argv[++i]);
205+
else if (argv[i] === '--stall-cap-minutes') stallCapMinutes = Number(argv[++i]);
206+
else if (argv[i] === '--no-liveness-probe') livenessProbe = false;
132207
else if (argv[i] === '--report-dir') reportDir = argv[++i] ?? '';
133208
else if (argv[i] === '--') {
134209
command = argv.slice(i + 1);
@@ -141,7 +216,21 @@ for (let i = 0; i < argv.length; i++) {
141216

142217
if (!logPath || command.length === 0 || !Number.isFinite(stallMinutes) || stallMinutes <= 0) {
143218
console.error(
144-
'run-with-stall-guard: usage: run-with-stall-guard.mjs --log <file> [--stall-minutes N] -- <command...>',
219+
'run-with-stall-guard: usage: run-with-stall-guard.mjs --log <file> [--stall-minutes N]\n' +
220+
' [--stall-cap-minutes N] [--no-liveness-probe] [--report-dir <dir>] -- <command...>',
221+
);
222+
process.exit(1);
223+
}
224+
225+
if (stallCapMinutes === 0) stallCapMinutes = stallMinutes * DEFAULT_CAP_MULTIPLE;
226+
if (!Number.isFinite(stallCapMinutes) || stallCapMinutes <= stallMinutes) {
227+
console.error(
228+
`run-with-stall-guard: --stall-cap-minutes (${stallCapMinutes}) must be GREATER than ` +
229+
`--stall-minutes (${stallMinutes}).\n` +
230+
' The cap bounds how long the liveness probe may defer a kill while the wrapped group\n' +
231+
' is still writing bytes at the source. A cap at or below the stall window disables\n' +
232+
' the probe silently, and a probe that is silently off is indistinguishable from one\n' +
233+
' that works -- so this is refused instead.',
145234
);
146235
process.exit(1);
147236
}
@@ -177,6 +266,7 @@ if (turboLogOrderViolation(command)) {
177266
}
178267

179268
const stallMs = stallMinutes * 60_000;
269+
const capMs = stallCapMinutes * 60_000;
180270
const log = createWriteStream(logPath, { flags: 'w' });
181271

182272
// detached: own process group, so a stall verdict can kill pnpm -> turbo -> the
@@ -263,6 +353,83 @@ function sampleGroup() {
263353
return procs;
264354
}
265355

356+
// ---------------------------------------------------------------------------
357+
// The liveness probe: source-side write progress
358+
// ---------------------------------------------------------------------------
359+
360+
/** Per-pid wchar counters observed on the previous poll. */
361+
let probeSeen = new Map();
362+
/** True once ANY group member's /proc/<pid>/io was read successfully. While
363+
* this is false the probe is UNAVAILABLE and can never postpone a kill: an
364+
* unreadable counter must not be mistaken for liveness. */
365+
let probeEverRead = false;
366+
/** The first poll only records counters. Without this, every pid's whole
367+
* lifetime total would be booked as "progress just now" on the first tick,
368+
* which is a stall's worth of free credit handed to a suite that is already
369+
* frozen. */
370+
let probeBaselined = false;
371+
/** Bytes the group has written since the baseline -- quoted in the verdict. */
372+
let probeBytes = 0;
373+
let lastProgressAt = Date.now();
374+
375+
/** One poll of /proc/<pid>/io across the wrapped process group.
376+
*
377+
* Only POSITIVE per-pid deltas count, and a pid seen for the first time
378+
* contributes its whole counter (new work starting IS progress), so a process
379+
* exiting can never move the accumulator backwards -- an exit must read as
380+
* neither a stall nor liveness. Every read is try/caught; the probe is
381+
* best-effort and fails CLOSED. */
382+
function pollWriteProgress() {
383+
let grew = 0;
384+
const next = new Map();
385+
let entries;
386+
try {
387+
entries = readdirSync('/proc');
388+
} catch {
389+
return false; // not Linux: probeEverRead stays false, probe stays unavailable
390+
}
391+
for (const entry of entries) {
392+
if (!/^\d+$/.test(entry)) continue;
393+
const pid = Number(entry);
394+
let wchar;
395+
try {
396+
const stat = readFileSync(`/proc/${pid}/stat`, 'utf8');
397+
// f[2] = pgrp. Scoping to the detached child's group excludes this guard
398+
// and every other agent's processes on a shared machine.
399+
if (Number(stat.slice(stat.lastIndexOf(')') + 2).split(' ')[2]) !== child.pid) continue;
400+
const m = /^wchar:\s*(\d+)/m.exec(readFileSync(`/proc/${pid}/io`, 'utf8'));
401+
if (!m) continue;
402+
wchar = Number(m[1]);
403+
} catch {
404+
continue; // vanished mid-read, or io is not readable for this uid
405+
}
406+
probeEverRead = true;
407+
next.set(pid, wchar);
408+
const prev = probeSeen.get(pid);
409+
grew += prev === undefined ? wchar : Math.max(0, wchar - prev);
410+
}
411+
probeSeen = next;
412+
if (!probeBaselined) {
413+
probeBaselined = true;
414+
return false;
415+
}
416+
if (grew > 0) {
417+
probeBytes += grew;
418+
lastProgressAt = Date.now();
419+
}
420+
return grew > 0;
421+
}
422+
423+
/** One line for the verdict banner: what the second signal saw. */
424+
function probeVerdictLine(now) {
425+
if (!livenessProbe) return 'disabled (--no-liveness-probe) -- output flushes were the only signal';
426+
if (!probeEverRead) {
427+
return 'UNAVAILABLE (/proc/<pid>/io unreadable here) -- output flushes were the only signal';
428+
}
429+
const quietM = ((now - lastProgressAt) / 60_000).toFixed(1);
430+
return `no byte written by ANY process in the group for ${quietM}m -- FROZEN at the source, not merely buffered`;
431+
}
432+
266433
/** Classify every group member from two /proc samples and, when report-dir
267434
* plumbing is armed, harvest SIGUSR2 diagnostic reports from the node
268435
* processes. Returns the forensics text block (empty string off-Linux). */
@@ -364,18 +531,75 @@ async function reapGroup(graceMs) {
364531
return survivors;
365532
}
366533

534+
let probeDeferrals = 0;
535+
367536
const watchdog = setInterval(() => {
537+
if (livenessProbe) pollWriteProgress();
368538
const silentMs = Date.now() - lastOutputAt;
369539
if (silentMs < stallMs) return;
370540

541+
// The second signal, in the ONE direction it is safe in. It may postpone a
542+
// kill while the group is demonstrably still producing bytes -- never past the
543+
// cap, and never at all when the counters could not be read. An idle or a
544+
// sync-spinning hang writes nothing, so neither is ever postponed by this.
545+
const sourceAlive =
546+
livenessProbe && probeEverRead && Date.now() - lastProgressAt < stallMs;
547+
const capped = silentMs >= capMs;
548+
549+
if (sourceAlive && !capped) {
550+
if (probeDeferrals % DEFER_NOTE_EVERY === 0) {
551+
const note =
552+
`\n⚠ stall guard: no output reached this guard for ${(silentMs / 60_000).toFixed(1)}m, but the wrapped\n` +
553+
` group has written ${probeBytes} bytes at the source since then -- deferring the kill\n` +
554+
` until the cap (${stallCapMinutes}m). A live suite is being hidden from this guard by a\n` +
555+
' buffering layer: FIX THE LAYER (every turbo under this guard must pin\n' +
556+
' --log-order=stream), do not rely on this deferral.\n';
557+
process.stdout.write(note);
558+
log.write(note);
559+
}
560+
probeDeferrals++;
561+
return;
562+
}
563+
371564
stalled = true;
372565
clearInterval(watchdog);
373-
const banner = `
566+
const now = Date.now();
567+
const banner = sourceAlive
568+
? `
569+
${'═'.repeat(72)}
570+
⛔ STALL-CAP: nothing reached this guard for ${(silentMs / 60_000).toFixed(1)} minutes (cap: ${stallCapMinutes}m),
571+
but the wrapped group kept WRITING the whole time.
572+
573+
frozen since : ${new Date(lastOutputAt).toISOString()} (as this guard sees it)
574+
last written : ${new Date(lastProgressAt).toISOString()} (as /proc/<pid>/io sees it)
575+
bytes written: ${probeBytes} since the probe's baseline
576+
last line : ${lastLine}
577+
578+
This group is NOT frozen -- it is producing output that never arrives here.
579+
Two things look exactly like this, and both are bugs to fix rather than
580+
wait out:
581+
582+
1. A BUFFERING LAYER between the suite and this guard -- the class turbo's
583+
grouped log order was one spelling of. Check that every turbo under this
584+
guard pins --log-order=stream and that no reporter or runner in the
585+
pipeline groups its output.
586+
2. A hang that WRITES while wedged -- a retry loop, a poller, a log spin.
587+
The forensics below name which processes were burning the bytes.
588+
589+
Killing at the cap instead of deferring forever: a guard that never fires
590+
leaves the job in_progress until the job timeout, which is the state this
591+
guard exists to abolish.
592+
593+
Collecting forensics before the kill (process states + JS stacks)...
594+
${'═'.repeat(72)}
595+
`
596+
: `
374597
${'═'.repeat(72)}
375598
⛔ STALL: no test output for ${(silentMs / 60_000).toFixed(1)} minutes (limit: ${stallMinutes}m).
376599
377600
frozen since : ${new Date(lastOutputAt).toISOString()}
378601
last line : ${lastLine}
602+
liveness probe: ${probeVerdictLine(now)}
379603
380604
This is the #4250 failure mode -- the suite is STOPPED, not slow. A
381605
healthy run prints continuously; only a hang goes silent this long.
@@ -641,6 +865,8 @@ async function selfTest() {
641865
check('idle hang is declared a stall', code === STALL_EXIT_CODE, `exit ${code}`);
642866
check('the verdict quotes the last line seen',
643867
out.includes('last line : RUN beta.test.ts'));
868+
check('idle hang is not rescued by the liveness probe (plain verdict, no deferral)',
869+
!out.includes('STALL-CAP') && !out.includes('deferring the kill'));
644870
if (linux) {
645871
check('idle hang is classified idle, not on-CPU',
646872
out.includes('idle -- waiting on something that never settles'));
@@ -671,6 +897,14 @@ async function selfTest() {
671897
out.includes('ON-CPU -- sync-spinning or GC-thrashing'));
672898
check('a blocked event loop is diagnosed by its SILENCE',
673899
out.includes('NO report -- its event loop is BLOCKED'));
900+
// The inversion this card exists to design out. A spinning hang pegs a
901+
// core, so any probe that reads CPU as liveness stops firing here -- and
902+
// "never fires on spin hangs" is strictly worse than the defect it would
903+
// be fixing, because no green run can tell it apart from success.
904+
check('sync-spinning hang is NOT rescued by the probe — burning CPU is not liveness',
905+
!out.includes('STALL-CAP') && !out.includes('deferring the kill'));
906+
check('the verdict names the source-side probe as the reason it fired',
907+
out.includes('FROZEN at the source'));
674908
}
675909

676910
// -- 6. A hang that never prints a first line. --
@@ -741,6 +975,79 @@ async function selfTest() {
741975
try { process.kill(pid, 'SIGKILL'); } catch { /* already gone */ }
742976
}
743977
}
978+
// -- 8. HEALTHY silent-but-working: the shape the probe exists to protect. --
979+
// The child writes real bytes the entire time, but none of them reach the
980+
// guard -- which is what ANY buffering layer between the suite and this
981+
// wrapper looks like from here (turbo's grouped log order was one
982+
// spelling of it). Output flushes alone call this a stall and kill a
983+
// healthy suite; the source-side probe is what tells them apart.
984+
if (linux) {
985+
const sink = join(dir, 'buffered-output.txt');
986+
const shape = [
987+
process.execPath, '-e',
988+
"const fs = require('fs'); const fd = fs.openSync(process.argv[1], 'a'); let n = 0;" +
989+
"const t = setInterval(() => { fs.writeSync(fd, 'work '.repeat(80) + '\\n');" +
990+
"if (++n > 45) { clearInterval(t); fs.closeSync(fd); console.log('suite passed'); } }, 100);",
991+
sink, dir,
992+
];
993+
const saved = await runGuard(
994+
['--log', join(dir, 'buffered.log'), ...WINDOW, '--stall-cap-minutes', '0.5', '--', ...shape],
995+
{}, { marker: dir },
996+
);
997+
check('a healthy silent-but-working run is NOT killed', saved.code === 0, `exit ${saved.code}`);
998+
check('...and is never called a stall', !saved.out.includes('STALL'));
999+
check('...and the deferral is announced, not silent',
1000+
saved.out.includes('deferring the kill'), saved.out.trim().split('\n')[0]);
1001+
1002+
// Positive control, and the reason case 8 is evidence rather than a
1003+
// coincidence: the SAME child, probe off, must die. Without this a probe
1004+
// that did nothing at all would score exactly like one that works.
1005+
const killed = await runGuard(
1006+
['--log', join(dir, 'buffered-noprobe.log'), ...WINDOW, '--no-liveness-probe', '--', ...shape],
1007+
{}, { marker: dir },
1008+
);
1009+
check('positive control: the same run IS killed with --no-liveness-probe',
1010+
killed.code === STALL_EXIT_CODE, `exit ${killed.code}`);
1011+
check('positive control: and the verdict says the probe was off',
1012+
killed.out.includes('disabled (--no-liveness-probe)'));
1013+
}
1014+
1015+
// -- 9. A hang that WRITES while wedged is still killed -- at the cap. --
1016+
// The probe's own residual failure mode: a retry loop or a log spin looks
1017+
// alive to it forever. The cap is what keeps that from becoming "never
1018+
// fires", and the distinct verdict word is what keeps it diagnosable.
1019+
if (linux) {
1020+
const res = await runGuard(
1021+
['--log', join(dir, 'writing-hang.log'), ...WINDOW, '--stall-cap-minutes', '0.15', '--',
1022+
process.execPath, '-e',
1023+
"const fs = require('fs'); const fd = fs.openSync(process.argv[1], 'a');" +
1024+
"console.log('RUN delta.test.ts');" +
1025+
"setInterval(() => { fs.writeSync(fd, 'still retrying\\n'); }, 50);",
1026+
join(dir, 'retry-loop.txt'), dir],
1027+
{}, { marker: dir },
1028+
);
1029+
const { code, out } = res;
1030+
check('a writing hang: the guard still exits on its own', !res.timedOut,
1031+
'the guard never exited — the probe inverted the defect');
1032+
check('a hang that keeps writing is still killed', code === STALL_EXIT_CODE, `exit ${code}`);
1033+
check('...at the cap, under its own distinct STALL-CAP verdict',
1034+
out.includes('STALL-CAP'), out.trim().split('\n').slice(-2).join(' | '));
1035+
check('...having first announced the deferral it was granted',
1036+
out.includes('deferring the kill'));
1037+
}
1038+
1039+
// -- 10. A cap that would silently disable the probe is refused. --
1040+
{
1041+
const bad = await runGuard(
1042+
['--log', join(dir, 'badcap.log'), ...WINDOW, '--stall-cap-minutes', '0.05', '--',
1043+
process.execPath, '-e', "console.log('this child must never run');", dir],
1044+
{}, { marker: dir },
1045+
);
1046+
check('a --stall-cap-minutes at or below --stall-minutes is refused',
1047+
bad.code === 1 && bad.out.includes('must be GREATER than'), `exit ${bad.code}`);
1048+
check('the cap refusal happens before anything spawns',
1049+
!bad.out.includes('this child must never run'));
1050+
}
7441051
} finally {
7451052
// Every synthetic child hangs by construction, so the sweep is not optional
7461053
// housekeeping — without it a failed run leaves spinning processes on a

0 commit comments

Comments
 (0)