feat+docs+test: D39 — D16 follow-ups (issue #3, 4 parts)

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 <noreply@anthropic.com>
This commit is contained in:
2026-05-24 21:13:57 +10:00
co-authored by Claude Opus 4.7
parent 994568a8fb
commit bdfea6884b
6 changed files with 301 additions and 5 deletions
+217
View File
@@ -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 ─────────