diff --git a/CHANGELOG.md b/CHANGELOG.md index 899297dca6..72377f8b56 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -26,6 +26,9 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). ## [Unreleased] +### Changed +- fix(quorum): **the stall timer no longer uses byte count as evidence of liveness (STALL-TIMEOUT-03).** `<500 bytes → apply a tighter kill window` was a proxy for "this slot is hung", and a live multi-model quorum falsified it the hard way — by killing three of its own five voters mid-answer. `claude-1` (idle 90s → 90s window), `copilot-1` (idle 30s → 30s), and `claude-z-ai` (90s) were all producing correct output when the timer fired; their partial answers were recoverable from `unavail_message`. `codex-1` and `antigravity-1` survived not because they were faster but because they **stream**, so every chunk rearmed the timer. The discriminator was never byte count. Worse, deriving the window from `idle_timeout_ms` (the #385 fix) made that field do double duty as "how long may this model think before output" — and for most slots the configured value (30s/90s) is far *smaller* than real think time, while the caller had budgeted 300s. There are now two windows, one per failure mode: **before the first byte**, `ttfb_timeout_ms` (default 30s) — zero output is the only honest evidence of a hang, so fast-fail belongs there; **after the first byte**, the inter-chunk ceiling — `inter_chunk_ceiling_ms` if the slot declares one, else the caller's idle budget. `stall_timeout_ms` is kept as a legacy alias for the ceiling, since the values already in that field were measured against post-preamble silence, so no config surface is added. Live-verified: `claude-1` answers in 134s where it previously died at 90s. Measuring also corrected an assumption — the `claude` CLI **buffers** (zero bytes until well past 30s) rather than emitting a preamble like the z-ai/minimax/kimi routes, which is why TTFB is per-slot configurable and why the claude-family slots carry `ttfb_timeout_ms: 150000`. Ratified by quorum (3/3 unanimous, Round 1: codex-1, antigravity-1, claude-minimax) over the alternative of keeping #386 as shipped; debate at `.planning/quorum/debates/2026-08-07-stall-timer-design-decision-a-vs-b.md`. + ## [0.44.3] - 2026-08-07 — Quorum stall-window derivation, no shipped user config, and migration/portability guards diff --git a/bin/call-quorum-slot-stall-timeout.test.cjs b/bin/call-quorum-slot-stall-timeout.test.cjs index 5ee174109a..ba9c9fc75f 100644 --- a/bin/call-quorum-slot-stall-timeout.test.cjs +++ b/bin/call-quorum-slot-stall-timeout.test.cjs @@ -1,10 +1,15 @@ 'use strict'; -// STALL-TIMEOUT-01: the <500-byte "stall" timer was hardcoded to 30s, which -// false-killed slow-bursty models (GLM-5.2[1m], MiniMax-M3 via a third-party -// Anthropic-compatible API) — they emit a short preamble then pause >30s while -// generating. `stall_timeout_ms` on the provider raises the threshold; absent / -// invalid values fall back to the 30s default. +// STALL-TIMEOUT-03 — the timer model a live quorum ruled on (2026-08-07). +// +// The old model asked "has this slot produced < 500 bytes?" and treated that as evidence +// of a hang. A quorum run falsified it by killing three of its own five voters mid-answer: +// they had emitted a ~200-byte preamble in under a second and were thinking in silence. +// Byte count never measured liveness — STREAMING does. So there are now two windows: +// • before the first byte → ttfb_timeout_ms (default 30s), where fast-fail belongs +// • after the first byte → inter_chunk_ceiling_ms, else the caller's idle budget +// `stall_timeout_ms` survives as a legacy alias for the ceiling, because the values +// already in that field were measured against post-preamble silence. const { describe, it } = require('node:test'); const assert = require('node:assert/strict'); @@ -12,130 +17,83 @@ const fs = require('node:fs'); const os = require('node:os'); const path = require('node:path'); const { spawnSync } = require('node:child_process'); -const { stallTimeoutFor, resolveStallTimeout, runSubprocess, parseVerdictLine } = require('./call-quorum-slot.cjs'); +const { resolveTtfbTimeout, resolveInterChunkCeiling, runSubprocess, parseVerdictLine } = require('./call-quorum-slot.cjs'); -describe('stallTimeoutFor — per-slot stall timeout override', () => { - it('defaults to 30000ms when stall_timeout_ms is absent', () => { - assert.equal(stallTimeoutFor({ name: 'codex-1' }), 30000); - assert.equal(stallTimeoutFor({}), 30000); +describe('resolveTtfbTimeout — the only window that may fast-fail', () => { + it('defaults to 30s', () => { + assert.deepEqual(resolveTtfbTimeout({ name: 'codex-1' }), { ms: 30000, source: 'default' }); + assert.deepEqual(resolveTtfbTimeout({}), { ms: 30000, source: 'default' }); }); - it('honors a positive per-slot stall_timeout_ms (the GLM/MiniMax fix)', () => { - assert.equal(stallTimeoutFor({ name: 'claude-z-ai', stall_timeout_ms: 120000 }), 120000); - assert.equal(stallTimeoutFor({ stall_timeout_ms: 90000 }), 90000); + it('honors an explicit per-slot ttfb_timeout_ms', () => { + assert.deepEqual(resolveTtfbTimeout({ ttfb_timeout_ms: 120000 }), { ms: 120000, source: 'per-slot' }); + assert.equal(resolveTtfbTimeout({ ttfb_timeout_ms: '45000' }).ms, 45000); }); - it('accepts a numeric string value', () => { - assert.equal(stallTimeoutFor({ stall_timeout_ms: '120000' }), 120000); + it('is NOT derived from idle_timeout_ms — that derivation was the bug', () => { + // STALL-TIMEOUT-02 derived the kill window from idle_timeout_ms, which made that + // field mean "how long may this model think before output". For copilot-1 (30s) and + // claude-1 (90s) the configured value was far below real think time, so both were + // killed mid-answer. TTFB must ignore it entirely. + assert.deepEqual(resolveTtfbTimeout({ idle_timeout_ms: 90000 }), { ms: 30000, source: 'default' }); + assert.deepEqual(resolveTtfbTimeout({ idle_timeout_ms: 30000 }), { ms: 30000, source: 'default' }); }); - it('falls back to 30000 for non-positive / NaN / null values', () => { - assert.equal(stallTimeoutFor({ stall_timeout_ms: 0 }), 30000); - assert.equal(stallTimeoutFor({ stall_timeout_ms: -5 }), 30000); - assert.equal(stallTimeoutFor({ stall_timeout_ms: 'nope' }), 30000); - assert.equal(stallTimeoutFor({ stall_timeout_ms: null }), 30000); + it('falls back to the default for garbage / non-numeric values', () => { + for (const bad of [0, -5, 'nope', null, true, {}, NaN, -Infinity]) { + assert.equal(resolveTtfbTimeout({ ttfb_timeout_ms: bad }).ms, 30000, `bad=${JSON.stringify(bad)}`); + } }); - it('never returns the bare 30s default for a slot that configured a longer one', () => { - // Regression guard: before STALL-TIMEOUT-01 this was hardcoded 30000 regardless. - assert.notEqual(stallTimeoutFor({ stall_timeout_ms: 120000 }), 30000); - }); - - it('clamps oversized values to TIMEOUT_MAX (Node fires >2^31-1ms timers immediately)', () => { - const MAX = 2147483647; - assert.equal(stallTimeoutFor({ stall_timeout_ms: 3e9 }), MAX); - assert.equal(stallTimeoutFor({ stall_timeout_ms: MAX + 1 }), MAX); - assert.equal(stallTimeoutFor({ stall_timeout_ms: Infinity }), MAX); - assert.equal(stallTimeoutFor({ stall_timeout_ms: MAX }), MAX); // boundary, unchanged - }); - - // ─── ADVERSARIAL: type-coercion gap ────────────────────────────────────────── - it('falls back to 30000 for a boolean true instead of a 1ms stall timer (type-coercion gap)', () => { - // Number(true) === 1, which passes the `v > 0` guard, so a boolean config value - // yields a 1ms stall timeout — every slot is instantly false-killed as STALLed. - // A non-numeric type like a boolean is not a valid duration and must fall back. - assert.equal(stallTimeoutFor({ stall_timeout_ms: true }), 30000); + it('clamps an oversized value to TIMEOUT_MAX (Node fires >2^31-1ms timers immediately)', () => { + assert.equal(resolveTtfbTimeout({ ttfb_timeout_ms: 3e9 }).ms, 2147483647); + assert.equal(resolveTtfbTimeout({ ttfb_timeout_ms: Infinity }).ms, 2147483647); }); }); -// ─── STALL-TIMEOUT-02 (issue #385) ──────────────────────────────────────────── -// The per-slot escape hatch existed but nothing set it: claude-z-ai / claude-minimax -// / claude-kimi ship `idle_timeout_ms: 90000` and no `stall_timeout_ms`, so all three -// were killed at 30s inside their 217–420-byte preamble, every round. An explicitly -// configured idle tolerance now derives the stall window. -describe('resolveStallTimeout — idle-derived stall window (#385)', () => { - it('derives the stall window from the slot\'s configured idle timeout', () => { - // The exact shape of the three false-killed slots. - const zai = { name: 'claude-z-ai', idle_timeout_ms: 90000 }; - assert.deepEqual(resolveStallTimeout(zai, 90000), { ms: 90000, source: 'idle' }); - assert.deepEqual(resolveStallTimeout(zai), { ms: 90000, source: 'idle' }); +describe('resolveInterChunkCeiling — a streaming slot is alive', () => { + it("defaults to the caller's idle budget once bytes are flowing", () => { + // This is the fix for the three killed voters: the caller had budgeted 300s while + // the derived window was 30s/90s. + assert.deepEqual(resolveInterChunkCeiling({ idle_timeout_ms: 90000 }, 300000), { ms: 300000, source: 'idle-budget' }); + assert.deepEqual(resolveInterChunkCeiling({ idle_timeout_ms: 30000 }, 300000), { ms: 300000, source: 'idle-budget' }); }); - it('keeps the 30s default when nothing is configured', () => { - // Fast-fail on genuinely hung slots must survive this fix — deriving from the - // built-in 90s idle FALLBACK would silently disable the stall timer fleet-wide. - assert.deepEqual(resolveStallTimeout({ name: 'codex-1' }, 90000), { ms: 30000, source: 'default' }); - assert.deepEqual(resolveStallTimeout({ name: 'codex-1' }), { ms: 30000, source: 'default' }); - }); - - it('a caller-supplied idle budget cannot INFLATE the window past the slot config', () => { - // The run in #385 dispatched with --timeout 300000 (idle=300000ms in the log). - // Deriving from that would make a genuinely dead slot cost 5 minutes per retry; - // the slot's own 90s declaration is the claim about how slow it is. - assert.deepEqual(resolveStallTimeout({ idle_timeout_ms: 90000 }, 300000), { ms: 90000, source: 'idle' }); - // …and a slot that declared nothing gets no window from --timeout at all. - assert.deepEqual(resolveStallTimeout({}, 300000), { ms: 30000, source: 'default' }); - }); - - it('a caller that LOWERS the idle budget caps the derived window', () => { - // latency_budget_ms / --timeout below the configured idle: the caller's budget wins. - assert.deepEqual(resolveStallTimeout({ idle_timeout_ms: 90000 }, 45000), { ms: 45000, source: 'idle' }); - // Clamped all the way down to the floor → indistinguishable from the default. - assert.deepEqual(resolveStallTimeout({ idle_timeout_ms: 90000 }, 10000), { ms: 30000, source: 'default' }); - }); - - it('an explicit stall_timeout_ms still wins over the idle timeout', () => { - const p = { stall_timeout_ms: 45000, idle_timeout_ms: 300000 }; - assert.deepEqual(resolveStallTimeout(p, 300000), { ms: 45000, source: 'per-slot' }); - }); - - it('does not LOWER the stall window below 30s for a short idle timeout', () => { - // codex-1 configures idle=30000; a slot with idle=5000 must not get a 5s stall - // timer — the derivation only ever raises the window. - assert.deepEqual(resolveStallTimeout({ idle_timeout_ms: 30000 }, 30000), { ms: 30000, source: 'default' }); - assert.deepEqual(resolveStallTimeout({ idle_timeout_ms: 5000 }, 5000), { ms: 30000, source: 'default' }); + it('honors an explicit per-slot ceiling above the caller budget (kimi ~610s)', () => { + assert.deepEqual( + resolveInterChunkCeiling({ inter_chunk_ceiling_ms: 660000 }, 300000), + { ms: 660000, source: 'per-slot' }, + ); }); - it('ignores a garbage idle timeout instead of deriving a nonsense window', () => { - assert.equal(resolveStallTimeout({ idle_timeout_ms: 'soon' }).ms, 30000); - assert.equal(resolveStallTimeout({ idle_timeout_ms: true }).ms, 30000); - assert.equal(resolveStallTimeout({ idle_timeout_ms: -1 }).ms, 30000); - assert.equal(resolveStallTimeout({ idle_timeout_ms: 0 }).ms, 30000); + it('treats a legacy stall_timeout_ms as the ceiling, not as TTFB', () => { + // Values already in that field were measured against post-preamble silence, which + // is exactly what the ceiling governs — so the migration is semantics-preserving. + assert.deepEqual(resolveInterChunkCeiling({ stall_timeout_ms: 270000 }, 300000), { ms: 270000, source: 'legacy-stall' }); + // The new field wins when both are present. + assert.equal(resolveInterChunkCeiling({ inter_chunk_ceiling_ms: 400000, stall_timeout_ms: 270000 }, 300000).ms, 400000); }); - it('clamps an oversized derived window to TIMEOUT_MAX (Node fires >2^31-1ms timers immediately)', () => { - assert.equal(resolveStallTimeout({ idle_timeout_ms: 3e9 }).ms, 2147483647); + it('falls back to 90s only when the caller supplies no budget at all', () => { + assert.deepEqual(resolveInterChunkCeiling({}), { ms: 90000, source: 'default' }); + assert.deepEqual(resolveInterChunkCeiling({}, 0), { ms: 90000, source: 'default' }); }); - it('reports a source label for every branch (so the dispatch log is diagnosable)', () => { - // Suggestion 3 in #385: the run output must say WHERE the window came from, - // instead of requiring a source read to tell 30s-default from 30s-configured. - assert.equal(resolveStallTimeout({ stall_timeout_ms: 90000 }).source, 'per-slot'); - assert.equal(resolveStallTimeout({ idle_timeout_ms: 90000 }).source, 'idle'); - assert.equal(resolveStallTimeout({}).source, 'default'); + it('reports a source for every branch, so the dispatch log is diagnosable', () => { + assert.equal(resolveInterChunkCeiling({ inter_chunk_ceiling_ms: 1 }, 5).source, 'per-slot'); + assert.equal(resolveInterChunkCeiling({ stall_timeout_ms: 1 }, 5).source, 'legacy-stall'); + assert.equal(resolveInterChunkCeiling({}, 5).source, 'idle-budget'); + assert.equal(resolveInterChunkCeiling({}).source, 'default'); }); }); // ─── LIVE PATH ──────────────────────────────────────────────────────────────── -// A resolver that returns the right number is worth nothing if the number never -// reaches the timer, or reaches the timer but not the slot that needed it. These -// two tests exercise the real dispatch: a spawned CLI that emits a sub-500-byte -// preamble and then goes quiet — exactly the shape that false-killed the three -// third-party slots — and the real `node call-quorum-slot.cjs --slot …` child. - -// A stand-in CLI: prints a short preamble (well under the 500-byte stall -// threshold), pauses, then answers. NF_FAKE_PAUSE_MS controls the silence. -const FAKE_CLI = ` +// A resolver returning the right number is worth nothing if the number never reaches +// the timer. These spawn real CLIs shaped like the two failure modes. + +// Emits a short preamble immediately, then thinks in silence, then answers — the exact +// shape of claude-1 / copilot-1 / claude-z-ai, which the old model killed mid-answer. +const FAKE_BURSTY = ` 'use strict'; process.stdout.write('thinking...\\n'); setTimeout(() => { @@ -144,6 +102,12 @@ setTimeout(() => { }, Number(process.env.NF_FAKE_PAUSE_MS || 900)); `; +// Emits NOTHING at all — the only shape that is genuinely indistinguishable from hung. +const FAKE_SILENT = ` +'use strict'; +setTimeout(() => { process.stdout.write('too late\\n'); process.exit(0); }, 5000); +`; + // Cleanup on process exit rather than TestContext.after: `t.after` landed in Node // 18.8, and package.json declares engines.node ">=18.0.0". const TMP_DIRS = []; @@ -151,61 +115,62 @@ process.on('exit', () => { for (const d of TMP_DIRS) { try { fs.rmSync(d, { recursive: true, force: true }); } catch (_) {} } }); -function makeFakeSlotDir() { +function makeFakeSlotDir(body = FAKE_BURSTY) { const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'nf-stall-')); TMP_DIRS.push(dir); // findProjectRoot() walks up to the nearest .planning/ — without one here it would // find the real repo and write this test's telemetry into it. fs.mkdirSync(path.join(dir, '.planning'), { recursive: true }); const cli = path.join(dir, 'fake-cli.cjs'); - fs.writeFileSync(cli, FAKE_CLI, 'utf8'); + fs.writeFileSync(cli, body, 'utf8'); return { dir, cli }; } -describe('LIVE PATH: the resolved stall window drives the real timer (#385)', () => { - it('kills a quiet sub-500-byte slot at the window it was given, not the 30s constant', async () => { +function fakeProvider(cli) { + return { name: 'fake-slot', type: 'subprocess', mainTool: 'node', cli: 'node', args_template: [cli, '{prompt}'] }; +} + +describe('LIVE PATH: two windows, two failure modes', () => { + it('THE REGRESSION: a preamble then a long silence SURVIVES a short TTFB window', async () => { + // This is the whole point. Old model: 200 bytes < 500 → the tight window governs → + // killed at 400ms. New model: the first byte disarms TTFB and the inter-chunk + // ceiling (3s) governs the 900ms think. Three real voters died on exactly this. + // Margins are generous on purpose: a 400ms TTFB window made this test fail when node + // process startup itself crossed it under parallel load — that measures the machine, + // not the semantics. 1.5s TTFB vs a 4s silence cannot be crossed by startup jitter, + // and a still-armed TTFB would kill at 1.5s, well short of the 4s answer. const { cli } = makeFakeSlotDir(); - const provider = { - name: 'fake-slow', type: 'subprocess', mainTool: 'node', cli: 'node', - args_template: [cli, '{prompt}'], - }; - // 400ms window vs a 900ms pause: the 30s default would have let this finish, so a - // STALL here proves the passed window — not the constant — armed the timer. + const provider = { ...fakeProvider(cli), env: { NF_FAKE_PAUSE_MS: '4000' } }; + const out = await runSubprocess(provider, 'q', 20000, 30000, null, {}, { ttfb: 1500, interChunk: 12000 }); + assert.match(out, /verdict: APPROVE/, 'a streaming slot must not be killed by the TTFB window'); + }); + + it('a slot that produces NOTHING is still killed fast, at the TTFB window', async () => { + // Fast-fail must survive the change, or a dead slot burns the full budget × retries. + const { cli } = makeFakeSlotDir(FAKE_SILENT); await assert.rejects( - () => runSubprocess(provider, 'q', 10000, 15000, null, {}, 400), - /STALL: only \d+ bytes received then silence for 400ms/, + () => runSubprocess(fakeProvider(cli), 'q', 30000, 40000, null, {}, { ttfb: 500, interChunk: 30000 }), + /STALL: no output at all for 500ms/, ); }); - it('lets that same slot finish when the window covers its pause', async () => { + it('a mid-stream gap beyond the ceiling is an IDLE kill, reporting bytes seen', async () => { const { cli } = makeFakeSlotDir(); - const provider = { - name: 'fake-slow', type: 'subprocess', mainTool: 'node', cli: 'node', - args_template: [cli, '{prompt}'], - }; - const out = await runSubprocess(provider, 'q', 10000, 15000, null, {}, 3000); - assert.match(out, /verdict: APPROVE/); + await assert.rejects( + () => runSubprocess(fakeProvider(cli), 'q', 10000, 15000, null, {}, { ttfb: 5000, interChunk: 300 }), + /IDLE_TIMEOUT after 300ms of inactivity \(\d+ bytes received before the gap\)/, + ); }); - it('falls back to the provider-derived window when handed a garbage one', async () => { + it('falls back to provider resolution when handed garbage timers', async () => { + // Number(true) === 1 would arm a 1ms timer and kill everything instantly. const { cli } = makeFakeSlotDir(); - // Number(true) === 1 → a 1ms stall timer would false-kill this slot instantly. - const provider = { - name: 'fake-slow', type: 'subprocess', mainTool: 'node', cli: 'node', - args_template: [cli, '{prompt}'], - }; - const out = await runSubprocess(provider, 'q', 10000, 15000, null, {}, true); + const out = await runSubprocess(fakeProvider(cli), 'q', 10000, 15000, null, {}, + { ttfb: true, interChunk: 'nope' }); assert.match(out, /verdict: APPROVE/); }); - }); -// The direct-caller fallback inside runSubprocess (`stallTimeoutFor(provider, -// idleTimeoutMs)`) applies the same rule main() does — a caller idle budget caps the -// window, floored at 30s. Its semantics are pinned at the resolver above rather than -// behaviorally: every value that branch can produce is ≥ 30s, so telling them apart -// through a live subprocess would need a >30s pause per case. - describe('LIVE PATH: the child derives and reports the stall window (#385)', () => { // Runs the real child end-to-end against a temp providers.json, so the derivation // in main() — not just the helper — is under test, along with the log line that @@ -228,20 +193,25 @@ describe('LIVE PATH: the child derives and reports the stall window (#385)', () return res.stderr || ''; } - it('derives the window from a preset that sets idle_timeout_ms but no stall_timeout_ms', () => { + it('reports both windows and their sources', () => { // The exact shipped shape of claude-z-ai / claude-minimax / claude-kimi. const stderr = dispatch({ idle_timeout_ms: 90000 }); - assert.match(stderr, /stall=90000ms \(idle\)/); + assert.match(stderr, /ttfb=30000ms \(default\)/, 'TTFB must not inherit idle_timeout_ms'); + assert.match(stderr, /inter-chunk=90000ms \(idle-budget\)/); }); - it('keeps the 30s default — labelled as such — for a slot that configures nothing', () => { + it('keeps the 30s TTFB default — labelled as such — for a slot that configures nothing', () => { const stderr = dispatch({}); - assert.match(stderr, /stall=30000ms \(default\)/); + assert.match(stderr, /ttfb=30000ms \(default\)/); }); - it('reproduces the #385 dispatch (--timeout 300000) without inflating the window to 5min', () => { + it('THE FIX: the #385 dispatch shape now gets the caller budget, not the 90s derivation', () => { + // Same dispatch that killed claude-1/copilot-1/claude-z-ai mid-answer. The caller + // budgeted 300s; the old model handed them 90s (or 30s) and killed them. const stderr = dispatch({ idle_timeout_ms: 90000 }, ['--timeout', '300000']); - assert.match(stderr, /idle=300000ms hard=300000ms stall=90000ms \(idle\)/); + assert.match(stderr, /ttfb=30000ms \(default\)/); + assert.match(stderr, /inter-chunk=300000ms \(idle-budget\)/); + assert.doesNotMatch(stderr, /inter-chunk=90000ms/, 'the killed-voter derivation must be gone'); }); it('does not warn about the parent dispatcher\'s own flags when the PARENT requires it', () => { @@ -314,3 +284,58 @@ describe('ADVERSARIAL: parseVerdictLine edge cases', () => { assert.equal(parseVerdictLine('reasoning here\r\nverdict: APPROVE\r\nnext line'), 'APPROVE'); }); }); + +// ─── Review round: stream discipline and budget caps ───────────────────────── + +// Emits a few stderr banner lines, then goes silent and never answers on stdout. +const FAKE_STDERR_ONLY = ` +'use strict'; +let n = 0; +const t = setInterval(() => { process.stderr.write('progress...\\n'); if (++n >= 3) clearInterval(t); }, 100); +setTimeout(() => process.exit(0), 20000); +`; + +describe('stream discipline: stderr proves liveness, not answer progress', () => { + it('stderr banners do NOT promote a slot to the wide inter-chunk window', async () => { + // The original rearm() treated stderr like stdout, so banner lines moved the slot to + // the ceiling and a CLI that never answered lived until the hard timeout. stderr may + // rearm the TTFB window — it does prove the process is alive — but it must not buy + // the wide window. Here: 3 banner lines, then silence, ttfb=1200 vs ceiling=30000. + // Death at ~TTFB proves stderr never promoted it; survival to 20s would prove it had. + const { cli } = makeFakeSlotDir(FAKE_STDERR_ONLY); + const started = Date.now(); + await assert.rejects( + () => runSubprocess(fakeProvider(cli), 'q', 30000, 40000, null, {}, { ttfb: 1200, interChunk: 30000 }), + /STALL: no output at all for 1200ms/, + ); + assert.ok(Date.now() - started < 10000, 'must die on the TTFB window, not the 30s ceiling'); + }); + + it('stdout still promotes the slot to the inter-chunk ceiling', async () => { + const { cli } = makeFakeSlotDir(); + const provider = { ...fakeProvider(cli), env: { NF_FAKE_PAUSE_MS: '4000' } }; + const out = await runSubprocess(provider, 'q', 20000, 30000, null, {}, { ttfb: 1500, interChunk: 12000 }); + assert.match(out, /verdict: APPROVE/); + }); +}); + +describe('the per-slot ceiling cannot bypass the operator budget', () => { + it('caps the inter-chunk ceiling at the hard/latency budget and says so', () => { + const { dir, cli } = makeFakeSlotDir(); + const providersPath = path.join(dir, 'providers.json'); + fs.writeFileSync(providersPath, JSON.stringify({ providers: [{ + name: 'fake-slot', type: 'subprocess', mainTool: 'node', cli: 'node', + args_template: [cli, '{prompt}'], + inter_chunk_ceiling_ms: 660000, // slot wants 11 minutes + latency_budget_ms: 5000, // operator says no + }] }), 'utf8'); + const res = spawnSync(process.execPath, [ + path.join(__dirname, 'call-quorum-slot.cjs'), '--slot', 'fake-slot', '--cwd', dir, + ], { cwd: dir, input: 'q\n', encoding: 'utf8', timeout: 30000, + env: { ...process.env, UNIFIED_PROVIDERS_CONFIG: providersPath, NF_FAKE_PAUSE_MS: '100' } }); + const err = res.stderr || ''; + assert.match(err, /inter-chunk ceiling 660000ms capped to 5000ms/, + 'a slot must not out-declare the operator budget'); + assert.doesNotMatch(err, /inter-chunk=660000ms/); + }); +}); diff --git a/bin/call-quorum-slot.cjs b/bin/call-quorum-slot.cjs index 4cba1c7be5..e26e625e1f 100644 --- a/bin/call-quorum-slot.cjs +++ b/bin/call-quorum-slot.cjs @@ -530,28 +530,43 @@ function buildSpawnArgs(provider, prompt, allowedToolsFlag, opts) { } // ─── Subprocess dispatch ─────────────────────────────────────────────────────── -// STALL-TIMEOUT-01: the "header-only stall" timer (used while a slot has produced -// < 500 bytes) defaults to 30s — fine for fast slots, but slow-bursty models routed -// via a third-party Anthropic-compatible API (GLM-5.2[1m], MiniMax-M3) emit a short -// preamble then pause well past 30s while generating. They are slow, not hung. A -// per-slot `stall_timeout_ms` in providers.json raises the threshold so they are not -// false-killed. Any value ≤ 0 / NaN / absent falls back to the 30s default. -// Node's setTimeout clamps delays above 2^31-1 ms and fires them IMMEDIATELY, so a -// nonsensically large stall_timeout_ms would silently disable the stall timer. Cap -// at TIMEOUT_MAX to keep the timer well-formed. +// STALL-TIMEOUT-03 — the timer model, after a live multi-model quorum ruled on it. // -// STALL-TIMEOUT-02 (issue #385): requiring `stall_timeout_ms` to be set explicitly -// made the escape hatch useless in practice — the slots that need it (claude-z-ai, -// claude-minimax, claude-kimi and any other third-party Anthropic-compatible route) -// are created by preset import / manual add, which sets `idle_timeout_ms` but never -// `stall_timeout_ms`. They declared a 90s idle tolerance and were still killed at 30s -// in their first 500 bytes, every round. So a slot's CONFIGURED `idle_timeout_ms`, -// when larger than the default stall window, now derives the stall window too: a slot -// that says "I may go quiet for 90s" does not want a 30s kill on its preamble. The -// 30s default still applies to every slot that configured nothing, so fast-fail on a -// genuinely hung slot is unchanged fleet-wide. +// History. STALL-TIMEOUT-01 used "totalBytesReceived < 500 → apply a tighter window" +// as a proxy for "this slot is hung". STALL-TIMEOUT-02 (#385) kept that proxy and only +// made the window configurable/derivable. A quorum run on 2026-08-07 falsified the +// proxy empirically — and did it by killing three of its own five voters mid-answer: +// +// claude-1 idle_timeout_ms=90000 → 90s window → KILLED at 90s, answer in flight +// copilot-1 idle_timeout_ms=30000 → 30s window → KILLED at 30s, answer in flight +// claude-z-ai idle_timeout_ms=90000 → 90s window → KILLED at 90s +// codex-1 / antigravity-1 → survived +// +// The discriminator was never byte count: it is whether a slot STREAMS. The survivors +// emit continuously so every chunk rearms the timer; the killed slots emit a ~200-byte +// preamble in <1s and then think in silence. Worse, deriving the window from +// `idle_timeout_ms` made that field do double duty as "how long may this model think +// before substantive output" — and for most slots the configured value (30s/90s) is far +// SMALLER than real think time, while the caller had budgeted 300s. +// +// The model now matches the two failure modes directly: +// • BEFORE the first byte → `ttfb_timeout_ms` (default 30s). Zero output is the only +// honest evidence of a hang, so this is where fast-fail belongs. +// • AFTER the first byte → the inter-chunk ceiling: `inter_chunk_ceiling_ms` if the +// slot declares one, else the caller's idle budget. A slot that is mid-generation is +// alive; only the caller's budget (or an explicit per-slot ceiling for a known +// slow-bursty route like kimi at ~610s) should bound it. +// +// `stall_timeout_ms` is kept as a LEGACY ALIAS for the inter-chunk ceiling, because the +// values already in the field were measured against post-preamble silence — which is +// exactly what the ceiling governs. So no config surface is added: the second knob is +// the old knob, renamed to say what it actually does. +// +// Node's setTimeout clamps delays above 2^31-1 ms and fires them IMMEDIATELY, so an +// oversized value would silently DISABLE a timer. Cap at TIMEOUT_MAX. const TIMEOUT_MAX = 2147483647; // 2^31 - 1 -const STALL_TIMEOUT_DEFAULT_MS = 30000; +const TTFB_TIMEOUT_DEFAULT_MS = 30000; +const INTER_CHUNK_DEFAULT_MS = 90000; // only when the caller supplies no budget // Coerce a duration config value to a positive number of ms, or null. // Only real numbers / numeric strings count. Without this, Number(true) === 1 would @@ -564,40 +579,36 @@ function toPositiveMs(raw) { } /** - * Resolve the header-only stall window and where it came from (the `source` is what - * the dispatch log prints, so this is diagnosable from run output instead of by - * reading this file — issue #385, suggestion 3). - * - * The derivation reads the slot's CONFIGURED `idle_timeout_ms` — a property of the - * provider ("this route is slow-bursty") — never the 90s built-in fallback (that - * would disable the stall timer for every unconfigured slot) and never a caller's - * `--timeout` alone (the orchestrator passes 300000 for its own reasons; inflating - * the stall window to 5 minutes would make a dead slot cost 5 minutes per retry). - * A caller that LOWERS the idle budget below the configured value still wins — its - * budget caps the derived window. - * - * @param {object} provider providers.json entry - * @param {number|string} [effectiveIdleMs] the idle timeout actually in force for - * this dispatch, used only as a ceiling. Omit when there is no caller budget. - * @returns {{ms: number, source: 'per-slot'|'idle'|'default'}} + * Time-to-first-byte window: how long a slot may produce NOTHING before it is treated + * as hung. Deliberately NOT derived from idle_timeout_ms — that derivation is the + * STALL-TIMEOUT-02 bug. A slot that needs to think a long time before its first token + * sets `ttfb_timeout_ms` explicitly. + * @returns {{ms: number, source: 'per-slot'|'default'}} */ -function resolveStallTimeout(provider, effectiveIdleMs) { - const explicit = toPositiveMs(provider && provider.stall_timeout_ms); +function resolveTtfbTimeout(provider) { + const explicit = toPositiveMs(provider && provider.ttfb_timeout_ms); if (explicit !== null) return { ms: explicit, source: 'per-slot' }; - const configuredIdle = toPositiveMs(provider && provider.idle_timeout_ms); - if (configuredIdle !== null) { - const ceiling = toPositiveMs(effectiveIdleMs); - const bounded = ceiling === null ? configuredIdle : Math.min(configuredIdle, ceiling); - if (bounded > STALL_TIMEOUT_DEFAULT_MS) return { ms: bounded, source: 'idle' }; - } - return { ms: STALL_TIMEOUT_DEFAULT_MS, source: 'default' }; + return { ms: TTFB_TIMEOUT_DEFAULT_MS, source: 'default' }; } -function stallTimeoutFor(provider, effectiveIdleMs) { - return resolveStallTimeout(provider, effectiveIdleMs).ms; +/** + * Inter-chunk ceiling: once ANY byte has arrived the slot is alive, so inactivity is + * bounded by the caller's idle budget unless the slot declares a longer ceiling. + * @param {object} provider + * @param {number|string} [effectiveIdleMs] the caller's idle budget for this dispatch + * @returns {{ms: number, source: 'per-slot'|'legacy-stall'|'idle-budget'|'default'}} + */ +function resolveInterChunkCeiling(provider, effectiveIdleMs) { + const explicit = toPositiveMs(provider && provider.inter_chunk_ceiling_ms); + if (explicit !== null) return { ms: explicit, source: 'per-slot' }; + const legacy = toPositiveMs(provider && provider.stall_timeout_ms); + if (legacy !== null) return { ms: legacy, source: 'legacy-stall' }; + const caller = toPositiveMs(effectiveIdleMs); + if (caller !== null) return { ms: caller, source: 'idle-budget' }; + return { ms: INTER_CHUNK_DEFAULT_MS, source: 'default' }; } -function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, stallTimeoutMs) { +function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, timers) { const { args, useStdinPrompt, isCcr, promptMutated } = buildSpawnArgs(provider, prompt, allowedToolsFlag, resumeOpts); if (promptMutated) { // CCR-MUTATE-01: warn that the prompt was neutralized for CCR's shell re-spawn. @@ -690,23 +701,43 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo let rateLimitHits = 0; const RATE_LIMIT_THRESHOLD = 2; // kill after 2 consecutive rate-limit messages let totalBytesReceived = 0; - // Tighter idle timeout when the CLI has produced < STALL_BYTE_THRESHOLD bytes - // (header-only → probably hung). Per-slot override via providers.json - // `stall_timeout_ms`, else derived from an explicitly configured idle timeout - // (see resolveStallTimeout): slow models (e.g. GLM-5.2[1m], MiniMax-M3) - // legitimately emit a small preamble then pause >30s mid-generation — they are - // slow, not stalled — so they need a longer threshold to avoid being false-killed. - // The caller resolves this once per dispatch and passes it in; the fallback keeps - // direct callers (tests, ad-hoc invocations) on the same rules. - const STALL_TIMEOUT_MS = toPositiveMs(stallTimeoutMs) ?? stallTimeoutFor(provider, idleTimeoutMs); - const STALL_BYTE_THRESHOLD = 500; // below this = "just a header, probably stalled" + // STALL-TIMEOUT-03: two windows, one per failure mode. `timers` is resolved once + // per dispatch by the caller; the fallback keeps direct callers on the same rules. + // The initial idleTimer above is REARMED to the TTFB window immediately below — + // until a byte arrives, zero output is the only honest evidence of a hang. + const TTFB_MS = toPositiveMs(timers && timers.ttfb) ?? resolveTtfbTimeout(provider).ms; + const INTER_CHUNK_MS = toPositiveMs(timers && timers.interChunk) + ?? resolveInterChunkCeiling(provider, idleTimeoutMs).ms; + let firstByteSeen = false; + + clearTimeout(idleTimer); + idleTimer = setTimeout(() => { + timedOut = true; timeoutType = 'STALL'; killGroup(); + }, TTFB_MS); + + // Byte COUNT is deliberately not consulted: a slot mid-generation is alive whether it + // has emitted 200 bytes or 200KB. But WHICH stream matters. Only stdout is answer + // progress; several CLIs here (gemini among them) write banners and progress lines to + // stderr, and letting those promote the slot to the wide inter-chunk window would let + // a CLI that never answers escape the fast TTFB fail entirely. So stderr rearms TTFB + // — it proves the process is alive, not that an answer is coming — and only stdout + // switches to the ceiling. Once stdout has been seen, stderr rearms the ceiling too, + // since by then the slot is demonstrably answering. + const rearmStdout = () => { + firstByteSeen = true; + clearTimeout(idleTimer); + idleTimer = setTimeout(() => { timedOut = true; timeoutType = 'IDLE'; killGroup(); }, INTER_CHUNK_MS); + }; + const rearmStderr = () => { + clearTimeout(idleTimer); + idleTimer = firstByteSeen + ? setTimeout(() => { timedOut = true; timeoutType = 'IDLE'; killGroup(); }, INTER_CHUNK_MS) + : setTimeout(() => { timedOut = true; timeoutType = 'STALL'; killGroup(); }, TTFB_MS); + }; child.stdout.on('data', d => { totalBytesReceived += d.length; - clearTimeout(idleTimer); - // Adaptive idle: use tighter 30s timeout when CLI has barely produced output (header-only stall) - const effectiveIdle = totalBytesReceived < STALL_BYTE_THRESHOLD ? STALL_TIMEOUT_MS : idleTimeoutMs; - idleTimer = setTimeout(() => { timedOut = true; timeoutType = totalBytesReceived < STALL_BYTE_THRESHOLD ? 'STALL' : 'IDLE'; killGroup(); }, effectiveIdle); + rearmStdout(); const chunk = d.toString(); l1OriginalSize += chunk.length; if (stdout.length < MAX_BUF) { @@ -732,9 +763,7 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo }); child.stderr.on('data', d => { totalBytesReceived += d.length; - clearTimeout(idleTimer); - const effectiveIdle = totalBytesReceived < STALL_BYTE_THRESHOLD ? STALL_TIMEOUT_MS : idleTimeoutMs; - idleTimer = setTimeout(() => { timedOut = true; timeoutType = totalBytesReceived < STALL_BYTE_THRESHOLD ? 'STALL' : 'IDLE'; killGroup(); }, effectiveIdle); + rearmStderr(); const chunk = d.toString().slice(0, 4096); stderr += chunk; // Check stderr for rate-limit patterns too (gemini logs to stderr) @@ -778,10 +807,10 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo : timeoutType === 'QUOTA' ? `QUOTA: provider returned quota/billing error (${totalBytesReceived} bytes partial response)` : timeoutType === 'STALL' - ? `STALL: only ${totalBytesReceived} bytes received then silence for ${STALL_TIMEOUT_MS}ms — no recognizable error pattern in partial output` + ? `STALL: no output at all for ${TTFB_MS}ms (time-to-first-byte window) — slot produced nothing` : timeoutType === 'HARD' ? `HARD_TIMEOUT after ${hardTimeoutMs}ms total` - : `IDLE_TIMEOUT after ${idleTimeoutMs}ms of inactivity`; + : `IDLE_TIMEOUT after ${INTER_CHUNK_MS}ms of inactivity (${totalBytesReceived} bytes received before the gap)`; reject(new Error(label)); return; } @@ -819,7 +848,7 @@ function spawnRotateCmd(cmdArray) { }); } -async function runSubprocessWithRotation(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, stallTimeoutMs) { +async function runSubprocessWithRotation(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, timers) { const rot = provider.oauth_rotation; const max = rot.max_retries ?? 3; const patterns = rot.retry_on_patterns ?? ['quota', 'resource_exhausted', 'unauthorized', '401', '403']; @@ -833,7 +862,7 @@ async function runSubprocessWithRotation(provider, prompt, idleTimeoutMs, hardTi } try { // Wrap inner call with retry-with-backoff (each oauth attempt gets retry protection) - const retryResult = await retryWithBackoff(() => runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, stallTimeoutMs), provider.name); + const retryResult = await retryWithBackoff(() => runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedToolsFlag, resumeOpts, timers), provider.name); const out = retryResult.result; totalRetryCount = attempt + retryResult.retryCount; if (matchesRotationPattern(out, patterns) && attempt < max) { @@ -1086,9 +1115,19 @@ async function main() { // STALL-TIMEOUT-02 (#385): the header-only stall window, derived from this slot's // configured idle tolerance and capped by the idle budget actually in force. - const stall = resolveStallTimeout(provider, effectiveIdleTimeout); + const ttfb = resolveTtfbTimeout(provider); + const chunk = resolveInterChunkCeiling(provider, effectiveIdleTimeout); + // A per-slot ceiling may exceed the CALLER's idle budget (that is its purpose) but must + // never exceed the OPERATOR's caps — effectiveHardTimeout already folds in + // quorum_timeout_ms and latency_budget_ms. Raising the hard timer to meet the ceiling + // instead would silently undo a `latency_budget_ms: 120000` an operator had set. + const boundedChunk = Math.min(chunk.ms, effectiveHardTimeout); + if (boundedChunk !== chunk.ms) { + process.stderr.write(`[call-quorum-slot] inter-chunk ceiling ${chunk.ms}ms capped to ${boundedChunk}ms by the hard/latency budget for slot ${slot}\n`); + } + const timers = { ttfb: Math.min(ttfb.ms, effectiveHardTimeout), interChunk: boundedChunk }; - process.stderr.write(`[call-quorum-slot] Timeouts: idle=${effectiveIdleTimeout}ms hard=${effectiveHardTimeout}ms stall=${stall.ms}ms (${stall.source}) for slot ${slot}\n`); + process.stderr.write(`[call-quorum-slot] Timeouts: idle=${effectiveIdleTimeout}ms hard=${effectiveHardTimeout}ms ttfb=${ttfb.ms}ms (${ttfb.source}) inter-chunk=${boundedChunk}ms (${chunk.source}) for slot ${slot}\n`); const startMs = Date.now(); @@ -1101,11 +1140,11 @@ async function main() { // thread-persistence semantics are identical for the rotation and non-rotation paths. const resumeOpts = { persistentThreads, repoDir, slotName: slot, invocationId }; if (provider.oauth_rotation?.enabled) { - const retryResult = await runSubprocessWithRotation(provider, prompt, effectiveIdleTimeout, effectiveHardTimeout, allowedTools, resumeOpts, stall.ms); + const retryResult = await runSubprocessWithRotation(provider, prompt, effectiveIdleTimeout, effectiveHardTimeout, allowedTools, resumeOpts, timers); result = retryResult.result; retryCount = retryResult.retryCount; } else { - const retryResult = await retryWithBackoff(() => runSubprocess(provider, prompt, effectiveIdleTimeout, effectiveHardTimeout, allowedTools, resumeOpts, stall.ms), slot); + const retryResult = await retryWithBackoff(() => runSubprocess(provider, prompt, effectiveIdleTimeout, effectiveHardTimeout, allowedTools, resumeOpts, timers), slot); result = retryResult.result; retryCount = retryResult.retryCount; } @@ -1227,4 +1266,4 @@ if (require.main === module) { } // ─── Test exports (SHELL-ESCAPE-01, TRUNC-01, INFRA-367) ─────────────────────── -module.exports = { buildSpawnArgs, stallTimeoutFor, resolveStallTimeout, runSubprocess, recordTelemetry, findProjectRoot, writeFailureLog, atomicUpdateJson, VERDICTS, VERDICT_LINE_RE, parseVerdictLine }; +module.exports = { buildSpawnArgs, resolveTtfbTimeout, resolveInterChunkCeiling, runSubprocess, recordTelemetry, findProjectRoot, writeFailureLog, atomicUpdateJson, VERDICTS, VERDICT_LINE_RE, parseVerdictLine };