diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 13743a1..6a7df6b 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -118,5 +118,10 @@ jobs: TOKENMEM_DB_PATH: ${{ runner.temp }}/mneme-ci-cold-pool.db run: node cold-pool-gate.test.mjs + - name: Integration test (embedding timeout — hot path degrades instead of hanging) + env: + TOKENMEM_DB_PATH: ${{ runner.temp }}/mneme-ci-embedding-timeout.db + run: node embedding-timeout.integration.test.mjs + - name: Adapter test (codex-recovery-proxy fault injection) run: node adapters/codex-recovery-proxy/proxy.test.mjs diff --git a/embedding-timeout.integration.test.mjs b/embedding-timeout.integration.test.mjs new file mode 100644 index 0000000..aa70c74 --- /dev/null +++ b/embedding-timeout.integration.test.mjs @@ -0,0 +1,111 @@ +// End-to-end: a slow embedding endpoint must not hold the recall hot path open +// Run: node embedding-timeout.integration.test.mjs +// +// generateEmbedding had no timeout. Because hybrid recall awaits it, one slow +// upstream call held the whole request open for as long as the network took. +// +// Measured on a 14-day recall_log (2404 calls, 2026-09-01): +// +// query_path=sync n=844 slow(>=3s)=0 avg 9ms +// query_path=strict n=144 slow(>=3s)=0 avg 60ms +// query_path=hybrid n=1416 slow(>=3s)=282 avg 2527ms +// +// Every slow call was on hybrid — the only path that embeds. The hybrid +// distribution has a cliff with nothing in it: p80 = 2290ms, p85 = 10695ms. +// That plateau is an upstream stall, not our work getting slower. +// +// The waiting bought nothing. FTS runs in the same Promise.all and is +// synchronous, so its rows are already in hand; the request just sits on the +// network. Worse, the hook that issued most of these aborts at 1500ms, so the +// server was spending 11 seconds producing a result nobody was still waiting for. +// +// The timeout is tested against generateEmbedding directly. Going through +// recallMemoriesHybrid would not discriminate on a machine without the +// sqlite-vec extension (CI): that path early-bails to FTS before it ever +// embeds, so it would pass whether or not the timeout exists. + +import { initMemory, generateEmbedding, recallMemoriesHybrid, storeMemory, closeMemory } from './index.mjs' +import http from 'node:http' + +let pass = 0, fail = 0 +const ok = (name, cond, extra = '') => { + if (cond) { pass++; console.log(`✓ ${name}`) } + else { fail++; console.log(`✗ ${name}${extra ? ' — ' + extra : ''}`) } +} + +const DIM = 1024 +const STALL_MS = 30_000 +const TIMEOUT_MS = 600 + +let mode = 'stall' +let calls = 0 +const server = http.createServer((req, res) => { + calls++ + const answer = () => { + if (res.writableEnded || res.destroyed) return + res.writeHead(200, { 'Content-Type': 'application/json' }) + res.end(JSON.stringify({ data: [{ embedding: new Array(DIM).fill(0.001) }] })) + } + if (mode === 'fast') answer() + else setTimeout(answer, STALL_MS).unref() +}) +await new Promise(r => server.listen(0, '127.0.0.1', r)) + +process.env.EMBEDDING_API_BASE_URL = `http://127.0.0.1:${server.address().port}` +process.env.EMBEDDING_API_KEY = 'test-key' +process.env.EMBEDDING_DIMENSION = String(DIM) +process.env.EMBEDDING_TIMEOUT_MS = String(TIMEOUT_MS) + +initMemory() + +// ── the fix itself ──────────────────────────────────────────────────────── +mode = 'stall' +let t0 = Date.now() +const stalledResult = await generateEmbedding('a query whose embedding never arrives') +let elapsed = Date.now() - t0 + +ok('the stalling endpoint was actually reached (fixture is wired up)', calls > 0, `calls=${calls}`) +ok('a stalled embedding gives up on schedule instead of waiting out the network', + elapsed < TIMEOUT_MS + 1500, `took ${elapsed}ms, budget ${TIMEOUT_MS}ms, stall ${STALL_MS}ms`) +ok('a timed-out embedding returns null rather than throwing', + stalledResult === null, `got ${stalledResult === null ? 'null' : typeof stalledResult}`) + +// ── the timeout must not eat healthy calls ──────────────────────────────── +mode = 'fast' +t0 = Date.now() +const goodResult = await generateEmbedding('a query whose embedding arrives promptly') +elapsed = Date.now() - t0 + +ok('a healthy embedding still comes back', + Array.isArray(goodResult) && goodResult.length === DIM, + `got ${Array.isArray(goodResult) ? goodResult.length + ' dims' : goodResult}`) +ok('a healthy embedding is not delayed by the timeout machinery', + elapsed < TIMEOUT_MS, `took ${elapsed}ms`) + +// ── degradation stays visible ───────────────────────────────────────────── +// Silent degradation is the failure mode this whole change is about: fast and +// wrong-looking-like-right is worse than slow. Only assertable where the vec +// extension is present, since otherwise hybrid never reaches the embed. +storeMemory({ + content: 'The recall hot path degrades to full-text search when the embedding API stalls.', + summary: 'embedding timeout degradation fixture', + importance: 6, +}) +mode = 'stall' +const rows = await recallMemoriesHybrid({ query: 'embedding stalls degrade full-text', limit: 5 }) +ok('recall still returns rows — it degrades, it does not fail', + Array.isArray(rows) && rows.length > 0, `got ${rows?.length} rows`) + +if (rows?._degradeReason === 'vec-extension-not-loaded') { + console.log('~ skipped: degradation-reason assertion needs the sqlite-vec extension (absent here)') +} else { + ok('a timeout is recorded as its own degradation reason, not as a normal hybrid call', + rows?._degradeReason === 'embedding-timeout', + `_degradeReason=${rows?._degradeReason}`) +} + +server.close() +closeMemory() + +console.log(`\n${fail ? 'FAIL' : 'PASS'}: ${pass} passed / ${fail} failed`) +process.exit(fail ? 1 : 0) diff --git a/index.mjs b/index.mjs index c2773e5..afac335 100644 --- a/index.mjs +++ b/index.mjs @@ -622,10 +622,41 @@ export function initMemory() { // ── Embedding (Optional) ──────────────────────────────────── +// How long a single embedding call may hold a caller before we give up on it. +// +// Chosen from the hybrid latency distribution over a 14-day recall log +// (1416 calls, 2026-09-01), which is bimodal with an empty middle: +// +// p50 501ms p70 919ms p80 2290ms | p85 10695ms p90 10734ms +// +// Nothing lives between ~3s and ~10s. A 2.5s bound therefore cuts the entire +// upstream-stall cluster (282 of the 286 calls it touches) while costing one +// legitimately slow embed. Tightening to 1s would start eating real ones (84 +// more) and buys nothing — the stall cluster is already gone by then. +// +// Giving up is cheap here. FTS runs in the same Promise.all and is synchronous, +// so hybrid already holds its rows; losing the vector leg costs ranking quality +// on that one call, not the answer itself. +// Read per call, not at module load. Capturing env at import time makes the +// knob untunable by anything that configures itself after the import — which is +// every embedder of this library, and every test. Same trap as the DB path. +const embeddingTimeoutMs = () => { + const n = parseInt(process.env.EMBEDDING_TIMEOUT_MS || '', 10) + return Number.isFinite(n) && n > 0 ? n : 2500 +} + +/** Lets the hot path tell "upstream was slow" apart from "upstream was broken". */ +const EMBED_TIMEOUT = Symbol('embedding-timeout') + /** - * Generate embedding vector (OpenAI-compatible API) + * Generate embedding vector (OpenAI-compatible API). + * + * Returns null on any failure — every caller guards on falsy and degrades to + * full-text search. Pass `{ signalTimeout: true }` to get EMBED_TIMEOUT back + * instead of null specifically when the deadline was hit, so a caller that + * cares can record *why* it degraded rather than reporting a normal result. */ -async function generateEmbedding(text) { +export async function generateEmbedding(text, { signalTimeout = false } = {}) { if (!_embeddingConfig) return null try { const res = await fetch(`${_embeddingConfig.baseUrl}/embeddings`, { @@ -640,12 +671,17 @@ async function generateEmbedding(text) { dimensions: _embeddingConfig.dimension, encoding_format: 'float', }), + signal: AbortSignal.timeout(embeddingTimeoutMs()), }) const data = await res.json() return data?.data?.[0]?.embedding || null } catch (e) { - log(`Embedding failed: ${e.message}`) - return null + // A stalling upstream is the common case and should not read as a broken one. + const timedOut = e?.name === 'TimeoutError' || e?.name === 'AbortError' + log(timedOut + ? `Embedding timed out after ${embeddingTimeoutMs()}ms — degrading to FTS for this call` + : `Embedding failed: ${e.message}`) + return timedOut && signalTimeout ? EMBED_TIMEOUT : null } } @@ -2119,8 +2155,8 @@ export async function recallMemoriesHybrid(opts = {}) { // Parallel: vector query (get embedding) + FTS query // _internal=true so the FTS path doesn't also surface random records (hybrid surfaces once at the end) - const [queryEmbedding, ftsRows] = await Promise.all([ - generateEmbedding(queryText), + const [rawEmbedding, ftsRows] = await Promise.all([ + generateEmbedding(queryText, { signalTimeout: true }), Promise.resolve(recallMemories({ ...opts, limit: candidateLimit, @@ -2130,6 +2166,13 @@ export async function recallMemoriesHybrid(opts = {}) { })), ]) + // A timed-out embedding is a degradation, not a normal hybrid call. It gets + // the same _degradeReason the early-bail branch sets, so a caller inspecting + // the result sees one consistent story instead of a silently vector-less + // "hybrid" answer. Silent degradation is the failure this guards against. + const embedTimedOut = rawEmbedding === EMBED_TIMEOUT + const queryEmbedding = embedTimedOut ? null : rawEmbedding + // Vector path: KNN top N let vecRows = [] if (queryEmbedding) { @@ -2300,7 +2343,14 @@ export async function recallMemoriesHybrid(opts = {}) { effectiveLimit: limit, }) if (ownsTrace) persistRecallTrace(trace, result.map(row => row.rowid)) - return attachRecallTrace(result, trace) + const out = attachRecallTrace(result, trace) + if (embedTimedOut && Array.isArray(out)) { + // Non-enumerable, matching the early-bail branch: invisible to + // JSON.stringify / spread, readable by callers that ask. + Object.defineProperty(out, '_degradedTo', { value: 'fts-only', enumerable: false }) + Object.defineProperty(out, '_degradeReason', { value: 'embedding-timeout', enumerable: false }) + } + return out } // ── Conversation History Retrieval ──────────────────────────