mirror of
https://github.com/dtzp555-max/olp.git
synced 2026-07-19 09:45:07 +00:00
fix(providers): D24 — close spawn-timeout race when timer fires during yield-suspension (round-2 F4)
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(
`<cli-name> 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 <noreply@anthropic.com>
This commit is contained in:
@@ -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;
|
||||
}
|
||||
}
|
||||
});
|
||||
|
||||
});
|
||||
|
||||
Reference in New Issue
Block a user