From f8348adb3b8428ba37765366a3823db158908379 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Sun, 24 May 2026 14:22:53 +1000 Subject: [PATCH] =?UTF-8?q?fix(providers):=20D24=20=E2=80=94=20close=20spa?= =?UTF-8?q?wn-timeout=20race=20when=20timer=20fires=20during=20yield-suspe?= =?UTF-8?q?nsion=20(round-2=20F4)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cold-audit catch from 2026-05-24 Round-2 cold-audit Finding 4 (P2 concurrency bug). All 3 provider plugins (anthropic / codex / mistral) had a race in spawn-timeout enforcement: The timer's rejection branch is `if (rejectNext) { rejectNext(SPAWN_TIMEOUT) }`. `rejectNext` is only set while the drain loop is AWAITING an empty-queue promise. If the timer fires while the generator is suspended at a `yield` (rejectNext === null because we're not currently awaiting), the rejection is silently skipped. The loop then drains queued items, sees `close` (from the SIGTERM), breaks normally. Post-loop guards on `!spawnTimedOut` both skip: SPAWN_FAILED throw + yield-stop emit. Generator returns normally with N partial chunks. Consumer (collectAllChunks) sees a "successful" return. Fallback never advances. Truncated response gets cached. This violates BOTH: - ADR 0004 § Trigger taxonomy bullet 4 (hard trigger never fires) - ADR 0005 § Cache write conditions item 1 (truncated response cached) The bug escaped FOUR reviewers: D10 diff-review, round-1 cold-audit, D11 reviewer, D14 reviewer. Round-2 cold-audit caught it because it was unprimed and walked the timer/drain-loop race manually. Fix (3 plugins, parallel race): Each plugin gains an unconditional post-loop check, placed AFTER the existing `try { drain loop } finally { clearTimeout(timer) }` block, but BEFORE the existing `!spawnTimedOut`-gated guards: ```js if (spawnTimedOut) { throw new ProviderError( ` spawn timed out after ${maxSpawnTimeMs}ms`, 'SPAWN_TIMEOUT', ); } ``` This closes the race surface: the inner-loop guard (unchanged, lines ~319/461/583) handles the rejectNext-set path; the new post-loop guard handles the rejectNext-null path. Together they cover both halves — SPAWN_TIMEOUT now reliably surfaces as a hard trigger regardless of which path the timer fire took. Changes (4 files, +154 / -0): - lib/providers/anthropic.mjs: post-loop guard at lines 360-365 (after clearTimeout at line 348-350, before existing SPAWN_FAILED guard at 368) - lib/providers/codex.mjs: post-loop guard at lines 521-526 (parallel) - lib/providers/mistral.mjs: post-loop guard at lines 643-648 (parallel) - test-features.mjs: new Suite 16 test 16e — race reproduction (109 lines) Test 16e race reproduction (deterministic): Exploits Node event-loop ordering. Mock spawn schedules data1 + data2 + close via a single setImmediate. setImmediate runs before timers in the same tick, so all 3 events queue before the timer can fire. Generator yields data1 then suspends at yield with rejectNext null. Consumer pauses 25ms (> 10ms timer). Timer fires during yield-suspension: spawnTimedOut=true, rejectNext null → branch skipped, SIGTERM sent. Consumer resumes, drain processes data2 + close, breaks normally. Post-loop: D24 guard catches spawnTimedOut → throws SPAWN_TIMEOUT. Pre-D24 behavior: generator returns normally (truncated, silently cacheable). Test would FAIL. Post-D24: SPAWN_TIMEOUT throws → test PASSES. Reviewer empirically validated the test's diagnostic power by stripping D24 from anthropic.mjs and observing exactly 16e fail (only 16e — 16a through 16d still pass on the orthogonal rejectNext-set path), then restored. Timing flake risk: very low. Race depends only on relative ordering of two setTimeout callbacks (10ms vs 25ms) which Node guarantees regardless of absolute drift. Reviewer ran 7 npm test passes; 16e timing spread 26.43-27.70ms (1.3ms variance). Tests: 334 → 335 (+1). 335/335 pass on Node 20. Out of scope (filed in issue #3): - SPAWN_TIMEOUT salvage parity: this fix discards partial chunks (matches current SPAWN_TIMEOUT semantics, doesn't introduce asymmetry vs SPAWN_FAILED-no-chunks). Whether to add SPAWN_TIMEOUT-with-usable-chunks salvage (analogous to D16's SPAWN_FAILED salvage) is a separate design decision tracked in issue #3. Authority: - ADR 0004 § Trigger taxonomy — Hard triggers bullet 4: "Provider CLI spawn timeout (configurable per-provider via hints.maxSpawnTimeMs)" https://github.com/dtzp555-max/olp/blob/main/docs/adr/0004-fallback-engine.md - ADR 0005 § Cache write conditions item 1 (no truncation) - engine.mjs HARD_TRIGGER_CODES['SPAWN_TIMEOUT'] = true (D10 P1.3, unchanged) - CC 开发铁律 v1.6 § 10.x — Round-2 Cold Audit caught this Reviewer (Iron Rule v1.6 § 10.x Mode A, fresh-context opus, independent of drafter): APPROVE. Verified guard position in all 3 plugins; read push() to confirm rejectNext-null mechanism; empirically validated test 16e's diagnostic specificity (strip-revert-restore); 7 test runs confirmed timing stability. No blocking issues. Co-Authored-By: Claude Opus 4.7 --- lib/providers/anthropic.mjs | 15 +++++ lib/providers/codex.mjs | 15 +++++ lib/providers/mistral.mjs | 15 +++++ test-features.mjs | 109 ++++++++++++++++++++++++++++++++++++ 4 files changed, 154 insertions(+) diff --git a/lib/providers/anthropic.mjs b/lib/providers/anthropic.mjs index 3919fee..80a088d 100644 --- a/lib/providers/anthropic.mjs +++ b/lib/providers/anthropic.mjs @@ -349,6 +349,21 @@ async function* _spawnAndStream(irRequest, authContext, spawnImpl) { clearTimeout(spawnDeadlineTimer); } + // D24 round-2 F4 fix: if the timer fired while the drain loop was processing + // queued items, rejectNext was null at fire-time so the rejection was skipped. + // The post-loop SPAWN_FAILED + yield-stop guards both check !spawnTimedOut, so + // the generator would otherwise return normally with partial chunks despite the + // timeout. This unconditional throw closes the race — SPAWN_TIMEOUT always + // surfaces as a hard trigger to the fallback engine regardless of which path + // the timer fire took. Note: any partial chunks already yielded are discarded + // by the caller; SPAWN_TIMEOUT salvage parity is tracked in issue #3. + if (spawnTimedOut) { + throw new ProviderError( + `claude spawn timed out after ${maxSpawnTimeMs}ms`, + 'SPAWN_TIMEOUT', + ); + } + // Process close if (exitCode !== 0 && !spawnTimedOut) { const errMsg = accumulatedStderr.slice(0, 300) || `claude exit ${exitCode}`; diff --git a/lib/providers/codex.mjs b/lib/providers/codex.mjs index 895935e..01dbeab 100644 --- a/lib/providers/codex.mjs +++ b/lib/providers/codex.mjs @@ -510,6 +510,21 @@ async function* _spawnAndStream(irRequest, authContext, spawnImpl) { clearTimeout(spawnDeadlineTimer); } + // D24 round-2 F4 fix: if the timer fired while the drain loop was processing + // queued items, rejectNext was null at fire-time so the rejection was skipped. + // The post-loop SPAWN_FAILED + yield-stop guards both check !spawnTimedOut, so + // the generator would otherwise return normally with partial chunks despite the + // timeout. This unconditional throw closes the race — SPAWN_TIMEOUT always + // surfaces as a hard trigger to the fallback engine regardless of which path + // the timer fire took. Note: any partial chunks already yielded are discarded + // by the caller; SPAWN_TIMEOUT salvage parity is tracked in issue #3. + if (spawnTimedOut) { + throw new ProviderError( + `codex spawn timed out after ${maxSpawnTimeMs}ms`, + 'SPAWN_TIMEOUT', + ); + } + // Process close if (exitCode !== 0 && !spawnTimedOut) { const errMsg = accumulatedStderr.slice(0, 300) || `codex exit ${exitCode}`; diff --git a/lib/providers/mistral.mjs b/lib/providers/mistral.mjs index 82aedb8..cc6aa75 100644 --- a/lib/providers/mistral.mjs +++ b/lib/providers/mistral.mjs @@ -632,6 +632,21 @@ async function* _spawnAndStream(irRequest, authContext, spawnImpl) { clearTimeout(spawnDeadlineTimer); } + // D24 round-2 F4 fix: if the timer fired while the drain loop was processing + // queued items, rejectNext was null at fire-time so the rejection was skipped. + // The post-loop SPAWN_FAILED + yield-stop guards both check !spawnTimedOut, so + // the generator would otherwise return normally with partial chunks despite the + // timeout. This unconditional throw closes the race — SPAWN_TIMEOUT always + // surfaces as a hard trigger to the fallback engine regardless of which path + // the timer fire took. Note: any partial chunks already yielded are discarded + // by the caller; SPAWN_TIMEOUT salvage parity is tracked in issue #3. + if (spawnTimedOut) { + throw new ProviderError( + `vibe spawn timed out after ${maxSpawnTimeMs}ms`, + 'SPAWN_TIMEOUT', + ); + } + // Process close if (exitCode !== 0 && !spawnTimedOut) { const errMsg = accumulatedStderr.slice(0, 300) || `vibe exit ${exitCode}`; diff --git a/test-features.mjs b/test-features.mjs index 556fd17..e2b8dc3 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -5678,4 +5678,113 @@ describe('Spawn timeout (Suite 16)', () => { } }); + + it('16e: spawn-timeout fires SPAWN_TIMEOUT even when timer races with queued chunks (D24 race fix)', async () => { + // Exercises the race fixed in D24 (cold-audit round-2 F4). + // + // Race path modelled deterministically: + // 1. Mock stdin.end() schedules data1 + data2 + 'close' via setImmediate + // (deferred so event handlers registered in the plugin body are ready). + // 2. Timer is 10ms. Drain loop awaits empty queue. setImmediate fires: + // push(data1) wakes the drain loop (rejectNext was set, now cleared), + // push(data2) and push(close) queue up. Drain processes data1, yields it. + // Generator suspends at yield with rejectNext===null. + // 3. Consumer (gen.next() resolved) waits 25ms (> 10ms timer). + // Timer fires: spawnTimedOut=true, rejectNext===null → rejectNext branch + // SKIPPED. Race condition reproduced. + // 4. Consumer resumes → drain loop processes data2 then 'close' → breaks. + // Post-loop: spawnTimedOut=true. + // Pre-D24: generator returns normally (truncated, silently cacheable). + // Post-D24: unconditional `if (spawnTimedOut) throw` → SPAWN_TIMEOUT. + // + // The timer starts inside the generator body (not at gen-creation time), + // so it only ticks after the first gen.next() call. + + const savedTimeout = anthropic.hints.maxSpawnTimeMs; + anthropic.hints.maxSpawnTimeMs = 10; // fires during the 25ms consumer pause + + const savedToken = process.env.CLAUDE_CODE_OAUTH_TOKEN; + process.env.CLAUDE_CODE_OAUTH_TOKEN = 'fake-token-16e'; + + __setSpawnImpl(function (_bin, _args, _opts) { + const proc = new EventEmitter(); + proc.stdout = new EventEmitter(); + proc.stderr = new EventEmitter(); + proc.stdin = { + write: () => {}, + end: () => { + // Emit data + close via setImmediate so the event handlers (registered + // AFTER stdin.end() in the plugin body) are already attached when + // these events fire. All three items land in the same setImmediate + // callback, so they're all in chunks[] before the drain loop resumes. + setImmediate(() => { + proc.stdout.emit('data', Buffer.from('partial-chunk-1')); + proc.stdout.emit('data', Buffer.from('partial-chunk-2')); + proc.stderr.emit('end'); + proc.emit('close', 0, null); // exitCode=0, done=true + }); + }, + }; + proc.killed = false; + proc.kill = (_sig) => { /* already closed */ }; + return proc; + }); + + try { + const irReq = makeIR({ model: 'claude-sonnet-4-6', stream: false }); + const gen = anthropic.spawn(irReq, { accessToken: 'fake-16e' }); + + // Pull exactly one chunk. Sequence: + // - Generator body starts: spawnImpl(), stdin.end() (schedules setImmediate) + // - Timer armed (10ms) + // - Drain loop: chunks=[], done=false → enters await (rejectNext set) + // - setImmediate fires: push(data1), push(data2), close queued, done=true + // - push(data1) calls resolveNext() → drain resumes + // - Drain processes data1 → yield → generator suspends. rejectNext=null. + // - gen.next() promise resolves with the first chunk. + let firstResult; + try { + firstResult = await gen.next(); + } catch (e) { + throw new Error(`Unexpected throw on first gen.next(): ${e.message}`); + } + assert.ok(firstResult && !firstResult.done, 'Expected first gen.next() to yield a chunk'); + + // Wait > 10ms. During this pause: + // - Timer fires: spawnTimedOut=true, rejectNext===null → branch skipped. + // - Race condition has now occurred (timer fired with no active rejectNext). + await new Promise(r => setTimeout(r, 25)); + + // Resume draining. Drain loop processes second data + 'close' → breaks. + // Post-loop: spawnTimedOut=true. + // Pre-D24: generator returns normally (done=true, no throw). FAIL. + // Post-D24: `if (spawnTimedOut) throw ProviderError SPAWN_TIMEOUT`. PASS. + let caughtError = null; + try { + while (true) { + const { value, done: genDone } = await gen.next(); + if (genDone) break; + void value; + } + } catch (e) { + caughtError = e; + } + + assert.ok(caughtError !== null, + 'Expected ProviderError SPAWN_TIMEOUT (D24 race fix: pre-D24 generator returned normally with partial chunks)'); + assert.ok(caughtError instanceof ProviderError, + `Expected ProviderError, got ${caughtError?.constructor?.name}`); + assert.equal(caughtError.code, 'SPAWN_TIMEOUT', + `Expected SPAWN_TIMEOUT code, got ${caughtError?.code}`); + } finally { + anthropic.hints.maxSpawnTimeMs = savedTimeout; + __resetSpawnImpl(); + if (savedToken !== undefined) { + process.env.CLAUDE_CODE_OAUTH_TOKEN = savedToken; + } else { + delete process.env.CLAUDE_CODE_OAUTH_TOKEN; + } + } + }); + });