From 47f18713850bc75c1fd352912c4131e64c47c3dd Mon Sep 17 00:00:00 2001 From: Paul Bakaus Date: Tue, 1 Sep 2026 11:09:44 -0700 Subject: [PATCH] Tests: stop two harness hangs from wedging a whole run Two suites could hang forever and never print a tally, because the one mechanism that could interrupt the wedged work was missing on both paths. Hang 1 (bun run test / build-phase.test.mjs): the test's run() helper spawned every child with spawnSync and no timeout. spawnSync blocks the test worker's thread, so node's --test-timeout (an event-loop timer) cannot interrupt a child that wedges (a fork/exec blocked on OS resources under concurrency, a gate's comp-diff grandchild, or a stray browser launch). Bound every child with spawnSync timeout + killSignal SIGKILL so a wedge becomes a fast, named failure the next test survives. Hang 2 (bun run test:skill-behavior): runTurn called generateText with no client-side deadline, so a stalled provider stream kept the fetch (and the whole node process) alive past the per-test timeout, producing no tally. Attach a real AbortSignal (default 840s, under the 900s per-test cap): on expiry the fetch aborts, the turn throws, and the scenario fails-and-continues. The unref'd timer is cleared on completion. Runner backstops: run-tests.mjs now spawns each command as a detached process-group leader and enforces a per-suite wall-clock cap that SIGKILLs the entire group (workers, grandchildren, browsers) on expiry, with SIGINT/SIGTERM forwarded so Ctrl-C still reaps the tree. The core node batch gets a finite --test-timeout (180s); skill-behavior gets a 60min group cap. Env overrides: IMPECCABLE_TEST_WALL_CLOCK_MS, IMPECCABLE_SKILL_BEHAVIOR_TURN_TIMEOUT_MS, IMPECCABLE_BUILD_PHASE_RUN_TIMEOUT_MS. Proof: bun run test green twice (~60s); scoped claude-sonnet-5 skill-behavior sweep terminates with a tally (20 tests, ~32min) where the 840s abort caught a wedged redesign turn and the sweep continued instead of hanging. Prepared with AI assistance (Claude Code). --- scripts/run-tests.mjs | 89 +++++++++++++++++++++++++------- scripts/test-suites.mjs | 14 +++++ tests/build-phase.test.mjs | 22 +++++++- tests/skill-behavior/harness.mjs | 28 +++++++++- 4 files changed, 130 insertions(+), 23 deletions(-) diff --git a/scripts/run-tests.mjs b/scripts/run-tests.mjs index 556d5a54e..88f92a3cc 100644 --- a/scripts/run-tests.mjs +++ b/scripts/run-tests.mjs @@ -1,7 +1,13 @@ #!/usr/bin/env node -import { spawnSync } from 'node:child_process'; +import { spawn } from 'node:child_process'; import { DEFAULT_SUITES, OPT_IN_SUITES, SUITES, expandSuites } from './test-suites.mjs'; +// Global wall-clock backstop for any one command. Even with per-test timeouts +// and client-side network deadlines in place, a wedged tool or an orphaned +// grandchild can keep a runner alive forever; this cap guarantees the sweep +// terminates. Per-suite `wallClockMs` overrides it; the env var overrides both. +const DEFAULT_WALL_CLOCK_MS = Number(process.env.IMPECCABLE_TEST_WALL_CLOCK_MS) || 1_200_000; + const args = process.argv.slice(2); if (args.includes('--help') || args.includes('-h')) { @@ -23,19 +29,24 @@ try { process.exit(1); } -for (const suiteName of suites) { - const suite = SUITES[suiteName]; - console.log(`\n## test:${suiteName}`); - console.log(suite.description); - for (const command of suite.commands) { - runCommand(command); +await main(); + +async function main() { + for (const suiteName of suites) { + const suite = SUITES[suiteName]; + console.log(`\n## test:${suiteName}`); + console.log(suite.description); + for (const command of suite.commands) { + await runCommand(command); + } } } -function runCommand(command) { +async function runCommand(command) { const env = { ...process.env, ...(command.env || {}) }; + const wallClockMs = command.wallClockMs ?? DEFAULT_WALL_CLOCK_MS; if (command.runner === 'bun') { - runProcess('bun', ['test', ...command.files], { env }); + await runProcess('bun', ['test', ...command.files], { env, wallClockMs }); return; } @@ -50,24 +61,62 @@ function runCommand(command) { if (command.timeoutMs) args.push(`--test-timeout=${command.timeoutMs}`); if (command.forceExit) args.push('--test-force-exit'); args.push(...command.files); - runProcess(process.execPath, args, { env }); + await runProcess(process.execPath, args, { env, wallClockMs }); return; } throw new Error(`Unsupported test runner "${command.runner}"`); } -function runProcess(cmd, args, { env }) { - console.log(`$ ${formatCommand(cmd, args)}`); - const result = spawnSync(cmd, args, { - stdio: 'inherit', - env, +// Spawn as a detached process-group leader so the wall-clock cap can SIGKILL +// the entire tree — the runner, its per-file `node --test` workers, and any +// grandchildren or browsers they left open — not just the top process. A +// blocked spawnSync inside a test can't be reached by node's `--test-timeout`; +// this group kill is the guaranteed cleanup that lets the sweep always end. +function runProcess(cmd, args, { env, wallClockMs }) { + return new Promise((resolve) => { + console.log(`$ ${formatCommand(cmd, args)}`); + const child = spawn(cmd, args, { stdio: 'inherit', env, detached: true }); + let timedOut = false; + // A detached child is its own group leader, so an interactive Ctrl-C on + // the runner no longer reaches it. Forward the interrupt to the group so + // the whole tree is torn down instead of orphaned. + const forward = (signal) => () => { + try { process.kill(-child.pid, signal); } catch { try { child.kill(signal); } catch { /* gone */ } } + }; + const onInt = forward('SIGINT'); + const onTerm = forward('SIGTERM'); + process.on('SIGINT', onInt); + process.on('SIGTERM', onTerm); + const timer = wallClockMs + ? setTimeout(() => { + timedOut = true; + console.error( + `\n[run-tests] wall-clock cap of ${wallClockMs}ms exceeded for "${formatCommand(cmd, args)}"; ` + + 'killing the process group (SIGKILL).', + ); + try { process.kill(-child.pid, 'SIGKILL'); } + catch { try { child.kill('SIGKILL'); } catch { /* already gone */ } } + }, wallClockMs) + : null; + const cleanup = () => { + if (timer) clearTimeout(timer); + process.off('SIGINT', onInt); + process.off('SIGTERM', onTerm); + }; + child.on('error', (err) => { + cleanup(); + console.error(err.message); + process.exit(1); + }); + child.on('exit', (code, signal) => { + cleanup(); + if (timedOut) process.exit(1); + if (signal) { console.error(`[run-tests] "${formatCommand(cmd, args)}" killed by signal ${signal}`); process.exit(1); } + if (code !== 0) process.exit(code || 1); + resolve(); + }); }); - if (result.error) { - console.error(result.error.message); - process.exit(1); - } - if (result.status !== 0) process.exit(result.status || 1); } function formatCommand(cmd, args) { diff --git a/scripts/test-suites.mjs b/scripts/test-suites.mjs index b0fed8df3..c70eb7f58 100644 --- a/scripts/test-suites.mjs +++ b/scripts/test-suites.mjs @@ -48,6 +48,13 @@ export const SUITES = { }, { runner: 'node', + // A finite per-test cap so an async hang is cancelled and reported + // rather than left running with `--test-timeout` unset (Infinity). + // Note: this timer lives in the event loop, so it cannot interrupt a + // test blocked in a synchronous spawnSync; the child bounds in + // tests/build-phase.test.mjs and the runner's wall-clock group-kill + // cover that case. The slowest core test is ~11s, so 180s is safe. + timeoutMs: 180000, files: [ 'tests/build-phase.test.mjs', 'tests/ci-test-plan.test.mjs', @@ -255,6 +262,13 @@ export const SUITES = { // path is graded, so the cap was selecting for the behavior the suite // exists to forbid. timeoutMs: 900000, + // Overall wall-clock safety cap for the whole sweep: if a provider + // call wedges past every inner guard (the harness's 840s per-turn + // AbortSignal and the 900s per-test timeout), the runner SIGKILLs the + // process group so the sweep still ends with a per-provider tally + // instead of hanging overnight. Sized well above a healthy two-provider + // sweep; override with IMPECCABLE_TEST_WALL_CLOCK_MS to scope it down. + wallClockMs: 3_600_000, files: [ 'tests/skill-behavior/scenarios.test.mjs', 'tests/skill-behavior/workflow-contract.test.mjs', diff --git a/tests/build-phase.test.mjs b/tests/build-phase.test.mjs index 68407d303..141258fd5 100644 --- a/tests/build-phase.test.mjs +++ b/tests/build-phase.test.mjs @@ -33,8 +33,28 @@ function makeComp(w = 640, h = 400) { return img; } +// Every child here is spawned synchronously. spawnSync blocks the test +// worker's thread, so node's own `--test-timeout` (an event-loop timer) can +// never interrupt a child that wedges — under load a fork/exec can block on +// OS resources, and a gate's grandchild (comp-diff.mjs) or an accidental +// browser launch can stall. spawnSync's own `timeout`/`killSignal` is the one +// mechanism that can kill such a child, so bound every run: a wedge becomes a +// fast, named failure that the next test survives, never a suite-wide hang. +const RUN_TIMEOUT_MS = Number(process.env.IMPECCABLE_BUILD_PHASE_RUN_TIMEOUT_MS) || 120_000; function run(script, args, cwd) { - return spawnSync(process.execPath, [script, ...args], { cwd, encoding: 'utf8' }); + const res = spawnSync(process.execPath, [script, ...args], { + cwd, + encoding: 'utf8', + timeout: RUN_TIMEOUT_MS, + killSignal: 'SIGKILL', + }); + if (res.error && (res.error.code === 'ETIMEDOUT' || res.signal === 'SIGKILL')) { + throw new Error( + `build-phase child timed out after ${RUN_TIMEOUT_MS}ms and was killed (SIGKILL): ` + + `node ${script} ${args.join(' ')}\nstdout so far:\n${res.stdout || ''}\nstderr so far:\n${res.stderr || ''}`, + ); + } + return res; } describe('comp-spec', () => { diff --git a/tests/skill-behavior/harness.mjs b/tests/skill-behavior/harness.mjs index 98898a6fb..2bcca2b9b 100644 --- a/tests/skill-behavior/harness.mjs +++ b/tests/skill-behavior/harness.mjs @@ -347,13 +347,31 @@ export function makeTools(workspace, extraEnv = {}, simulatedUser = {}) { * `priorMessages` lets multi-turn scenarios chain context from a previous * call (append the SDK's response messages between turns). */ -export async function runTurn({ workspace, model, userPrompt, priorMessages = [], maxSteps = 8, env = {}, simulatedUser = {} }) { +// A single turn (generateText) can drive up to ~30 tool-use steps against a +// frontier model; the thorough path was measured near 580s. generateText +// takes no timeout of its own, so a provider socket that stalls mid-stream +// keeps the fetch — and therefore the whole node process — alive indefinitely, +// past node's own `--test-timeout` (which cancels the test but not the open +// handle). We attach a real AbortSignal instead: on expiry the underlying +// fetch is aborted, the socket closes, the turn throws, and the scenario +// fails-and-continues so the sweep still produces a per-provider tally. The +// cap sits just under the 900s per-test timeout so a genuine slow-but-correct +// run is never killed. The timer is unref'd (it must not keep the loop alive +// after a healthy turn) and cleared on completion. +const TURN_TIMEOUT_MS = Number(process.env.IMPECCABLE_SKILL_BEHAVIOR_TURN_TIMEOUT_MS) || 840_000; +export async function runTurn({ workspace, model, userPrompt, priorMessages = [], maxSteps = 8, env = {}, simulatedUser = {}, timeoutMs = TURN_TIMEOUT_MS }) { const { tools, trace } = makeTools(workspace, env, simulatedUser); const messages = [ ...priorMessages, { role: 'user', content: userPrompt }, ]; let result; + const controller = new AbortController(); + const timer = setTimeout( + () => controller.abort(new Error(`LLM turn exceeded ${timeoutMs}ms; aborting the provider call`)), + timeoutMs, + ); + if (typeof timer.unref === 'function') timer.unref(); try { result = await generateText({ model, @@ -361,13 +379,19 @@ export async function runTurn({ workspace, model, userPrompt, priorMessages = [] messages, tools, stopWhen: [stepCountIs(maxSteps)], + // Real client-side deadline on the provider call: without it a stalled + // stream wedges the whole sweep with no tally. + abortSignal: controller.signal, // Resolved from the model object so the 21 runTurn call sites stay // unchanged. Reasoning models run at the provider default otherwise, // which is not the tier this suite is meant to measure. providerOptions: getProviderOptions(model?.modelId ?? ''), }); } catch (err) { - throw new Error(`LLM behavior turn failed before completing: ${String(err)}`, { cause: err }); + const reason = controller.signal.aborted ? ` (aborted after ${timeoutMs}ms client-side timeout)` : ''; + throw new Error(`LLM behavior turn failed before completing${reason}: ${String(err)}`, { cause: err }); + } finally { + clearTimeout(timer); } const generatedResponseMessages = result.responseMessages ?? result.response?.messages ?? []; const responseMessages = [...messages, ...generatedResponseMessages];