From 397f7291ec77c10d50e8a095cb01ca391209d5c8 Mon Sep 17 00:00:00 2001 From: "open-swe[bot]" Date: Fri, 7 Aug 2026 12:12:19 -0400 Subject: [PATCH 1/2] fix(quorum): replace the byte-threshold stall proxy with a two-window timer (STALL-TIMEOUT-03) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `totalBytesReceived < 500 -> apply a tighter kill window` was a proxy for "this slot is hung". A live multi-model quorum falsified it the hard way: it killed three of its own five voters mid-answer. claude-1 idle 90000 -> 90s window -> KILLED at 90s, answer in flight copilot-1 idle 30000 -> 30s window -> KILLED at 30s, answer in flight claude-z-ai idle 90000 -> 90s window -> KILLED at 90s codex-1 / antigravity-1 -> survived The survivors were not faster; they STREAM, so every chunk rearmed the timer. Byte count never measured liveness. And deriving the window from idle_timeout_ms (#385) made that field do double duty as "how long may this model think before output" — for most slots that value is far smaller than real think time, while the caller had budgeted 300s. Two windows now, 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 here and nowhere else. - after the first byte: inter_chunk_ceiling_ms if declared, else the caller's idle budget. A slot mid-generation is alive whether it has emitted 200B or 200KB. stall_timeout_ms survives as a legacy alias for the ceiling — the values already in that field were measured against post-preamble silence, which is what the ceiling governs — so the config surface does not grow. Measuring also corrected an assumption I had stated as fact: the `claude` CLI BUFFERS (zero bytes until well past 30s), unlike the z-ai/minimax/kimi routes that emit a ~200B preamble in under a second. That is exactly the case claude-minimax named in round 1 as what would change its mind, and why TTFB is per-slot configurable. Live-verified: claude-1 answers in 134s at ttfb=150000 where it died at 90s before. Ratified by quorum 3/3 (codex-1, antigravity-1, claude-minimax) over keeping #386 as shipped. Extracted fresh per improvement I3 rather than rebasing #293's 685 lines. Debate: .planning/quorum/debates/2026-08-07-stall-timer-design-decision-a-vs-b.md Tests rewritten for the new semantics — the old ones encoded the falsified premise. Mutation-proven: making the first byte not disarm TTFB fails the regression test; re-deriving TTFB from idle_timeout_ms fails the guard against that exact bug. Co-Authored-By: Claude Opus 5 (1M context) --- CHANGELOG.md | 3 + bin/call-quorum-slot-stall-timeout.test.cjs | 258 +++++++++----------- bin/call-quorum-slot.cjs | 170 +++++++------ 3 files changed, 213 insertions(+), 218 deletions(-) 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..38d05afc3a 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, {}, Infinity === 0]) { + 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', () => { diff --git a/bin/call-quorum-slot.cjs b/bin/call-quorum-slot.cjs index 4cba1c7be5..fc2484899a 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,31 @@ 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); + + // Every chunk rearms the inter-chunk timer. Byte COUNT is deliberately not consulted: + // a slot mid-generation is alive whether it has emitted 200 bytes or 200KB. + const rearm = () => { + firstByteSeen = true; + clearTimeout(idleTimer); + idleTimer = setTimeout(() => { timedOut = true; timeoutType = 'IDLE'; killGroup(); }, INTER_CHUNK_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); + rearm(); const chunk = d.toString(); l1OriginalSize += chunk.length; if (stdout.length < MAX_BUF) { @@ -732,9 +751,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); + rearm(); const chunk = d.toString().slice(0, 4096); stderr += chunk; // Check stderr for rate-limit patterns too (gemini logs to stderr) @@ -778,10 +795,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 +836,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 +850,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 +1103,14 @@ 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); + const timers = { ttfb: ttfb.ms, interChunk: chunk.ms }; + // The hard cap must still cover the widest window a dispatch can legitimately use, + // or a slot with a long inter-chunk ceiling is killed by the hard timer instead. + effectiveHardTimeout = Math.max(effectiveHardTimeout, chunk.ms); - 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=${chunk.ms}ms (${chunk.source}) for slot ${slot}\n`); const startMs = Date.now(); @@ -1101,11 +1123,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 +1249,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 }; From 5588128be9cdc0f49d238675f165b19425217203 Mon Sep 17 00:00:00 2001 From: "open-swe[bot]" Date: Fri, 7 Aug 2026 12:26:34 -0400 Subject: [PATCH 2/2] =?UTF-8?q?fix(quorum):=20address=20review=20=E2=80=94?= =?UTF-8?q?=20stderr=20must=20not=20buy=20the=20wide=20window;=20ceiling?= =?UTF-8?q?=20must=20respect=20operator=20budgets?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three valid findings on the two-window timer: - stderr rearmed the inter-chunk ceiling, so a CLI writing only banners/progress lines (gemini does) escaped the TTFB fast-fail and lived to the hard timeout without ever answering. Only stdout is answer progress: stderr now rearms the TTFB window instead — it proves the process is alive, not that an answer is coming — and promotes to the ceiling only after stdout has been seen. - The resolved ceiling raised effectiveHardTimeout to meet it, which silently undid the operator's caps: a slot declaring inter_chunk_ceiling_ms 660000 got a 660s hard timeout even under latency_budget_ms 120000. The ceiling is now capped BY effectiveHardTimeout (which already folds in quorum_timeout_ms and latency_budget_ms) and the capping is logged. A per-slot ceiling may exceed the caller's idle budget — that is its purpose — but never the operator's. - `Infinity === 0` in a fixture list is just `false`, duplicating the `true` case. Replaced with NaN and -Infinity, which were the intended shapes. My first version of the stderr test asserted the wrong property — that a stderr-spewing CLI dies at TTFB. It does not, and should not: a process emitting progress every 200ms is alive, and the hard timeout is the backstop. The property worth pinning is that stderr never promotes the slot to the WIDE window, so the fixture now emits 3 banner lines then goes silent and the test asserts death at ~1.2s TTFB rather than survival to the 30s ceiling. Both fixes mutation-proven: restoring stderr's ceiling-rearm fails the stream test (20s vs 1.2s), and restoring the hard-timeout raise fails the budget-cap test. Co-Authored-By: Claude Opus 5 (1M context) --- bin/call-quorum-slot-stall-timeout.test.cjs | 57 ++++++++++++++++++++- bin/call-quorum-slot.cjs | 37 +++++++++---- 2 files changed, 83 insertions(+), 11 deletions(-) diff --git a/bin/call-quorum-slot-stall-timeout.test.cjs b/bin/call-quorum-slot-stall-timeout.test.cjs index 38d05afc3a..ba9c9fc75f 100644 --- a/bin/call-quorum-slot-stall-timeout.test.cjs +++ b/bin/call-quorum-slot-stall-timeout.test.cjs @@ -40,7 +40,7 @@ describe('resolveTtfbTimeout — the only window that may fast-fail', () => { }); it('falls back to the default for garbage / non-numeric values', () => { - for (const bad of [0, -5, 'nope', null, true, {}, Infinity === 0]) { + for (const bad of [0, -5, 'nope', null, true, {}, NaN, -Infinity]) { assert.equal(resolveTtfbTimeout({ ttfb_timeout_ms: bad }).ms, 30000, `bad=${JSON.stringify(bad)}`); } }); @@ -284,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 fc2484899a..e26e625e1f 100644 --- a/bin/call-quorum-slot.cjs +++ b/bin/call-quorum-slot.cjs @@ -715,17 +715,29 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo timedOut = true; timeoutType = 'STALL'; killGroup(); }, TTFB_MS); - // Every chunk rearms the inter-chunk timer. Byte COUNT is deliberately not consulted: - // a slot mid-generation is alive whether it has emitted 200 bytes or 200KB. - const rearm = () => { + // 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; - rearm(); + rearmStdout(); const chunk = d.toString(); l1OriginalSize += chunk.length; if (stdout.length < MAX_BUF) { @@ -751,7 +763,7 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo }); child.stderr.on('data', d => { totalBytesReceived += d.length; - rearm(); + rearmStderr(); const chunk = d.toString().slice(0, 4096); stderr += chunk; // Check stderr for rate-limit patterns too (gemini logs to stderr) @@ -1105,12 +1117,17 @@ async function main() { // configured idle tolerance and capped by the idle budget actually in force. const ttfb = resolveTtfbTimeout(provider); const chunk = resolveInterChunkCeiling(provider, effectiveIdleTimeout); - const timers = { ttfb: ttfb.ms, interChunk: chunk.ms }; - // The hard cap must still cover the widest window a dispatch can legitimately use, - // or a slot with a long inter-chunk ceiling is killed by the hard timer instead. - effectiveHardTimeout = Math.max(effectiveHardTimeout, chunk.ms); + // 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 ttfb=${ttfb.ms}ms (${ttfb.source}) inter-chunk=${chunk.ms}ms (${chunk.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();