diff --git a/lib/cache/keys.mjs b/lib/cache/keys.mjs index d115973..e5d8041 100644 --- a/lib/cache/keys.mjs +++ b/lib/cache/keys.mjs @@ -162,6 +162,41 @@ export function hasCacheControl(ir) { return extractCacheControlMarkers(ir.messages).length > 0; } +// ── Per-request fingerprint (provider-agnostic) ─────────────────────────── + +/** + * Computes a stable per-request fingerprint over IR fields that define the + * request semantics (independent of provider/model). Used by fallback engine + * (D28 round-3 F2) to correlate per-hop log events from the same logical + * request. Returns first 16 hex characters of SHA-256 for compact log lines. + * + * Fields included (must mirror the cache key composition without (provider, model)): + * messages (normalized), tools, temperature, max_tokens, top_p, stop, + * tool_choice, response_format + * + * Note: cache_control is intentionally excluded here — it is a routing hint, + * not a semantic field that changes the request's logical identity for + * observability purposes. + * + * @param {object} ir + * @returns {string} — 16-character hex digest + */ +export function computeIRRequestHash(ir) { + // Use normalizeMessages so semantically-identical message arrays produce + // identical hashes (e.g. content array vs string normalization). + const subset = { + messages: normalizeMessages(ir.messages ?? []), + tools: ir.tools ?? null, + temperature: ir.temperature ?? null, + max_tokens: ir.max_tokens ?? null, + top_p: ir.top_p ?? null, + stop: ir.stop ?? null, + tool_choice: ir.tool_choice ?? null, + response_format: ir.response_format ?? null, + }; + return createHash('sha256').update(JSON.stringify(subset)).digest('hex').slice(0, 16); +} + // ── Cache key computation ───────────────────────────────────────────────── /** diff --git a/lib/fallback/engine.mjs b/lib/fallback/engine.mjs index acb5512..52c2e2e 100644 --- a/lib/fallback/engine.mjs +++ b/lib/fallback/engine.mjs @@ -13,12 +13,14 @@ * Sealed at D9. Do NOT modify without an ADR 0004 amendment. */ +import { randomBytes } from 'node:crypto'; import { readFileSync } from 'node:fs'; import { homedir } from 'node:os'; import { join } from 'node:path'; import { ProviderError } from '../providers/base.mjs'; import { getProviderForModel } from '../providers/index.mjs'; +import { computeIRRequestHash } from '../cache/keys.mjs'; // ── Hard-trigger evaluation ──────────────────────────────────────────────── @@ -53,6 +55,35 @@ const HARD_TRIGGER_CODES = { */ const CLIENT_ERROR_STATUSES = new Set([400, 401, 403, 404, 422]); +/** + * Classifies a thrown error into one of the trigger taxonomy categories + * per ADR 0004 § Trigger taxonomy (D28 round-3 F2). Used in log events + * so operators can pivot on the classification bucket. + * + * Note: 'soft' is not currently returnable from this function. Soft triggers + * are evaluated before spawn via evaluateSoftTriggers() and are deferred to + * v1.x (D22 Amendment 2). The 'soft' variant is listed in the JSDoc return + * type for forward-compatibility only. + * + * @param {Error|null|undefined} error + * @returns {'hard' | 'soft' | 'auth_missing' | 'client_error' | 'non_trigger' | null} + */ +function classifyTrigger(error) { + if (!error) return null; + if (error instanceof ProviderError && error.code) { + if (error.code === 'AUTH_MISSING') return 'auth_missing'; + if (HARD_TRIGGER_CODES[error.code] === true) return 'hard'; + return 'non_trigger'; + } + const status = error.statusCode ?? error.status ?? null; + if (status !== null && typeof status === 'number') { + if (CLIENT_ERROR_STATUSES.has(status)) return 'client_error'; + if (status >= 500) return 'hard'; + if (status >= 400) return 'hard'; // quota-exhaustion 4xx (e.g. 429, 529) + } + return 'non_trigger'; +} + /** * Returns true if `status` is a client-side error that must NOT trigger fallback. * Exported for tests. @@ -220,6 +251,12 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option throw new Error('executeWithFallback: chain must be a non-empty array'); } + // D28 round-3 F2: per-request fingerprints for log correlation. + // chain_id is unique per executeWithFallback invocation; ir_request_hash + // is provider-agnostic so it groups all hops from the same logical request. + const chainId = randomBytes(8).toString('hex'); // 16-char hex + const irRequestHash = computeIRRequestHash(irRequest); + const triedProviders = []; let originalError = null; // Per ADR 0004: first-hop error is the canonical signal let firstErrorRecorded = false; @@ -243,9 +280,13 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // visibility; D9 keeps them unified per ADR-0004 spec. if (evaluateSoftTriggers(softTriggers, quotaSnapshot)) { logEvent('info', 'fallback_soft_trigger', { + chain_id: chainId, hop: i, provider, model, + trigger_type: 'soft', + ir_request_hash: irRequestHash, + next_provider: chain[i + 1]?.provider ?? null, reason: 'soft_trigger_fired', }); triedProviders.push(provider); @@ -276,7 +317,15 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // executeHopFn returned successfully = chunks buffered = no client writes // blocked = safe to return. Any retry attempt after this point would be // post-first-chunk and is therefore forbidden. We return immediately. - logEvent('info', 'fallback_hop_success', { hop: i, provider, model }); + logEvent('info', 'fallback_hop_success', { + chain_id: chainId, + hop: i, + provider, + model, + trigger_type: null, + ir_request_hash: irRequestHash, + next_provider: null, + }); return { chunks, providerUsed: provider, @@ -294,18 +343,30 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option } logEvent('warn', 'fallback_hop_error', { + chain_id: chainId, hop: i, provider, model, error: err.message, code: err.code ?? null, + trigger_type: classifyTrigger(err), + ir_request_hash: irRequestHash, + next_provider: chain[i + 1]?.provider ?? null, }); // ── Client error: stop immediately ───────────────────────────── // Per ADR 0004 § "No fallback for client-side errors" const status = err.statusCode ?? err.status ?? null; if (status !== null && CLIENT_ERROR_STATUSES.has(status)) { - logEvent('warn', 'fallback_client_error_no_fallback', { hop: i, provider, status }); + logEvent('warn', 'fallback_client_error_no_fallback', { + chain_id: chainId, + hop: i, + provider, + status, + trigger_type: 'client_error', + ir_request_hash: irRequestHash, + next_provider: null, + }); return { chunks: null, providerUsed: provider, @@ -321,7 +382,14 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // Silently masking it by trying next provider prevents user from discovering // the misconfiguration. if (err instanceof ProviderError && err.code === 'AUTH_MISSING') { - logEvent('warn', 'fallback_auth_missing_no_fallback', { hop: i, provider }); + logEvent('warn', 'fallback_auth_missing_no_fallback', { + chain_id: chainId, + hop: i, + provider, + trigger_type: 'auth_missing', + ir_request_hash: irRequestHash, + next_provider: null, + }); return { chunks: null, providerUsed: provider, @@ -338,12 +406,16 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // Fallback is eligible if the error is a hard trigger. if (evaluateHardTriggers(err)) { logEvent('info', 'fallback_hard_trigger', { + chain_id: chainId, hop: i, provider, model, error: err.message, code: err.code ?? null, advance_to_hop: i + 1, + trigger_type: classifyTrigger(err), + ir_request_hash: irRequestHash, + next_provider: chain[i + 1]?.provider ?? null, }); continue; // advance to next hop } @@ -351,10 +423,14 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // ── Non-trigger error: surface immediately ────────────────────── // Per ADR 0004 § Alternatives considered (a): "any error" fallback rejected. logEvent('warn', 'fallback_non_trigger_error', { + chain_id: chainId, hop: i, provider, error: err.message, code: err.code ?? null, + trigger_type: classifyTrigger(err), + ir_request_hash: irRequestHash, + next_provider: null, }); return { chunks: null, @@ -371,8 +447,12 @@ export async function executeWithFallback(chain, irRequest, executeHopFn, option // Per ADR 0004 § Decision § Chain advancement step 4: // "return A's original error (not B's, not C's)" logEvent('error', 'fallback_chain_exhausted', { + chain_id: chainId, chain: chain.map(h => h.provider), triedProviders, + trigger_type: null, + ir_request_hash: irRequestHash, + next_provider: null, }); return { diff --git a/test-features.mjs b/test-features.mjs index b9cab0e..eea2046 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -4955,6 +4955,319 @@ describe('Fallback engine — HTTP integration (D9)', () => { }); +// ── Suite 13g: D28 round-3 F2 — structured log observability fields ───────── +// +// Tests that all executeWithFallback logEvent calls carry the 4 new fields: +// chain_id, ir_request_hash, trigger_type, next_provider +// +// Also tests computeIRRequestHash (stability, provider-agnosticism, per-field sensitivity). +// +// Authority: ADR 0004 § Observability headers + +import { computeIRRequestHash } from './lib/cache/keys.mjs'; + +describe('Fallback engine — D28 observability fields (chain_id / ir_request_hash / trigger_type / next_provider)', () => { + + // ── Helper: capture all logEvent calls ──────────────────────────────────── + + function makeLogCapture() { + const events = []; + return { + logEvent: (level, event, data) => events.push({ level, event, data }), + events, + }; + } + + // ── chain_id: present + 16-char hex + consistent across all hops ────────── + + it('chain_id is present in all events and is 16-char hex', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Rate limited', 'RATE_LIMITED'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + assert.ok(events.length >= 2, 'Expected at least 2 log events'); + for (const e of events) { + assert.ok(typeof e.data.chain_id === 'string', `chain_id must be string, event: ${e.event}`); + assert.match(e.data.chain_id, /^[0-9a-f]{16}$/, `chain_id must be 16-char hex, event: ${e.event}`); + } + }); + + it('chain_id is consistent across all hops from one executeWithFallback call', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Rate limited', 'RATE_LIMITED'); + const chain = [ + { provider: 'a', model: 'model-a' }, + { provider: 'b', model: 'model-b' }, + { provider: 'c', model: 'model-c' }, + ]; + const hopFn = async (provider) => { + if (provider === 'a') throw err; + if (provider === 'b') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + assert.ok(events.length >= 3, 'Expected at least 3 log events'); + const ids = new Set(events.map(e => e.data.chain_id)); + assert.equal(ids.size, 1, `All events in one call must share the same chain_id, got: ${[...ids]}`); + }); + + it('chain_id differs between separate executeWithFallback calls', async () => { + const chain = [{ provider: 'anthropic', model: 'claude-sonnet-4-6' }]; + const hopFn = async () => [{ type: 'stop', finish_reason: 'stop' }]; + const { logEvent: log1, events: events1 } = makeLogCapture(); + const { logEvent: log2, events: events2 } = makeLogCapture(); + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent: log1 }); + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent: log2 }); + assert.ok(events1.length >= 1); + assert.ok(events2.length >= 1); + // With overwhelming probability two random 8-byte values are different + assert.notEqual(events1[0].data.chain_id, events2[0].data.chain_id, + 'Separate calls must have different chain_ids'); + }); + + // ── ir_request_hash: provider-agnostic + consistent across hops ─────────── + + it('ir_request_hash is the same across all hops within one chain', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Rate limited', 'RATE_LIMITED'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'some-model' }), hopFn, { logEvent }); + const hashes = new Set(events.map(e => e.data.ir_request_hash)); + assert.equal(hashes.size, 1, `All hops must share the same ir_request_hash, got: ${[...hashes]}`); + }); + + it('ir_request_hash does not change when provider or model changes but content is same', async () => { + const ir = makeIR({ model: 'claude-sonnet-4-6', messages: [{ role: 'user', content: 'Hello' }] }); + const hash1 = computeIRRequestHash(ir); + // Same IR, different model field (computeIRRequestHash is provider-agnostic) + const ir2 = makeIR({ model: 'gpt-5.5', messages: [{ role: 'user', content: 'Hello' }] }); + const hash2 = computeIRRequestHash(ir2); + // model is NOT in the computeIRRequestHash subset, so hashes must be equal + assert.equal(hash1, hash2, 'ir_request_hash must be provider/model-agnostic'); + }); + + // ── trigger_type: classification per error type ─────────────────────────── + + it('trigger_type is "hard" for QUOTA_EXHAUSTED (fallback_hard_trigger event)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Quota exhausted', 'QUOTA_EXHAUSTED'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const hardEvent = events.find(e => e.event === 'fallback_hard_trigger'); + assert.ok(hardEvent, 'Expected fallback_hard_trigger event'); + assert.equal(hardEvent.data.trigger_type, 'hard'); + }); + + it('trigger_type is "auth_missing" for AUTH_MISSING (fallback_auth_missing_no_fallback event)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Auth missing', 'AUTH_MISSING'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const authEvent = events.find(e => e.event === 'fallback_auth_missing_no_fallback'); + assert.ok(authEvent, 'Expected fallback_auth_missing_no_fallback event'); + assert.equal(authEvent.data.trigger_type, 'auth_missing'); + }); + + it('trigger_type is "client_error" for HTTP 400 (fallback_client_error_no_fallback event)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = Object.assign(new Error('Bad request'), { statusCode: 400 }); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const clientEvent = events.find(e => e.event === 'fallback_client_error_no_fallback'); + assert.ok(clientEvent, 'Expected fallback_client_error_no_fallback event'); + assert.equal(clientEvent.data.trigger_type, 'client_error'); + }); + + it('trigger_type is "non_trigger" for generic error (fallback_non_trigger_error event)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new Error('Unexpected generic error'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const nonTriggerEvent = events.find(e => e.event === 'fallback_non_trigger_error'); + assert.ok(nonTriggerEvent, 'Expected fallback_non_trigger_error event'); + assert.equal(nonTriggerEvent.data.trigger_type, 'non_trigger'); + }); + + it('trigger_type is null on success (fallback_hop_success event)', async () => { + const { logEvent, events } = makeLogCapture(); + const chain = [{ provider: 'anthropic', model: 'claude-sonnet-4-6' }]; + const hopFn = async () => [{ type: 'stop', finish_reason: 'stop' }]; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const successEvent = events.find(e => e.event === 'fallback_hop_success'); + assert.ok(successEvent, 'Expected fallback_hop_success event'); + assert.equal(successEvent.data.trigger_type, null); + }); + + // ── next_provider: lookahead routing ────────────────────────────────────── + + it('next_provider is chain[i+1].provider when chain advances on hard trigger', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Rate limited', 'RATE_LIMITED'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const hardEvent = events.find(e => e.event === 'fallback_hard_trigger'); + assert.ok(hardEvent, 'Expected fallback_hard_trigger event'); + assert.equal(hardEvent.data.next_provider, 'openai', 'next_provider must be the next chain hop'); + }); + + it('next_provider is null on the last hop (chain exhausted)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = new ProviderError('Rate limited', 'RATE_LIMITED'); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + ]; + const hopFn = async () => { throw err; }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const exhaustedEvent = events.find(e => e.event === 'fallback_chain_exhausted'); + assert.ok(exhaustedEvent, 'Expected fallback_chain_exhausted event'); + assert.equal(exhaustedEvent.data.next_provider, null, 'next_provider must be null when chain is exhausted'); + }); + + it('next_provider is null on client error stop (no advancement)', async () => { + const { logEvent, events } = makeLogCapture(); + const err = Object.assign(new Error('Bad request'), { statusCode: 422 }); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async (provider) => { + if (provider === 'anthropic') throw err; + return [{ type: 'stop', finish_reason: 'stop' }]; + }; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const clientEvent = events.find(e => e.event === 'fallback_client_error_no_fallback'); + assert.ok(clientEvent, 'Expected fallback_client_error_no_fallback event'); + assert.equal(clientEvent.data.next_provider, null, 'next_provider must be null when not advancing'); + }); + + it('next_provider is null on success (no advancement needed)', async () => { + const { logEvent, events } = makeLogCapture(); + const chain = [ + { provider: 'anthropic', model: 'claude-sonnet-4-6' }, + { provider: 'openai', model: 'gpt-5.5' }, + ]; + const hopFn = async () => [{ type: 'stop', finish_reason: 'stop' }]; + await executeWithFallback(chain, makeIR({ model: 'test-model' }), hopFn, { logEvent }); + const successEvent = events.find(e => e.event === 'fallback_hop_success'); + assert.ok(successEvent, 'Expected fallback_hop_success event'); + assert.equal(successEvent.data.next_provider, null, 'next_provider must be null on success'); + }); + + // ── computeIRRequestHash: stability + per-field sensitivity ─────────────── + + it('computeIRRequestHash: identical IR inputs → identical hash', () => { + const ir1 = makeIR({ messages: [{ role: 'user', content: 'Hello' }], model: 'model-a' }); + const ir2 = makeIR({ messages: [{ role: 'user', content: 'Hello' }], model: 'model-a' }); + assert.equal(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: returns 16-char hex string', () => { + const ir = makeIR({ messages: [{ role: 'user', content: 'Hello' }] }); + const hash = computeIRRequestHash(ir); + assert.equal(typeof hash, 'string'); + assert.equal(hash.length, 16); + assert.match(hash, /^[0-9a-f]{16}$/); + }); + + it('computeIRRequestHash: changes when messages content changes', () => { + const ir1 = makeIR({ messages: [{ role: 'user', content: 'Hello' }] }); + const ir2 = makeIR({ messages: [{ role: 'user', content: 'Goodbye' }] }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when temperature changes', () => { + const ir1 = makeIR({ temperature: 0.5 }); + const ir2 = makeIR({ temperature: 1.0 }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when max_tokens changes', () => { + const ir1 = makeIR({ max_tokens: 100 }); + const ir2 = makeIR({ max_tokens: 200 }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when top_p changes', () => { + const ir1 = makeIR({ top_p: 0.9 }); + const ir2 = makeIR({ top_p: 0.5 }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when stop changes', () => { + const ir1 = makeIR({ stop: ['END'] }); + const ir2 = makeIR({ stop: ['STOP'] }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when tool_choice changes', () => { + const ir1 = makeIR({ tool_choice: 'auto' }); + const ir2 = makeIR({ tool_choice: 'none' }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when response_format changes', () => { + const ir1 = makeIR({ response_format: { type: 'text' } }); + const ir2 = makeIR({ response_format: { type: 'json_object' } }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + + it('computeIRRequestHash: changes when tools changes', () => { + const ir1 = makeIR({ tools: [{ type: 'function', function: { name: 'foo' } }] }); + const ir2 = makeIR({ tools: [{ type: 'function', function: { name: 'bar' } }] }); + assert.notEqual(computeIRRequestHash(ir1), computeIRRequestHash(ir2)); + }); + +}); + // ── Suite 14: providers.enabled config wiring ────────────────────────────── // // Tests that: