diff --git a/bin/gstack-pregate b/bin/gstack-pregate index f377afa3a..afc5e42a2 100755 --- a/bin/gstack-pregate +++ b/bin/gstack-pregate @@ -61,7 +61,8 @@ const HELP = `gstack-pregate — cheap checks before anything paid or remote (do --allow-repo-commands run pin-file commands and the test runner (what /ship passes); without it those checks are incomplete --policy-from base|head base (default, reviewed) or head (unreviewed; needs --allow-repo-commands) --out pregate.json path (default ${PREGATE_OUT_REL}) - --timeout per-check timeout (default 600): it bounds the whole check, every runner process included + --timeout timeout for each runner process (default 600): the unit-file group, each serial file, each guard + without timeout_s; the stall timeout catches a silent one sooner --stall-timeout kill a test command's process group after this long with no output and record the check incomplete (PREGATE_STALLED); default stall_timeout_s from the base .gstack/pregate.json, else ${DEFAULT_STALL_TIMEOUT_S}; 0 disables diff --git a/docs/pregate.md b/docs/pregate.md index 4205d81bd..7ec5d374d 100644 --- a/docs/pregate.md +++ b/docs/pregate.md @@ -127,9 +127,10 @@ Two stages with separate clocks, both printed: the project's `engines.bun` (the row prints `runtime: bun from `), so a Capy host's older image Bun cannot flip the verdict. - Every test-tier command (the lanes runner, each guard, the `--remote` gate) - runs supervised: see [supervision](#supervision). `--timeout` bounds the - whole check (all runner processes together); a serial file that would start - after the deadline is not started and the check is `incomplete`. + runs supervised: see [supervision](#supervision). `--timeout` bounds each + runner process (the unit-file group, each serial file, each guard without + its own `timeout_s`), not their total; the stall timeout catches a hung or + silent one sooner. - Under 8 cores, a base-branch `remote_gate` or a remote `test_backend` (`gstack-config set test_backend ubicloud`) records the local test tier as a `requires-remote` obligation instead of running it: see [remote gate](#remote-gate). @@ -157,9 +158,10 @@ gstack lacks never gets a green it did not ask for). Tier 2 checks still to come ## Supervision: progress, stalls, deadlines GBRA-95 (gbrain, 4 cores): a core edit selected 3,683 local files, 358 of them -serial; the test stage printed nothing for 90 minutes because each runner -process had its own `--timeout` and its output was buffered until it returned. -Now each test-tier command: +serial; the test stage printed nothing for 90 minutes: each runner process +ran up to its own `--timeout` (one per serial file) with its output buffered +until it returned, and nothing noticed a process that had gone quiet. Now each +test-tier command: - runs in its own process group (`setsid`), with stdout and stderr appended to a log file, never a pipe, so a backgrounded grandchild that keeps the output @@ -182,7 +184,9 @@ Now each test-tier command: (`--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; -- is killed as **timed out** at the check's `--timeout` deadline. +- is killed as **timed out** when that runner process reaches `--timeout` + (per runner process, so many serial files that each fit still pass); the + check is `incomplete` and the next serial file still runs. A kill is SIGTERM to the group, then SIGKILL after 5 s (a group that ignores SIGTERM still dies). SIGINT or SIGTERM to `gstack-pregate` itself SIGKILLs every diff --git a/lib/pregate/checks/lanes.ts b/lib/pregate/checks/lanes.ts index 7b155af59..a4419adc2 100644 --- a/lib/pregate/checks/lanes.ts +++ b/lib/pregate/checks/lanes.ts @@ -49,13 +49,13 @@ export function parseSummary(output: string): RunnerSummary { return { ran: null, failed: null }; } -interface LocalRun { exit: number | null; outcome: Supervised['outcome'] | 'not-started'; ran: number | null; failed: number | null; tail: string[]; command: string; files: string[]; lastFile: string | null; ms: number } +interface LocalRun { exit: number | null; outcome: Supervised['outcome']; ran: number | null; failed: number | null; tail: string[]; command: string; files: string[]; lastFile: string | null; ms: number } const quote = (f: string) => `'${f.replace(/'/g, `'\\''`)}'`; -async function runOnce(ctx: PregateContext, env: NodeJS.ProcessEnv, runner: string, files: string[], log: string, deadline: number, counter: Counter): Promise { +async function runOnce(ctx: PregateContext, env: NodeJS.ProcessEnv, runner: string, files: string[], log: string, counter: Counter): Promise { const command = runner.replace('{files}', files.map(quote).join(' ')); - const r = await supervise({ command, cwd: ctx.repoRoot, env: { ...env, CI: env.CI ?? '1' }, log, deadline, stallMs: ctx.stallTimeoutMs, label: `lanes (${files.length === 1 ? files[0] : `${files.length} files`})`, files, adapter: adapterFor(runner), counter, progress: ctx.progress }); + const r = await supervise({ command, cwd: ctx.repoRoot, env: { ...env, CI: env.CI ?? '1' }, log, deadline: Date.now() + ctx.timeoutMs, stallMs: ctx.stallTimeoutMs, label: `lanes (${files.length === 1 ? files[0] : `${files.length} files`})`, files, adapter: adapterFor(runner), counter, progress: ctx.progress }); const output = readRange(log, r.start, r.end); const summary = parseSummary(output); return { exit: r.exit, outcome: r.outcome, ...summary, tail: output.trim().split('\n').slice(-25), command, files, lastFile: r.lastFile, ms: r.ms }; @@ -64,8 +64,8 @@ async function runOnce(ctx: PregateContext, env: NodeJS.ProcessEnv, runner: stri /** * Unit files in one runner process, then each serial-pattern file in its * own (a serial file shares process-wide state: a module mock, an env - * mutation). `--timeout` bounds the whole check: a group that would start - * after the deadline is not started. A stalled group is killed and the next + * mutation). `--timeout` bounds each runner process; the stall timeout + * catches a silent one. A stalled or timed-out group is killed and the next * one runs. The first unfinished, then the first non-zero run decides the * exit; counts add up only when every run reported a summary. */ @@ -75,29 +75,26 @@ async function runLocal(ctx: PregateContext, env: NodeJS.ProcessEnv, runner: str fs.writeFileSync(log, ''); const serial = files.filter(f => matchesAny(ctx.config.serial_patterns, f)); const unit = files.filter(f => !serial.includes(f)); - const deadline = Date.now() + ctx.timeoutMs; const counter: Counter = { done: 0, total: files.length }; const runs: LocalRun[] = []; for (const group of [...(unit.length ? [unit] : []), ...serial.map(f => [f])]) { - if (Date.now() >= deadline) { runs.push({ exit: null, outcome: 'not-started', ran: null, failed: null, tail: [], command: '', files: group, lastFile: null, ms: 0 }); continue; } - runs.push(await runOnce(ctx, env, runner, group, log, deadline, counter)); + runs.push(await runOnce(ctx, env, runner, group, log, counter)); } const bad = runs.find(r => r.exit === null) ?? runs.find(r => r.exit !== 0); const sum = (k: 'ran' | 'failed') => (runs.some(r => r[k] === null) ? null : runs.reduce((n, r) => n + (r[k] as number), 0)); - const started = runs.filter(r => r.outcome !== 'not-started'); - return { runs, bad, exit: bad ? bad.exit : 0, ran: sum('ran'), failed: sum('failed'), log, tail: (bad?.tail.length ? bad : started[started.length - 1] ?? runs[0]!).tail, command: started.map(r => r.command).join(' && '), serial: serial.length }; + return { runs, bad, exit: bad ? bad.exit : 0, ran: sum('ran'), failed: sum('failed'), log, tail: (bad ?? runs[runs.length - 1]!).tail, command: runs.map(r => r.command).join(' && '), serial: serial.length }; } -/** Why the local lane did not finish: the stall, the deadline or a launch failure, with the last file started. */ +/** Why the local lane did not finish: a stall, a runner process past --timeout or a launch failure, with the last file started. */ function unfinished(ctx: PregateContext, r: Awaited>, total: number): Pick { - const notStarted = r.runs.filter(x => x.outcome === 'not-started').flatMap(x => x.files).length; const stalled = r.runs.filter(x => x.outcome === 'stalled'); - const rest = `${notStarted ? `; ${notStarted} of ${total} file(s) not started` : ''}${r.failed ? `; ${r.failed} failed before that` : ''}`; + 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 .gstack/pregate.json; 0 disables) for a test that is quiet for longer` }; } - const why = r.runs.find(x => x.outcome === 'spawn-failed') ? 'the runner could not be launched' : `local lane timed out after ${ctx.timeoutMs} ms`; - return { code: 'PREGATE_INCOMPLETE', detail: `${why} (${total} files${rest})`, fix: 'raise --timeout or split the selection; a timed-out lane never passes' }; + if (!timedOut.length) return { code: 'PREGATE_INCOMPLETE', detail: `the runner could not be launched (${total} files${rest})`, fix: 'read the lane log, fix the runner command, then rerun gstack-pregate --stage tests' }; + return { code: 'PREGATE_INCOMPLETE', detail: `a runner process timed out after ${ctx.timeoutMs} ms (--timeout applies to each runner process; ${total} files; last file started: ${timedOut.map(x => x.lastFile ?? `(none reported; ${x.files.length} file(s))`).join(', ')}${rest})`, fix: 'raise --timeout or split the selection; a timed-out lane never passes' }; } function describe(sel: Selection): string[] { diff --git a/test/pregate-supervise.test.ts b/test/pregate-supervise.test.ts index 3696bac70..114ba6a99 100644 --- a/test/pregate-supervise.test.ts +++ b/test/pregate-supervise.test.ts @@ -182,15 +182,18 @@ describe('gstack-pregate: the test stage never hangs silently', () => { expect(alive(Number(fs.readFileSync(path.join(repo.root, 'bg.pid'), 'utf8')))).toBe(false); }, 90_000); - test('--timeout bounds the whole check: serial files past the deadline are not started and the lane is incomplete', () => { + test('--timeout bounds each runner process: serial files that each fit run to a pass even when their total exceeds it; one that overruns is incomplete', () => { const repo = makeFixtureRepo(); repos.push(repo); - const slow = "const test = require('node:test');\ntest('slow', async () => { await new Promise(r => setTimeout(r, 2500)); });\n"; + const slow = "const test = require('node:test');\ntest('slow', async () => { await new Promise(r => setTimeout(r, 1500)); });\n"; commit(repo, { 'test/a.serial.test.js': slow, 'test/b.serial.test.js': slow, 'test/c.serial.test.js': slow }); - const r = pregate(repo, ['--timeout', '4']); - expect(r.status).toBe(EXIT.fail); - const row = lanes(repo); - expect(row).toMatchObject({ status: 'incomplete', code: 'PREGATE_INCOMPLETE' }); - expect(row.detail).toMatch(/local lane timed out after 4000 ms \(3 files; 1 of 3 file\(s\) not started\)/); + const r = pregate(repo, ['--timeout', '3']); + expect(r.status).toBe(EXIT.ok); + expect(lanes(repo)).toMatchObject({ status: 'pass' }); + expect(lanes(repo).detail).toContain('3 tests ran in 3 file(s) (3 serial), exit 0'); + commit(repo, { 'test/c.serial.test.js': "const test = require('node:test');\ntest('slower', async () => { await new Promise(r => setTimeout(r, 5000)); });\n" }); + expect(pregate(repo, ['--timeout', '3']).status).toBe(EXIT.fail); + expect(lanes(repo)).toMatchObject({ status: 'incomplete', code: 'PREGATE_INCOMPLETE' }); + expect(lanes(repo).detail).toContain('a runner process timed out after 3000 ms (--timeout applies to each runner process; 3 files; last file started: test/c.serial.test.js)'); }, 90_000); test('a late tree mutation by a test\'s child is caught while the check runs, and a leftover child cannot mutate the tree after it', async () => {