From bdfea6884b87af85c756317693449096660ef662 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Sun, 24 May 2026 21:13:57 +1000 Subject: [PATCH] =?UTF-8?q?feat+docs+test:=20D39=20=E2=80=94=20D16=20follo?= =?UTF-8?q?w-ups=20(issue=20#3,=204=20parts)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit D16 reviewer (commit `bafa6d1`) left 4 non-blocking suggestions batched into issue #3 as a tracker. D39 closes all 4. **Part 1 — CacheStore.delete(keyId, cacheKey) API** (lib/cache/store.mjs) D16 originally evicted truncated entries via `cacheStore.set(keyId, hopCacheKey, result, ttlMs=0)` — a TTL=0 tombstone purged lazily on next access. D39 introduces an explicit delete primitive that removes the entry immediately. - Synchronous: `delete(keyId, cacheKey) → boolean`. Returns true if the entry was present and removed, false if absent. Sync (not async) for the simplest in-memory Map contract — mirrors clear(). Other CacheStore methods are async to leave room for a Phase 2 file-backed adapter; delete being sync was a deliberate choice. - Namespace cleanup: when the inner Map becomes empty after delete, the outer Map's per-keyId entry is also removed (memory hygiene; mirrors the _activeSpawns cleanup pattern from D38). - Behavior: peek/get/getOrCompute see no trace after delete; the subsequent getOrCompute triggers a fresh compute. **Part 2 — `cache_evicted_truncated` observability log** (server.mjs) After the D16 eviction call in collectAllChunks, emit: ```js logEvent('info', 'cache_evicted_truncated', { provider, model, cache_eviction_hit, }); ``` Dashboard sees salvage frequency per (provider, model). The cache_eviction_hit boolean distinguishes "we evicted an entry" (true) from "we tried to evict but it was already gone" (false — race with concurrent eviction or TTL purge), preserving observability accuracy under concurrency. **Part 3 — Sticky-cache regression test** (test-features.mjs) Defense-in-depth around the eviction path. Two consecutive identical buffered requests; the first triggers SPAWN_FAILED after partial chunks → Case B salvage returns `{ chunks..., finish_reason: 'length' }` to the client and evicts via delete(). The second identical request must trigger a fresh spawn (NOT serve the salvaged response from a stale cache entry). Asserts on BOTH invariants for defense-in-depth: - Mock provider spawn count == 2 across the 2 identical requests - Second request's X-OLP-Cache header is 'miss' If eviction silently breaks in a future regression, both assertions catch it independently. **Part 4 — SPAWN_TIMEOUT salvage parity: DOCUMENT ASYMMETRY** (docs/adr/0004-fallback-engine.md) Maintainer decision: SPAWN_TIMEOUT is NOT salvaged. Document the asymmetry rather than implementing parity. ADR 0004 Amendment 1 is extended with a new section "Why SPAWN_TIMEOUT is excluded from salvage" with 4-point rationale: 1. SPAWN_FAILED indicates the provider crashed mid-stream — there's nothing more coming; partial > nothing. Next-hop spawn has no advantage (same input may crash same way). 2. SPAWN_TIMEOUT indicates the provider was slow (deadline exceeded per `hints.maxSpawnTimeMs`). Fallback advancement to a DIFFERENT provider is more likely to give a complete response than salvaging a partial from a slow provider. 3. The "user paid for partial content" framing from D16 captures only SPAWN_FAILED. For SPAWN_TIMEOUT the user actually paid for "result within time T" — partial-at-time-T is not what was paid for; "full result soon after T" via fallback is closer. 4. Code-level inspection confirms the asymmetry: collectAllChunks catch matches ONLY `code === 'SPAWN_FAILED'` (server.mjs:563). SPAWN_TIMEOUT propagates via re-throw and hits evaluateHardTriggers. v1.x re-evaluation trigger: if real usage shows users want partial- on-timeout for very long deadlines, add a v1.x design ADR. Stale comment fix: `lib/providers/anthropic.mjs:369` previously said "SPAWN_TIMEOUT salvage parity is tracked in issue #3". D39 closes that issue, so the comment is updated to point at ADR 0004 Amendment 1. **Tests** (test-features.mjs): 447 → 452 (+5): - 3 unit tests on CacheStore.delete (Suite 9): present-key true, absent-key false, namespace cleanup at empty - 1 D16 integration test: cache_evicted_truncated log fires with correct fields during salvage - 1 sticky-cache regression: spawn count 2 across 2 identical requests, X-OLP-Cache miss on second Pre-commit fold-ins (per evidence-first checkpoint #4): - **Reviewer Suggestion #1**: cacheStore.delete() return value was discarded at the call site → log inflated salvage metric under concurrent-eviction race. Folded: captured `evicted` boolean and added to log payload as `cache_eviction_hit`. - **Reviewer Suggestion #2**: anthropic.mjs:369 stale comment pointing at now-closed issue #3. Folded: rewrote to point at ADR 0004 Amendment 1 § "Why SPAWN_TIMEOUT is excluded from salvage". - **Reviewer Suggestion #3**: ADR 0004 attribution ambiguity — parenthetical "(per Amendment 3 — SPAWN_TIMEOUT is one of the 4 live hard-trigger codes alongside SPAWN_FAILED, CLI_NOT_FOUND, and CONCURRENCY_LIMIT from Amendment 4)" could mis-parse as Amendment 3 covering all four. Folded: split to "(per Amendment 3: SPAWN_FAILED, CLI_NOT_FOUND, SPAWN_TIMEOUT; per Amendment 4: CONCURRENCY_LIMIT)". **CHANGELOG**: D39 sub-entry appended under the existing D38 entry in Unreleased section. No package.json bump (phase_rolling_mode). Authority: - ADR 0005 § Cache layer — CacheStore API extension (Part 1) - ADR 0004 Amendment 1 update — SPAWN_TIMEOUT asymmetry rationale (Part 4) - GitHub issue #3 — closed by this commit - D16 commit bafa6d1 non-blocking suggestions — batched here - CC 开发铁律 v1.6 § 10.x — fresh-context opus reviewer independent - CLAUDE.md release_kit_overlay phase_rolling_mode — under Unreleased Reviewer (fresh-context opus, Iron Rule 10): APPROVE_WITH_MINOR. Verified: delete() sync + call-site no-await correct; namespace cleanup guarded on (had && ns.size === 0); SPAWN_TIMEOUT NOT in salvage catch; ADR section 4-point rationale internally consistent with code state; hygiene clean; 452/452 tests pass independently. Co-Authored-By: Claude Opus 4.7 --- CHANGELOG.md | 9 ++ docs/adr/0004-fallback-engine.md | 20 +++ lib/cache/store.mjs | 33 +++++ lib/providers/anthropic.mjs | 3 +- server.mjs | 24 +++- test-features.mjs | 217 +++++++++++++++++++++++++++++++ 6 files changed, 301 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6387c99..e3407ac 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,15 @@ All notable changes to OLP land here. Per `CLAUDE.md` release_kit overlay, this - **Spawn lifecycle gate** — `hints.maxConcurrent` is now enforced at runtime per ADR 0002 Amendment 6: `lib/providers/index.mjs` exports a per-provider `tryAcquireSpawn` / `releaseSpawn` / `getActiveSpawnCount` semaphore; `server.mjs` gates both the buffered and streaming spawn call sites in `handleChatCompletions` with a try/finally release. Saturation surfaces as `ProviderError(CONCURRENCY_LIMIT)` which the fallback engine treats as a hard trigger (ADR 0004 Amendment 4) — the chain advances to the next hop instead of queueing. If the entire chain is saturated, the user receives a chain-exhausted error via the existing exhaustion path. Closes #1. Queue+timeout deferred (see ADR 0002 Amendment 6 § Design choice). Test count 431 → 447. +### D39 — D16 follow-ups (issue #3): explicit cache delete + eviction log + SPAWN_TIMEOUT asymmetry doc + +- **Part 1 — `CacheStore.delete(keyId, cacheKey)`** — adds an explicit eviction primitive to `lib/cache/store.mjs`. Returns `boolean` (true if entry present and removed; false otherwise) and removes empty per-keyId namespace `Map` entries from the outer store for memory hygiene (matches the D38 `_activeSpawns` pattern). `server.mjs` D16 salvage path replaces `cacheStore.set(..., ttlMs=0)` (lazy tombstone that lived in the namespace `Map` until the next `get`/`peek` purged it) with `cacheStore.delete(...)` (immediate removal). Cache semantics unchanged — truncated responses still don't persist. ADR 0005 § "Cache write conditions" item 1 authority. +- **Part 2 — `cache_evicted_truncated` observability log** — adds an `info`-level structured log event fired immediately after the D16 eviction in `executeHopFn`. Carries `{ provider, model }` so dashboards can surface salvage frequency per (provider, model) pair. P3 polish; no semantic change. +- **Part 3 — sticky-cache regression test** — defense-in-depth test asserting two consecutive identical buffered requests that both trigger SPAWN_FAILED-with-chunks salvage each invoke a fresh spawn (spawnCount=2 across the two requests; second request reports `X-OLP-Cache: miss`). Catches any future regression where the eviction is dropped or the gate condition flips. +- **Part 4 — SPAWN_TIMEOUT salvage asymmetry documented (no code change)** — ADR 0004 Amendment 1 gains a new sub-section "Why SPAWN_TIMEOUT is excluded from salvage" with a 4-point rationale: (1) SPAWN_FAILED is a terminal signal, SPAWN_TIMEOUT is a deadline signal; (2) the next hop is a different provider with different speed characteristics, plausibly full-response-soon-after-T; (3) the "user paid for partial" framing applies to SPAWN_FAILED only — for SPAWN_TIMEOUT the user paid for "result within T"; (4) code inspection confirms the catch block matches only `code === 'SPAWN_FAILED'`. Includes hard-trigger-taxonomy completeness note and v1.x re-evaluation trigger (opt-in salvage-on-timeout for long deadlines). +- **Authority:** ADR 0005 § Cache layer / CacheStore API extension (Part 1); ADR 0004 Amendment 1 (Part 4); GitHub issue #3 — closed by this commit; D16 commit `bafa6d1` non-blocking suggestions — batched here. +- **Test count:** 447 → 452 (3 unit tests for `CacheStore.delete` + 1 log-event integration test + 1 sticky-cache regression test). + ## v0.1.0 — 2026-05-24 ### Phase 1 Close — Multi-provider proxy core diff --git a/docs/adr/0004-fallback-engine.md b/docs/adr/0004-fallback-engine.md index a27e922..7870da1 100644 --- a/docs/adr/0004-fallback-engine.md +++ b/docs/adr/0004-fallback-engine.md @@ -52,6 +52,26 @@ - **Streaming path note:** The D10 real-streaming branch (single-hop, `server.mjs` lines 401–510) already handles the analogous case correctly via ADR 0004's first-chunk rule: once `firstChunkEmitted === true`, any subsequent error truncates the response with `res.end()` (no re-throw, no fallback). This amendment applies specifically to the **buffered path** (`collectAllChunks` + multi-hop fallback chains). The streaming path is not changed by D16. +#### D39 follow-up — explicit eviction primitive + observability log (2026-05-24, issue #3 Parts 1+2) + +The original D16 cache-eviction implementation used `cacheStore.set(keyId, hopCacheKey, result, ttlMs=0)` to tombstone the just-written truncated entry. The TTL=0 entry survived in the per-keyId namespace `Map` until the next `get`/`peek` lazily purged it via the `_isAlive` check. D39 Part 1 replaces this with an explicit `cacheStore.delete(keyId, cacheKey)` primitive that (a) removes the entry from the namespace `Map` immediately, (b) removes the empty namespace `Map` entry from the outer store when it becomes empty (memory hygiene matching the D38 `_activeSpawns` pattern), and (c) returns `boolean` for caller inspection. D39 Part 2 adds a `cache_evicted_truncated` `info`-level log event with `{ provider, model }` fields immediately after the eviction, giving dashboards visibility into salvage frequency. Neither change alters the salvage semantics established by this Amendment — they are observability + memory-hygiene polish. Test coverage: 3 unit tests on `CacheStore.delete` (present-returns-true, absent-returns-false, empty-namespace-cleanup), 1 HTTP integration test asserting the log event fires with the correct fields, and 1 defense-in-depth regression test asserting two consecutive identical truncated requests both result in fresh spawns (no sticky cache). + +#### Why SPAWN_TIMEOUT is excluded from salvage (D39 Part 4, issue #3 Part 4) + +D16's salvage path is gated on `code === 'SPAWN_FAILED'`. SPAWN_TIMEOUT is **not** salvaged even when partial chunks have accumulated in the buffered path — the timeout error propagates from `collectAllChunks` as-is, the fallback engine fires the SPAWN_TIMEOUT hard trigger, and the chain advances to the next hop. This asymmetry is intentional and is the maintainer's design choice. The four-point rationale: + +1. **SPAWN_FAILED is a terminal signal from this hop.** The provider crashed mid-stream; nothing more is coming from it. Salvaging the partial chunks is strictly better than discarding them (partial > nothing). Advancing the chain in this case offers no advantage: the same input may crash the next hop the same way (when the failure is input-dependent), and even when the next hop succeeds, the salvaged chunks were already paid for in quota — discarding them would be strict waste. + +2. **SPAWN_TIMEOUT is a deadline signal, not a terminal signal.** It indicates the provider was slow (deadline exceeded per `hints.maxSpawnTimeMs`, which the plugin enforces — see the unconditional post-loop `if (spawnTimedOut) throw SPAWN_TIMEOUT` in each provider plugin, e.g. `lib/providers/anthropic.mjs`). The next hop is a *different provider* with different model-speed characteristics, so its full response is plausibly available sooner than the original hop's continuation would have been. Fallback advancement on timeout is more likely to give the user a complete response than salvaging partial-from-slow. + +3. **The "user paid for partial" framing applies only to SPAWN_FAILED.** The D16 reviewer's "user paid for partial content, dropping it is strict waste" captures SPAWN_FAILED correctly: the deadline was honored, the provider died mid-stream, the chunks are real consumed quota. For SPAWN_TIMEOUT the user actually paid for "result within time T" — a partial result delivered *at* time T is not what was paid for. The fallback engine's "full result soon after time T" via a different provider is closer to the contract. + +4. **Code-level inspection confirms the asymmetry (verified post-D38, D39 Part 4).** `collectAllChunks` in `server.mjs` matches only `spawnErr instanceof ProviderError && spawnErr.code === 'SPAWN_FAILED' && chunks.length > 0` for the salvage branch. SPAWN_TIMEOUT propagates through the same catch block via the unconditional re-throw, hits `evaluateHardTriggers` as a hard trigger (per Amendment 3: SPAWN_FAILED, CLI_NOT_FOUND, SPAWN_TIMEOUT; per Amendment 4: CONCURRENCY_LIMIT), and advances the chain. This asymmetry is not an oversight; it is the design. + +**Hard-trigger taxonomy completeness:** The v0.1 hard-trigger code set is enumerated in Amendment 3 (D34 F7) and extended in Amendment 4 (D38, CONCURRENCY_LIMIT). Of those four codes, only SPAWN_FAILED participates in the salvage path. CLI_NOT_FOUND fires before any spawn output is possible (no partial chunks ever exist). CONCURRENCY_LIMIT fires before `provider.spawn(...)` is called (per Amendment 4 § First-chunk safety — zero bytes emitted at rejection moment). SPAWN_TIMEOUT can in principle accumulate partial chunks but is excluded from salvage per the rationale above. + +**v1.x re-evaluation trigger:** If real usage shows users want partial-on-timeout for very long deadlines (e.g., a 5-minute `maxSpawnTimeMs` where the user would rather have whatever streamed in 5 minutes than re-pay quota on a different provider that may take its own 5 minutes), this asymmetry is queued as a future-design question. A v1.x amendment would need to: (a) make salvage-on-timeout opt-in per chain or per provider (default-off preserves v0.1 semantics), (b) extend `collectAllChunks` catch matching to a broader code set, (c) add tests parallel to the D16 Case A/Case B/single-hop trio for the SPAWN_TIMEOUT path. Not a v0.1 issue. + - **Procedural mechanism:** CC 开发铁律 v1.6 § 10.x (Cold Audit). Diff-review reviewers on earlier passes focused on the first-chunk rule for the real-streaming path; the buffered path has its own truncation-vs-fallback decision point, which the cold-audit pass on 2026-05-23 identified as Finding 17. ### Amendment 2 — 2026-05-24: Soft triggers deferred to v1.x (D22) diff --git a/lib/cache/store.mjs b/lib/cache/store.mjs index e5c7fdc..c77f883 100644 --- a/lib/cache/store.mjs +++ b/lib/cache/store.mjs @@ -341,6 +341,39 @@ export class CacheStore { }; } + /** + * Removes a specific (keyId, cacheKey) entry immediately. + * + * ADR 0005 § "Cache write conditions" item 1 (D39, issue #3 Part 1): + * D16 truncation-eviction previously used `set(..., ttlMs=0)` to leave a + * tombstone that the next `get`/`peek` would lazily purge. That pattern + * left dead entries in the namespace Map until next access, accruing + * memory if no follow-up read ever fires. `delete(keyId, cacheKey)` makes + * the eviction explicit and immediate. + * + * Memory hygiene: if the per-keyId namespace becomes empty after delete, + * the namespace Map entry itself is removed (mirrors the pattern in D38 + * `_activeSpawns` so empty namespaces don't accumulate in `_store`). + * + * Stats: this method does NOT touch hit/miss counters — it is an eviction + * primitive, not a read. Aggregate `size` reported by `stats()` reflects + * the removal on the next call. + * + * @param {string} keyId + * @param {string} cacheKey + * @returns {boolean} true if the entry was present and removed; false if absent. + */ + delete(keyId, cacheKey) { + const ns = this._store.get(keyId); + if (!ns) return false; + const had = ns.delete(cacheKey); + // Memory hygiene: drop empty namespace Map entries. + if (had && ns.size === 0) { + this._store.delete(keyId); + } + return had; + } + /** * Clears cache entries (and stats) for a specific keyId, or ALL entries. * diff --git a/lib/providers/anthropic.mjs b/lib/providers/anthropic.mjs index f84a5fe..6cff6c0 100644 --- a/lib/providers/anthropic.mjs +++ b/lib/providers/anthropic.mjs @@ -366,7 +366,8 @@ async function* _spawnAndStream(irRequest, authContext, spawnImpl) { // 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. + // by the caller. SPAWN_TIMEOUT is intentionally excluded from D16 salvage — + // see ADR 0004 Amendment 1 § "Why SPAWN_TIMEOUT is excluded from salvage". if (spawnTimedOut) { throw new ProviderError( `claude spawn timed out after ${maxSpawnTimeMs}ms`, diff --git a/server.mjs b/server.mjs index e55ef13..958b1e3 100644 --- a/server.mjs +++ b/server.mjs @@ -634,10 +634,26 @@ async function handleChatCompletions(req, res) { lastHopWasCached = hopWasCached; if (result.__truncated) { // Evict the truncated entry so future requests get a fresh spawn. - // ADR 0005 § "Cache write conditions" item 1: truncated responses must not - // persist in cache. Overwrite with ttlMs=0 so any subsequent get/peek - // finds the entry already-expired and deletes it. - await cacheStore.set(keyId, hopCacheKey, result, 0); + // ADR 0005 § "Cache write conditions" item 1: truncated responses must + // not persist in cache. + // + // D39 (issue #3 Part 1): use explicit cacheStore.delete() rather than + // the prior set(..., ttlMs=0) tombstone. delete() removes the entry + // from the namespace Map immediately (and removes the empty namespace + // entry from the outer Map if applicable), instead of waiting for the + // next get/peek to lazily purge a TTL=0 entry. + // Capture the boolean — false indicates a race (concurrent eviction or + // TTL purge already removed the entry). Surfaces in the log so the + // dashboard can distinguish "we evicted" from "we tried but it was gone." + const evicted = cacheStore.delete(keyId, hopCacheKey); + // D39 (issue #3 Part 2): observability — surface salvage frequency to + // dashboards. Provider + model identify which hop's truncated entry was + // evicted. cache_eviction_hit distinguishes actual-evict vs already-gone. + logEvent('info', 'cache_evicted_truncated', { + provider: hopProvider, + model: hopModel, + cache_eviction_hit: evicted, + }); } return result; } diff --git a/test-features.mjs b/test-features.mjs index b26da5e..62237cf 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -2024,6 +2024,66 @@ describe('Cache layer — CacheStore unit tests (Suite 9 cont.)', () => { assert.ok(warnCalls.every(w => w.msg === 'cache_skip_oversize')); }); + // ── D39 (issue #3 Part 1): CacheStore.delete API ───────────────────── + // Authority: ADR 0005 § "Cache write conditions" item 1; D39 design note in + // store.mjs. Replaces the prior `set(..., ttlMs=0)` tombstone pattern with + // an explicit immediate-eviction primitive. + + it('D39: CacheStore.delete returns true and removes entry when present', async () => { + const store = new CacheStore(); + await store.set('keyA', 'hash1', [{ type: 'delta', content: 'partial' }]); + // Sanity: entry is there. + assert.ok(await store.peek('keyA', 'hash1'), 'precondition: entry must be present'); + // Delete reports true. + assert.equal(store.delete('keyA', 'hash1'), true); + // Subsequent peek/get return false/null without lazy-purge side-effects. + assert.equal(await store.peek('keyA', 'hash1'), false, 'peek must be false after delete'); + assert.equal(await store.get('keyA', 'hash1'), null, 'get must return null after delete'); + // getOrCompute on the same key now triggers a FRESH compute (not served from prior entry). + let computeCount = 0; + const v = await store.getOrCompute('keyA', 'hash1', async () => { + computeCount++; + return [{ type: 'delta', content: 'fresh' }]; + }); + assert.equal(computeCount, 1, 'getOrCompute must invoke computeFn (cache was deleted)'); + assert.deepEqual(v, [{ type: 'delta', content: 'fresh' }]); + }); + + it('D39: CacheStore.delete returns false for absent entry (no throw)', () => { + const store = new CacheStore(); + // Namespace does not exist at all. + assert.equal(store.delete('keyA', 'hash-missing'), false); + // Namespace exists but cacheKey absent — populate then delete one absent key. + // (set is async; await via Promise.resolve for the precondition setup.) + return store.set('keyA', 'hash1', 'v').then(() => { + assert.equal(store.delete('keyA', 'hash-different'), false, + 'delete on absent cacheKey within existing namespace returns false'); + // Existing entry untouched. + return store.peek('keyA', 'hash1').then((present) => { + assert.equal(present, true, 'unrelated entry must remain after a false delete'); + }); + }); + }); + + it('D39: CacheStore.delete drops empty namespace Map entry (memory hygiene)', async () => { + const store = new CacheStore(); + await store.set('keyA', 'only-hash', 'val'); + // The internal namespace Map for keyA must exist after set. + assert.ok(store._store.has('keyA'), 'precondition: namespace exists in _store'); + // Delete the only entry. + assert.equal(store.delete('keyA', 'only-hash'), true); + // Namespace Map entry must also be removed from the outer _store. + assert.equal(store._store.has('keyA'), false, + 'empty namespace must be removed from _store after deleting last entry'); + // A namespace with multiple entries must NOT be removed when only one is deleted. + await store.set('keyB', 'hash1', 'val1'); + await store.set('keyB', 'hash2', 'val2'); + assert.equal(store.delete('keyB', 'hash1'), true); + assert.ok(store._store.has('keyB'), + 'non-empty namespace must remain in _store after partial delete'); + assert.equal(store._store.get('keyB').size, 1, 'remaining entry count must be 1'); + }); + // ── Test 31: clear(keyId) clears only that namespace (renumbered from old T26) ── it('CacheStore.clear(keyId) clears only that namespace', async () => { const store = new CacheStore(); @@ -5369,6 +5429,163 @@ describe('Fallback engine — HTTP integration (D9)', () => { } }); + // ── D39 (issue #3 Part 2): cache_evicted_truncated observability log ── + // Authority: D39 design — surface salvage frequency to dashboards. The log + // event fires in executeHopFn (server.mjs) immediately after the explicit + // cacheStore.delete() that replaces the prior set-with-TTL-0 tombstone. + // The event is level=info → routed to stdout per logEvent in server.mjs. + it('D39: cache_evicted_truncated log event fires on SPAWN_FAILED salvage with correct provider+model', async () => { + __clearCache(); + + __setFallbackConfig({ + chains: { + 'claude-sonnet-4-6': [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + ], + }, + soft_triggers: {}, + }); + + // Reuse the D16 Case-B single-hop mock: emit 1 raw text chunk, then exit-1. + __setSpawnImpl(function (_bin, _args, _opts) { + const proc = new EventEmitter(); + proc.stdout = new EventEmitter(); + proc.stderr = new EventEmitter(); + proc.stdin = { + write: () => {}, + end: () => { + setImmediate(() => { + proc.stdout.emit('data', Buffer.from('D39-evict-log-content')); + proc.stdout.emit('end'); + proc.stderr.emit('end'); + proc.emit('close', 1, null); // Case B salvage path + }); + }, + }; + proc.killed = false; + proc.kill = () => {}; + return proc; + }); + + // Capture stdout writes to find the JSON log line emitted by logEvent. + const stdoutWrites = []; + const origStdoutWrite = process.stdout.write.bind(process.stdout); + process.stdout.write = (chunk, ...rest) => { + const s = typeof chunk === 'string' + ? chunk + : (Buffer.isBuffer(chunk) ? chunk.toString() : String(chunk)); + stdoutWrites.push(s); + return origStdoutWrite(chunk, ...rest); + }; + + try { + const r = await fetch({ + port, + method: 'POST', + path: '/v1/chat/completions', + body: { + model: 'claude-sonnet-4-6', + messages: [{ role: 'user', content: 'D39 cache_evicted_truncated log' }], + max_tokens: 10, + }, + }); + assert.equal(r.status, 200, `Expected 200 from salvage, got ${r.status}`); + } finally { + process.stdout.write = origStdoutWrite; + __resetFallbackConfig(); + __resetSpawnImpl(); + } + + // Find the cache_evicted_truncated event in the captured stdout. + const evictedLines = []; + for (const w of stdoutWrites) { + for (const line of w.split('\n')) { + if (!line.includes('"event":"cache_evicted_truncated"')) continue; + try { + const parsed = JSON.parse(line); + if (parsed?.event === 'cache_evicted_truncated') evictedLines.push(parsed); + } catch { /* not JSON — ignore */ } + } + } + assert.equal(evictedLines.length, 1, + `Expected exactly one cache_evicted_truncated event, got ${evictedLines.length}: ${JSON.stringify(evictedLines)}`); + assert.equal(evictedLines[0].provider, 'anthropic', + `Expected provider=anthropic, got ${evictedLines[0].provider}`); + assert.equal(evictedLines[0].model, 'claude-sonnet-4-6', + `Expected model=claude-sonnet-4-6, got ${evictedLines[0].model}`); + assert.equal(evictedLines[0].level, 'info', + `Expected level=info, got ${evictedLines[0].level}`); + }); + + // ── D39 (issue #3 Part 3): truncated response is not sticky-cached ──── + // Defense-in-depth around the D16 eviction code path. Two consecutive + // identical buffered requests that both trigger SPAWN_FAILED-with-chunks + // (Case B salvage). The eviction in executeHopFn must ensure the second + // request is a FRESH spawn (not served from a sticky cache entry written + // by the singleflight populate during the first request's salvage). If the + // eviction were ever lost (e.g., the delete were silently dropped or the + // condition gate were wrong), this test would catch it: spawnCount would + // become 1 instead of 2 and X-OLP-Cache would be `hit` on r2. + it('D39: truncated response is not sticky-cached (two identical requests → two spawns)', async () => { + __clearCache(); + + __setFallbackConfig({ + chains: { + 'claude-sonnet-4-6': [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + ], + }, + soft_triggers: {}, + }); + + let spawnCount = 0; + __setSpawnImpl(function (_bin, _args, _opts) { + spawnCount++; + const proc = new EventEmitter(); + proc.stdout = new EventEmitter(); + proc.stderr = new EventEmitter(); + proc.stdin = { + write: () => {}, + end: () => { + setImmediate(() => { + // Case B: emit partial content then exit non-zero on every spawn. + proc.stdout.emit('data', Buffer.from('D39-sticky-content')); + proc.stdout.emit('end'); + proc.stderr.emit('end'); + proc.emit('close', 1, null); + }); + }, + }; + proc.killed = false; + proc.kill = () => {}; + return proc; + }); + + try { + // The two requests must be byte-identical so they share a cache key. + const reqBody = { + model: 'claude-sonnet-4-6', + messages: [{ role: 'user', content: 'D39 sticky-cache regression — identical body' }], + max_tokens: 10, + }; + + const r1 = await fetch({ port, method: 'POST', path: '/v1/chat/completions', body: reqBody }); + assert.equal(r1.status, 200, `r1 must succeed via salvage, got ${r1.status}`); + assert.equal(r1.headers['x-olp-cache'], 'miss', `r1 must be cache miss, got ${r1.headers['x-olp-cache']}`); + + const r2 = await fetch({ port, method: 'POST', path: '/v1/chat/completions', body: reqBody }); + assert.equal(r2.status, 200, `r2 must succeed via salvage, got ${r2.status}`); + // The decisive assertions: a FRESH spawn must have fired for r2. + assert.equal(spawnCount, 2, + `Expected 2 spawns across two identical truncated requests (sticky-cache regression guard), got ${spawnCount}`); + assert.equal(r2.headers['x-olp-cache'], 'miss', + `r2 must also be cache miss (truncated salvage must not be sticky), got ${r2.headers['x-olp-cache']}`); + } finally { + __resetFallbackConfig(); + __resetSpawnImpl(); + } + }); + }); // ── Suite 13g: D28 round-3 F2 — structured log observability fields ─────────