From 59acf5759ed183b5e9cb5a0440d02c7d88c512ac Mon Sep 17 00:00:00 2001 From: Garry Tan Date: Mon, 31 Aug 2026 04:50:31 +0000 Subject: [PATCH] =?UTF-8?q?feat:=20two-phase=20session=20timeout=20?= =?UTF-8?q?=E2=80=94=20silent=20APIs=20die=20at=20the=20startup=20grace,?= =?UTF-8?q?=20named?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The single spawn-armed timer charged API queue latency to the work budget: the recurring '0 turns / $0.00 / x3 attempts' failure with four budget-bump receipts (180->300s, 240->360s, 300->420s, 90->300s). Split: startup phase (no NDJSON byte yet) kills EARLY at min(grace, timeout) with the distinct exitReason 'timeout_startup' — an availability verdict, not transcript archaeology — and the work phase arms on the first byte for the REMAINING budget, so total wall never exceeds the timeout (tier envelopes are margin-free: tests pass timeout: CAPTURE_MS and bun-budget the same tier). Local grace 90s (observed queue latency 60-90s), CI floor 300s (TODOS-filed; shared runners queue harder), both pinned by the new grace tests with fake -claude shims covering the late-first-byte and silent-API paths. Co-Authored-By: Claude Fable 5 --- test/helpers/session-runner.ts | 52 +++++++++-- test/session-runner-groupkill.test.ts | 5 +- test/session-runner-startup-grace.test.ts | 102 ++++++++++++++++++++++ 3 files changed, 153 insertions(+), 6 deletions(-) create mode 100644 test/session-runner-startup-grace.test.ts diff --git a/test/helpers/session-runner.ts b/test/helpers/session-runner.ts index 34e62b325..58071d163 100644 --- a/test/helpers/session-runner.ts +++ b/test/helpers/session-runner.ts @@ -55,6 +55,14 @@ export interface SkillTestResult { maxInterTurnMs: number; } +/** Local default startup grace: 90s covers observed API queue latency + * (60-90s receipts) without letting a dead API burn a 600s budget. */ +export const STARTUP_GRACE_MS = 90_000; +/** CI floor (TODOS-filed): shared runners queue harder; killing startup + * before 300s in CI converts ordinary queueing into false failures. + * Pinned by test/session-runner-startup-grace.test.ts. */ +export const STARTUP_GRACE_CI_FLOOR_MS = 300_000; + const BROWSE_ERROR_PATTERNS = [ /Unknown command: \w+/, /Unknown snapshot flag: .+/, @@ -134,6 +142,15 @@ export async function runSkillTest(options: { * per-test GSTACK_HOME overrides so the test doesn't have to spell out * env setup in the prompt itself. */ env?: Record; + /** Startup-phase deadline: if NO NDJSON byte arrives within this window, + * the run is killed EARLY with exitReason 'timeout_startup' instead of + * burning the whole work budget waiting on an API that is not answering + * (the recurring '0 turns / $0.00' class — four budget-bump receipts). + * Defaults to min(STARTUP_GRACE_MS, timeout); the CI floor is higher + * because CI queueing is real. Total wall stays <= timeout either way — + * bun-level tier budgets are sized to the runner timeout with no margin, + * so this phase split must never extend the envelope. */ + startupGraceMs?: number; }): Promise { const { prompt, @@ -145,6 +162,10 @@ export async function runSkillTest(options: { runId, env: extraEnv, } = options; + const startupGraceMs = Math.min( + options.startupGraceMs ?? (process.env.CI ? STARTUP_GRACE_CI_FLOOR_MS : STARTUP_GRACE_MS), + timeout, + ); const model = options.model ?? process.env.EVALS_MODEL ?? 'claude-sonnet-4-6'; const startTime = Date.now(); @@ -206,13 +227,21 @@ export async function runSkillTest(options: { proc.on('error', () => resolve(1)); }); - // Race against timeout + // Two-phase timeout. Phase 1 (startup): no NDJSON byte yet — a shorter + // deadline kills a non-answering API run EARLY and names it, instead of + // the old single timer burning the full work budget to produce an opaque + // '0 turns / $0.00' failure. Phase 2 (work): armed by the read loop when + // the FIRST byte arrives, for the REMAINING budget — total wall is always + // <= timeout (tier envelopes are margin-free by convention). let stderr = ''; let exitReason = 'unknown'; let timedOut = false; + let timedOutInStartup = false; + let phaseTimer: ReturnType; - const timeoutId = setTimeout(() => { + const killRun = (startupPhase: boolean): void => { timedOut = true; + timedOutInStartup = startupPhase; // Group SIGKILL (mirrors runShardChild): claude AND every tool // subprocess it spawned die together — a bare proc.kill() left orphans // that inherited our stdout/stderr pipes and kept the API burning @@ -222,7 +251,13 @@ export async function runSkillTest(options: { // Belt and braces with the group kill: even if an orphan survives (EPERM // fallback path), cancel() unblocks the read loop below. reader.cancel().catch(() => { /* stream already closed */ }); - }, timeout); + }; + phaseTimer = setTimeout(() => killRun(true), startupGraceMs); + /** Called once by the read loop on the first NDJSON byte. */ + const armWorkPhase = (elapsedMs: number): void => { + clearTimeout(phaseTimer); + phaseTimer = setTimeout(() => killRun(false), Math.max(0, timeout - elapsedMs)); + }; // Stream NDJSON from stdout for real-time progress const collectedLines: string[] = []; @@ -251,6 +286,9 @@ export async function runSkillTest(options: { // Track time to first NDJSON line (measures latency from spawn to first Claude response) if (firstResponseMs === 0) { firstResponseMs = Date.now() - startTime; + // First byte: startup phase over — arm the work phase for the + // REMAINING budget (total wall stays <= timeout). + armWorkPhase(firstResponseMs); } // Real-time progress to stderr + persistent logs @@ -327,10 +365,14 @@ export async function runSkillTest(options: { })(), ]); const exitCode = await procExited; - clearTimeout(timeoutId); + clearTimeout(phaseTimer); if (timedOut) { - exitReason = 'timeout'; + // 'timeout_startup' = the API never sent a byte inside the grace — an + // availability problem, not a test failure worth reading transcripts + // for. Distinct so triage (and WS10's inconclusive classification) can + // key off it without receipts archaeology. + exitReason = timedOutInStartup ? 'timeout_startup' : 'timeout'; } else if (exitCode === 0) { exitReason = 'success'; } else { diff --git a/test/session-runner-groupkill.test.ts b/test/session-runner-groupkill.test.ts index eb7faf3be..1011813a1 100644 --- a/test/session-runner-groupkill.test.ts +++ b/test/session-runner-groupkill.test.ts @@ -59,7 +59,10 @@ describe('session-runner timeout kills the whole process group', () => { }); const wall = Date.now() - started; - expect(result.exitReason).toBe('timeout'); + // The shim never prints NDJSON, so the two-phase timer kills it in the + // STARTUP phase (grace = min(default, timeout) = 3s here) — the + // distinct reason is the point: no byte ever arrived. + expect(result.exitReason).toBe('timeout_startup'); // The old bug's signature was the drain blocking long past the budget // (600s -> 1400s). Generous 10x bound: timeout 3s + the 5s stderr // grace race must return promptly once the group is dead. diff --git a/test/session-runner-startup-grace.test.ts b/test/session-runner-startup-grace.test.ts new file mode 100644 index 000000000..23d04f2b1 --- /dev/null +++ b/test/session-runner-startup-grace.test.ts @@ -0,0 +1,102 @@ +/** + * Two-phase timeout pins for the claude session runner (WS4c). + * + * The old single timer charged API queue latency to the work budget — the + * recurring '0 turns / $0.00 / x3 attempts' failure with four budget-bump + * receipts (180→300s, 240→360s, 300→420s, 90→300s). The split: + * startup phase — no NDJSON byte yet; killed at the grace with the + * DISTINCT reason 'timeout_startup' (availability, not behavior); + * work phase — armed on the first byte for the REMAINING budget, so the + * total wall never exceeds `timeout` (tier envelopes are margin-free: + * tests pass `timeout: CAPTURE_MS` and use the same tier as bun budget). + * + * Also pins the TODOS-filed 300s CI startup floor: shared CI runners queue + * harder, and a floor below 300s converts ordinary queueing into false reds. + */ +import { describe, expect, test } from 'bun:test'; +import * as fs from 'node:fs'; +import * as os from 'node:os'; +import * as path from 'node:path'; +import { + runSkillTest, + STARTUP_GRACE_CI_FLOOR_MS, + STARTUP_GRACE_MS, +} from './helpers/session-runner'; + +describe('session-runner two-phase timeout', () => { + test('CI startup-grace floor is 300s and the local default is sane', () => { + expect(STARTUP_GRACE_CI_FLOOR_MS).toBe(300_000); + expect(STARTUP_GRACE_MS).toBeGreaterThanOrEqual(60_000); + expect(STARTUP_GRACE_MS).toBeLessThanOrEqual(STARTUP_GRACE_CI_FLOOR_MS); + }); + + test('a run whose first byte arrives late still gets its work budget honored within the total', async () => { + // Fake claude: silent for 2s (startup latency), then streams NDJSON and + // wedges. startupGraceMs=4s tolerates the latency; work budget then + // kills at ~timeout. exitReason must be plain 'timeout' (work phase), + // NOT 'timeout_startup', and the wall must respect the total envelope. + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'grace-')); + const shimDir = path.join(dir, 'bin'); + fs.mkdirSync(shimDir); + fs.writeFileSync(path.join(shimDir, 'claude'), [ + '#!/bin/bash', + 'sleep 2', + 'echo \'{"type":"system","subtype":"init"}\'', + 'exec sleep 6071', + ].join('\n') + '\n', { mode: 0o755 }); + + const realPath = process.env.PATH; + process.env.PATH = `${shimDir}:${realPath}`; + try { + const started = Date.now(); + const result = await runSkillTest({ + prompt: 'ignored', + workingDirectory: dir, + maxTurns: 1, + timeout: 5_000, + startupGraceMs: 4_000, + testName: 'grace-probe-work-phase', + }); + const wall = Date.now() - started; + expect(result.exitReason).toBe('timeout'); + expect(result.firstResponseMs).toBeGreaterThanOrEqual(1_500); + // Total envelope: startup consumed ~2s, work phase gets the remainder — + // wall ≈ timeout (5s) + stderr grace (5s), never grace+timeout stacked. + expect(wall).toBeLessThan(20_000); + } finally { + process.env.PATH = realPath; + Bun.spawnSync(['pkill', '-f', 'sleep 6071'], { timeout: 5_000 }); + fs.rmSync(dir, { recursive: true, force: true }); + } + }, 60_000); + + test('a silent API is killed at the grace, early, with the startup reason', async () => { + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'grace-')); + const shimDir = path.join(dir, 'bin'); + fs.mkdirSync(shimDir); + fs.writeFileSync(path.join(shimDir, 'claude'), '#!/bin/bash\nexec sleep 6072\n', { mode: 0o755 }); + + const realPath = process.env.PATH; + process.env.PATH = `${shimDir}:${realPath}`; + try { + const started = Date.now(); + const result = await runSkillTest({ + prompt: 'ignored', + workingDirectory: dir, + maxTurns: 1, + timeout: 30_000, // generous work budget… + startupGraceMs: 2_000, // …but startup dies fast when nothing answers + testName: 'grace-probe-startup', + }); + const wall = Date.now() - started; + expect(result.exitReason).toBe('timeout_startup'); + // The whole point: ~2s + drain grace, NOT the 30s work budget. + expect(wall).toBeLessThan(15_000); + expect(result.costEstimate.turnsUsed).toBe(0); + } finally { + process.env.PATH = realPath; + Bun.spawnSync(['pkill', '-f', 'sleep 6072'], { timeout: 5_000 }); + fs.rmSync(dir, { recursive: true, force: true }); + } + }, 60_000); +});