From bb19bfb13efbd12d8d08ad31712293ed2a4b220f Mon Sep 17 00:00:00 2001 From: garrytan Date: Mon, 2 Nov 2026 23:28:13 +0000 Subject: [PATCH] fix(pregate): a quiet suite that is busy on CPU is not stalled (GST-1095) The stall timer looked only at log growth, so a parallel check.sh that prints nothing for 9 minutes while working ended PREGATE_STALLED (FOUN-63). supervise now samples the process group's CPU time each second and treats growth of at least a tenth of wall time as liveness. An idle hang still stalls; a hang that burns CPU is left to --timeout. Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> --- docs/pregate.md | 15 ++++++++---- docs/troubleshooting.md | 4 +-- lib/pregate/checks/guards.ts | 2 +- lib/pregate/checks/lanes.ts | 2 +- lib/pregate/config.ts | 7 +++--- lib/pregate/supervise.ts | 45 +++++++++++++++++++++++++++++++--- lib/pregate/types.ts | 2 +- lib/result-codes.ts | 4 +-- test/pregate-supervise.test.ts | 25 +++++++++++++++++++ 9 files changed, 87 insertions(+), 19 deletions(-) diff --git a/docs/pregate.md b/docs/pregate.md index 9128fa093..6632ed79d 100644 --- a/docs/pregate.md +++ b/docs/pregate.md @@ -85,7 +85,7 @@ the byte-pinned `/ship` renders in `test/fixtures/golden/`). | `serial_patterns` | test-file globs the `lanes` check runs one process per file, apart from the unit files (default `**/*.serial.test.*`) | | `sealed` | sealed or eval output that must never reach a public destination; read by the pre-push hook and `gstack-pregate sealed` (see [sealed output](#sealed)) | | `price_file` | repo-relative path of the paid gate's call-plan data file (`GSTACK_EVAL_CALLS v1`); `gstack-eval-plan price-gate` prices from it and never executes anything ([docs/eval-calls.md](eval-calls.md)) | -| `stall_timeout_s` | seconds a test command may print nothing before its process group is killed and the check is `incomplete` (`PREGATE_STALLED`); default 300, `0` disables; `--stall-timeout` overrides; the `--remote` gate is exempt (see [supervision](#supervision)) | +| `stall_timeout_s` | seconds a test command may print nothing and use no CPU before its process group is killed and the check is `incomplete` (`PREGATE_STALLED`); default 300, `0` disables; `--stall-timeout` overrides; the `--remote` gate is exempt (see [supervision](#supervision)) | | `timeout_s` | seconds each runner process may take (the unit-file group, each serial file, each guard without its own `timeout_s`, and the remote gate's deadline) when `--timeout` is not passed; 1 to 3600, default 600. `gstack-ship-preflight` and the `finish` fallback run pregate without `--timeout`, so this is how a repo with long lanes sets theirs | | `remote_gate` | the repo's remote test gate command; under 8 cores the local test tier becomes a `requires-remote` obligation naming it, and `--remote` runs it (see [remote gate](#remote-gate)) | | `run_profiles` | name → `{ workflow, events, jobs, artifact, max_age_hours?, os? }`: the GitHub Actions runs `clear --run` verifies as evidence on the identical tree; a profile named after a lane (`free-tests.yml/macos-named-regressions`) clears that lane (see [run evidence](#run-evidence)). `--from-run` and the main-push reuse job verify runs against them too ([from-run](#from-run), [CI reuse](#ci-reuse)) | @@ -447,10 +447,15 @@ test-tier command: a one-file run (each serial file) reports its file from the launch for any runner. Other runners (node --test, vitest, jest, pytest, playwright test, flutter test, dart test, cargo test) get heartbeats only. A heartbeat follows each 60 s with no progress line; -- is killed as **stalled** when its log does not grow for the stall timeout - (`--stall-timeout `, else `stall_timeout_s`, else 300; `0` disables): the - check is `incomplete` with `PREGATE_STALLED` and names the last file - started; the next serial file still runs. The `--remote` gate is exempt: a +- is killed as **stalled** when its log does not grow and its process group + uses no CPU for the stall timeout (`--stall-timeout `, else + `stall_timeout_s`, else 300; `0` disables): the check is `incomplete` with + `PREGATE_STALLED` and names the last file started; the next serial file + still runs. The group counts as busy when its CPU time, sampled each second, + grew by at least a tenth of the wall time, so a quiet suite that is working + (FOUN-63: a parallel `check.sh` silent for 9 minutes) is not killed, while + a hang that waits on nothing is. A hang that keeps burning CPU is left to + the timeout. Windows reads no CPU time here and uses log growth alone. The `--remote` gate is exempt: a gate that waits on CI is quiet by design, so only its timeout bounds it, and its heartbeats add `; last output: `; - is killed as **timed out** when that runner process reaches its timeout diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index d78dfb536..37c73ac6c 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -3843,14 +3843,14 @@ the lane log, then rerun or split the selection. A tool missing from PATH is ### `PREGATE_STALLED` -**Meaning.** A test command the lanes check (or a guard) launched wrote nothing to its log for the stall timeout (default 300 s, +**Meaning.** A test command the lanes check (or a guard) launched wrote nothing to its log and its process group used no CPU for the stall timeout (default 300 s, `stall_timeout_s` in the base branch's `.gstack/pregate.json` or the user-owned file, or `--stall-timeout`). pregate killed its process group and names the last test file started. The check is incomplete, never pass. **Fix.** Open the printed log, find the hang in the named file (a blocked child, a server that never exits, a synchronous wait), fix it and rerun -`gstack-pregate --stage tests`. A test that is legitimately quiet for longer +`gstack-pregate --stage tests`. A test that legitimately waits quietly for longer needs a larger `--stall-timeout`; `0` disables the stall kill and leaves only `--timeout`. The `--remote` gate never stalls: it is bounded by `--timeout` (else `timeout_s`), so a gate that waits on CI needs a timeout long enough for diff --git a/lib/pregate/checks/guards.ts b/lib/pregate/checks/guards.ts index 3f6ca1c46..7d24d0b6d 100644 --- a/lib/pregate/checks/guards.ts +++ b/lib/pregate/checks/guards.ts @@ -56,7 +56,7 @@ async function run(ctx: PregateContext): Promise { for (const g of selected) runs.push(await runGuard(ctx, g, runtime.env, dir)); const lines = [`runtime: ${runtime.label}`]; for (const r of runs) { - lines.push(r.stalled ? `GUARD: ${r.guard.id} stalled: no output for ${ctx.stallTimeoutMs / 1000} s; process group killed (log ${r.log})` : r.timedOut ? `GUARD: ${r.guard.id} timed out after ${r.guard.timeout_s ?? ctx.timeoutMs / 1000} s (log ${r.log})` : `GUARD: ${r.guard.id} exit=${r.exit} (log ${r.log})`); + lines.push(r.stalled ? `GUARD: ${r.guard.id} stalled: no output for ${ctx.stallTimeoutMs / 1000} s and its process group used no CPU; process group killed (log ${r.log})` : r.timedOut ? `GUARD: ${r.guard.id} timed out after ${r.guard.timeout_s ?? ctx.timeoutMs / 1000} s (log ${r.log})` : `GUARD: ${r.guard.id} exit=${r.exit} (log ${r.log})`); if (r.exit !== 0) lines.push(...r.tail.map(l => ` ${l}`)); if (r.environment) lines.push(` ${r.guard.id} ${environmentLine(r.environment)}`); } diff --git a/lib/pregate/checks/lanes.ts b/lib/pregate/checks/lanes.ts index 1de603914..15b84e379 100644 --- a/lib/pregate/checks/lanes.ts +++ b/lib/pregate/checks/lanes.ts @@ -401,7 +401,7 @@ function unfinished(ctx: PregateContext, r: Awaited> const timedOut = r.runs.filter(x => x.outcome === 'timeout'); const rest = r.failed ? `; ${r.failed} failed` : ''; if (stalled.length) { - return { code: 'PREGATE_STALLED', detail: `no test output for ${ctx.stallTimeoutMs / 1000} s; process group killed; last file started: ${stalled.map(x => x.lastFile ?? `(none reported; ${x.files.length} file(s))`).join(', ')}${rest}`, fix: `read ${r.log} for the stalled file; fix the hang, or raise --stall-timeout (stall_timeout_s in ${ctx.configFile}; 0 disables) for a test that is quiet for longer` }; + return { code: 'PREGATE_STALLED', detail: `no test output for ${ctx.stallTimeoutMs / 1000} s and its process group used no CPU; process group killed; last file started: ${stalled.map(x => x.lastFile ?? `(none reported; ${x.files.length} file(s))`).join(', ')}${rest}`, fix: `read ${r.log} for the stalled file; fix the hang, or raise --stall-timeout (stall_timeout_s in ${ctx.configFile}; 0 disables) for a test that waits quietly for longer` }; } const launch = r.runs.find(x => x.outcome === 'spawn-failed'); if (launch) { diff --git a/lib/pregate/config.ts b/lib/pregate/config.ts index 19a09b289..863b5f894 100644 --- a/lib/pregate/config.ts +++ b/lib/pregate/config.ts @@ -29,8 +29,9 @@ * the pre-push hook and `gstack-pregate sealed`, not by `run`) * price_file the call-plan data file `gstack-eval-plan price-gate` prices * a paid gate from (GSTACK_EVAL_CALLS v1; never executed) - * stall_timeout_s seconds without test output before the lanes check kills - * the runner's process group (default 300; 0 disables) + * stall_timeout_s seconds without test output or CPU activity before the + * lanes check kills the runner's process group (default 300; + * 0 disables) * timeout_s seconds each runner process may take (the unit-file group, * each serial file, each guard without its own timeout_s, the * remote gate) when `--timeout` is not passed (default 600) @@ -352,7 +353,7 @@ export function explainConfig(): string { `serial_patterns: test-file globs the lanes check runs one process per file, apart from the unit files (default ${DEFAULT_SERIAL_PATTERNS.join(', ')})`, 'sealed: { paths, transcripts, answer_markers, seed_patterns, local_paths, allow_paths, case_insensitive, label_keys, identifier_keys, visibility }: sealed or eval output the pre-push hook and `gstack-pregate sealed` refuse to publish to a public destination; allow_paths (base branch only) exempt publishable files from the path globs; label_keys turns on sealed.label_join, which refuses a published record that puts one of those fields next to an identifier (identifier_keys globs, or a hex value) (docs/pregate.md#sealed)', 'price_file: repo-relative path of the GSTACK_EVAL_CALLS v1 call-plan file `gstack-eval-plan price-gate` prices a paid gate from; never executed (docs/eval-calls.md)', - 'stall_timeout_s: seconds without test output before the lanes check kills the runner\'s process group and records it incomplete (default 300; 0 disables; --stall-timeout overrides)', + 'stall_timeout_s: seconds without test output or CPU activity before the lanes check kills the runner\'s process group and records it incomplete (default 300; 0 disables; --stall-timeout overrides)', 'timeout_s: seconds each runner process may take (the unit-file group, each serial file, each guard without its own timeout_s, and the remote gate\'s deadline) when --timeout is not passed; 1 to 3600, default 600', 'remote_gate: the repo\'s remote test gate command; under 8 cores the test tier becomes a requires-remote obligation naming it, and gstack-pregate --remote runs it (it must print PREGATE_REMOTE: tree= tests= failed=) (docs/pregate.md#remote-gate)', 'run_profiles: name → { workflow, events, jobs, artifact, max_age_hours?, os? }; the GitHub Actions runs gstack-pregate clear --run verifies as evidence on the identical tree (docs/pregate.md#run-evidence)', diff --git a/lib/pregate/supervise.ts b/lib/pregate/supervise.ts index a7ff3ed88..9aa12d722 100644 --- a/lib/pregate/supervise.ts +++ b/lib/pregate/supervise.ts @@ -2,8 +2,10 @@ * pregate/supervise — how a test-tier command runs (Lane C, GBRA-95): its * own process group, stdout and stderr appended to a log file (no pipes, so * a backgrounded grandchild holding the output can never keep the check - * waiting), supervised asynchronously. A stall is no log growth for - * `stallMs`; the deadline is the check's `--timeout`. Either kills the whole + * waiting), supervised asynchronously. A stall is `stallMs` with no log growth + * and no CPU activity in the process group (GST-1095: a quiet parallel suite + * that is busy working is alive; a hang that keeps burning CPU is left to the + * deadline); the deadline is the check's `--timeout`. Either kills the whole * process group (SIGTERM, then SIGKILL after a grace period) and the run is * incomplete. After a normal exit the group's leftover members are killed. * @@ -34,7 +36,7 @@ export interface SuperviseOptions { log: string; /** Absolute epoch ms when the run is killed as timed out. */ deadline: number; - /** No log growth for this long kills the group; 0 disables. */ + /** No log growth and no CPU activity in the group for this long kills it; 0 disables. */ stallMs: number; heartbeatMs?: number; graceMs?: number; @@ -63,6 +65,9 @@ export interface Supervised { } const ACTIVE = new Set(); +const USER_HZ = 100; +const CPU_SAMPLE_MS = 1_000; +const CPU_BUSY_SHARE = 0.1; /** SIGKILL every supervised process group still running (the CLI's SIGINT/SIGTERM handler, before it exits). */ export function cancelActive(): number { @@ -80,6 +85,31 @@ export function killGroup(pid: number, signal: NodeJS.Signals): void { try { process.kill(-pid, signal); } catch { /* group already gone */ } } +/** CPU time in ms used by the process group `pgid`, reaped children included where the platform reports them; null where it cannot be read (Windows). */ +export function groupCpuMs(pgid: number): number | null { + if (process.platform === 'win32') return null; + if (fs.existsSync('/proc/self/stat')) { + let ticks = 0; + for (const name of fs.readdirSync('/proc')) { + if (!/^\d+$/.test(name)) continue; + let stat: string; + try { stat = fs.readFileSync(`/proc/${name}/stat`, 'utf8'); } catch { continue; } + const f = stat.slice(stat.lastIndexOf(')') + 2).split(' '); + if (Number(f[2]) === pgid) ticks += Number(f[11]) + Number(f[12]) + Number(f[13]) + Number(f[14]); + } + return ticks * 1000 / USER_HZ; + } + const ps = spawnSync('ps', ['-A', '-o', 'pgid=,time='], { encoding: 'utf8', timeout: 15_000 }); + if (ps.status !== 0) return null; + let ms = 0; + for (const line of ps.stdout.split('\n')) { + const [id, time] = line.trim().split(/\s+/); + const t = time && /^(?:(\d+)-)?(?:(\d+):)?(\d+):(\d+(?:\.\d+)?)$/.exec(time); + if (Number(id) === pgid && t) ms += (((Number(t[1] ?? 0) * 24 + Number(t[2] ?? 0)) * 60 + Number(t[3])) * 60 + Number(t[4])) * 1000; + } + return ms; +} + /** The adapter that reads per-file progress from this runner's output, or null when it has none. */ export function adapterFor(command: string): ProgressAdapter | null { for (const [name, re] of Object.entries(PROGRESS_ADAPTERS)) if (re.test(command)) return name as ProgressAdapter; @@ -110,6 +140,8 @@ export function supervise(o: SuperviseOptions): Promise { let readAt = start; let partial = ''; let lastGrowth = started; + let lastBusy = started; + let cpu: { at: number; ms: number } | null = { at: started, ms: 0 }; let lastProgress = started; let current: { file: string; at: number; failed: boolean } | null = null; let lastFile: string | null = null; @@ -184,7 +216,12 @@ export function supervise(o: SuperviseOptions): Promise { if (grown > size) { size = grown; lastGrowth = now; readNew(); } if (outcome) return; if (now >= o.deadline) { stop('timeout'); return; } - if (o.stallMs > 0 && now - lastGrowth >= o.stallMs) { stop('stalled'); return; } + if (o.stallMs > 0 && cpu && now - cpu.at >= CPU_SAMPLE_MS) { + const used = groupCpuMs(child.pid!); + if (used !== null && used - cpu.ms >= CPU_BUSY_SHARE * (now - cpu.at)) lastBusy = now; + cpu = used === null ? null : { at: now, ms: used }; + } + if (o.stallMs > 0 && now - Math.max(lastGrowth, lastBusy) >= o.stallMs) { stop('stalled'); return; } if (now - lastProgress < heartbeatMs) return; let last: string | undefined; if (o.lastLine) { diff --git a/lib/pregate/types.ts b/lib/pregate/types.ts index fd9ddda19..3e13116f6 100644 --- a/lib/pregate/types.ts +++ b/lib/pregate/types.ts @@ -54,7 +54,7 @@ export interface PregateContext { timeoutMs: number; /** Where timeoutMs came from: `--timeout`, `timeout_s from `, or the 600 s default. */ timeoutSource?: string; - /** No output for this long kills a test-tier process group (`--stall-timeout`, `stall_timeout_s`); 0 disables. */ + /** No output and no CPU activity for this long kills a test-tier process group (`--stall-timeout`, `stall_timeout_s`); 0 disables. */ stallTimeoutMs: number; /** Live stderr lines: per-file progress, heartbeats, the stage result. */ progress: (line: string) => void; diff --git a/lib/result-codes.ts b/lib/result-codes.ts index 59c25980c..ea0a69d1f 100644 --- a/lib/result-codes.ts +++ b/lib/result-codes.ts @@ -410,8 +410,8 @@ export const RESULT_CODES = { }, PREGATE_STALLED: { anchor: 'pregate-stalled', - summary: 'a test command printed nothing for the stall timeout, so its process group was killed; the check is incomplete, never pass', - fix: 'read the lane log for the last file started, fix the hang, or raise `--stall-timeout` (`stall_timeout_s`; 0 disables) for a test that is quiet for longer, then rerun `gstack-pregate --stage tests`', + summary: 'a test command printed nothing and used no CPU for the stall timeout, so its process group was killed; the check is incomplete, never pass', + fix: 'read the lane log for the last file started, fix the hang, or raise `--stall-timeout` (`stall_timeout_s`; 0 disables) for a test that waits quietly for longer, then rerun `gstack-pregate --stage tests`', }, PREGATE_RECEIPT_INVALID: { anchor: 'pregate-receipt-invalid', diff --git a/test/pregate-supervise.test.ts b/test/pregate-supervise.test.ts index 900f4f890..df6f2fb73 100644 --- a/test/pregate-supervise.test.ts +++ b/test/pregate-supervise.test.ts @@ -66,6 +66,21 @@ describe('supervise: process group, log file, stall and deadline', () => { expect(printing.wall).toBeGreaterThan(1500); }); + // Value: protects=a quiet suite that is busy working is not killed as stalled, while a busy run that never ends still hits the deadline + // (GST-1095); fails_when=stall detection looks only at log growth and kills a CPU-busy silent run; why_new=a quiet 9-minute parallel check.sh + // ended PREGATE_STALLED on Founderstar (FOUN-63); seam=none; no_claim=a hung run that keeps burning CPU is caught by the deadline, not the stall timer + test('a silent command that keeps using CPU is not stalled; a busy run that never ends still times out at the deadline', async () => { + const dir = scratch(); + const busy = `${process.execPath} -e 'const end = Date.now() + 3500; while (Date.now() < end) {} console.log("done")'`; + const quiet = await run(dir, busy, { stallMs: 1500 }); + expect(quiet.outcome).toBe('exited'); + expect(quiet.exit).toBe(0); + expect(quiet.log).toContain('done'); + const forever = await run(dir, `${process.execPath} -e 'for (;;) {}'`, { stallMs: 1500, deadline: Date.now() + 4000 }); + expect(forever.outcome).toBe('timeout'); + expect(forever.exit).toBeNull(); + }, 20_000); + test('a group that ignores SIGTERM is SIGKILLed after the grace period', async () => { const dir = scratch(); const r = await run(dir, `trap '' TERM; echo $$ > ${dir}/stubborn.pid; while :; do sleep 0.1; done`, { stallMs: 500, graceMs: 400 }); @@ -195,6 +210,16 @@ describe('gstack-pregate: the test stage never hangs silently', () => { expect(r.err).toMatch(/^gstack-pregate: lanes stalled — .*; fix: .* \(PREGATE_STALLED; https:\/\/github\.com\/garrytan\/gstack\/blob\/main\/docs\/troubleshooting\.md#pregate-stalled\)$/m); }, 90_000); + // Value: protects=the FOUN-63 shape end to end: a lane test that is silent past --stall-timeout but busy passes instead of PREGATE_STALLED + // (GST-1095); fails_when=the lanes check kills a CPU-busy quiet test at the stall timeout; why_new=FOUN-63; seam=none; no_claim=none + test('a test that is silent past the stall timeout but busy runs to a pass', () => { + const repo = makeFixtureRepo(); repos.push(repo); + commit(repo, { 'test/busy.test.js': "const test = require('node:test');\ntest('quiet and busy', () => { const end = Date.now() + 5000; while (Date.now() < end) {} });\n" }); + const r = pregate(repo, ['--stall-timeout', '2']); + expect(lanes(repo)).toMatchObject({ status: 'pass' }); + expect(r.status).toBe(EXIT.ok); + }, 90_000); + test('a test whose child backgrounds and holds stdout passes promptly instead of waiting out --timeout', () => { const repo = makeFixtureRepo({ pregate: { ...BASE_PREGATE, runner: 'node {files}' } }); repos.push(repo); commit(repo, { 'test/bg.test.js': NODE_BACKGROUND });