diff --git a/CHANGELOG.md b/CHANGELOG.md index a58561d99..1cdc543ce 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,12 @@ # Changelog +## [1.93.35.0] - 2026-11-03 + +**pregate no longer kills a quiet test suite that is busy working.** + +### Fixed +- **`lib/pregate/supervise.ts`**: the stall timeout now needs both no log output and an idle process group. Each second, supervise reads the group's CPU time (`/proc` on Linux, `ps -S` on macOS and BSDs). If it grew by at least a tenth of the wall time, the group counts as alive. Before, a parallel `check.sh` that printed nothing for 9 minutes while working ended `PREGATE_STALLED` at the 300 s default (Founderstar FOUN-63). A hang that waits on nothing still stalls. A hang that keeps using CPU now runs to `--timeout`, and either way the check is incomplete, never a pass. Windows reads no CPU time and keeps log growth alone. The `PREGATE_STALLED` detail, the guard line and the docs say what was measured. Both new tests fail on main. There a silent CPU-bound command ends `stalled` and a busy lane test ends `PREGATE_STALLED`. + ## [1.93.34.0] - 2026-11-03 **The docsync fault-callback replays and the runShadow deadline test stop failing on loaded remote pregate VMs.** diff --git a/VERSION b/VERSION index 56b8028cf..7f54b9d80 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -1.93.34.0 +1.93.35.0 diff --git a/agents-digest/gstack-AGENTS.md b/agents-digest/gstack-AGENTS.md index f2f1d212b..c77e7a3ef 100644 --- a/agents-digest/gstack-AGENTS.md +++ b/agents-digest/gstack-AGENTS.md @@ -1,4 +1,4 @@ -# gstack digest v1.93.34.0 — regenerate/re-copy after upgrading gstack +# gstack digest v1.93.35.0 — regenerate/re-copy after upgrading gstack Behavioral rules from gstack (https://github.com/garrytan/gstack), compressed for agent hosts without a full skill install. The full skills add workflows, diff --git a/docs/pregate.md b/docs/pregate.md index 641cd22e5..4abfcd628 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 while using under a tenth of one 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)) | @@ -459,10 +459,17 @@ 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 + stays under a tenth of one 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. Linux reads `/proc` (exited children's time included once + reaped); macOS and other BSDs read `ps -S`; a failed read skips that + sample. 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 42c2a96ce..56add0826 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -3917,14 +3917,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 under a tenth of one CPU (Windows: log growth alone), 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..1a67ff05a 100644 --- a/lib/pregate/checks/guards.ts +++ b/lib/pregate/checks/guards.ts @@ -20,7 +20,7 @@ import { baseInputs, sha256 } from '../context'; import { classifyCommandEnvironment, classifyEnvironment, environmentLine, environmentResult, launchCause } from '../environment'; import { launchRuntime } from '../runtime'; import { checkScratch } from '../run-scratch'; -import { readRange, supervise } from '../supervise'; +import { readRange, STALL_IDLE, supervise } from '../supervise'; import type { EnvironmentCause } from '../types'; import type { CheckDef, CheckResult, PregateContext } from '../types'; @@ -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${STALL_IDLE}; 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..2e16b61f5 100644 --- a/lib/pregate/checks/lanes.ts +++ b/lib/pregate/checks/lanes.ts @@ -39,7 +39,7 @@ import { isDeviceDart, listRepoFiles, readRepoFile } from '../import-graph'; import { selectLanes, type Selection } from '../lane-selection'; import { launchRuntime } from '../runtime'; import { cargoModel, type CargoModel } from '../rust'; -import { adapterFor, readRange, supervise, type Counter, type Supervised } from '../supervise'; +import { adapterFor, readRange, STALL_IDLE, supervise, type Counter, type Supervised } from '../supervise'; import { verifyFromRun } from '../../run-evidence'; import { matchesAny } from '../../ship-policy'; import type { CheckDef, CheckResult, PregateContext, RemoteObligation } from '../types'; @@ -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${STALL_IDLE}; 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..37cc3210e 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,11 @@ export interface Supervised { } const ACTIVE = new Set(); +const USER_HZ = 100; +const CPU_SAMPLE_MS = 1_000; +const CPU_BUSY_SHARE = 0.1; +/** What a stall means beyond silence, for the PREGATE_STALLED detail and the guard line; Windows reads no CPU time. */ +export const STALL_IDLE = process.platform === 'win32' ? '' : ' and its process group used under a tenth of one CPU'; /** SIGKILL every supervised process group still running (the CLI's SIGINT/SIGTERM handler, before it exits). */ export function cancelActive(): number { @@ -80,6 +87,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', '-S', '-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 +142,8 @@ export function supervise(o: SuperviseOptions): Promise { let readAt = start; let partial = ''; let lastGrowth = started; + let lastBusy = started; + let cpu = { at: started, ms: 0 }; let lastProgress = started; let current: { file: string; at: number; failed: boolean } | null = null; let lastFile: string | null = null; @@ -184,7 +218,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 && process.platform !== 'win32' && 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 = { at: now, ms: used ?? cpu.ms }; + } + 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..8bb6f4089 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 for the stall timeout while its process group used under a tenth of one CPU (log growth alone on Windows), so the 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/package.json b/package.json index 014883f88..bb9e0c261 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "gstack", - "version": "1.93.34", + "version": "1.93.35", "description": "Garry's Stack — Claude Code skills + fast headless browser. One repo, one install, entire AI engineering workflow.", "license": "MIT", "type": "module", 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 });