mirror of
https://github.com/garrytan/gstack.git
synced 2026-09-09 22:48:57 +02:00
feat: two-phase session timeout — silent APIs die at the startup grace, named
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 <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Fable 5
parent
0c0077100a
commit
59acf5759e
@@ -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<string, string>;
|
||||
/** 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<SkillTestResult> {
|
||||
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<typeof setTimeout>;
|
||||
|
||||
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 {
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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);
|
||||
});
|
||||
Reference in New Issue
Block a user