diff --git a/docs-site/src/content/docs/ko/reference/configuration/routing.md b/docs-site/src/content/docs/ko/reference/configuration/routing.md index d19dce2f092..fed5f09dbfc 100644 --- a/docs-site/src/content/docs/ko/reference/configuration/routing.md +++ b/docs-site/src/content/docs/ko/reference/configuration/routing.md @@ -121,6 +121,27 @@ CLI: `ocx route policy list`, `ocx route policy show `, `ocx route policy dr CLI: `ocx logs explain `, `ocx logs rebuild-index`, `ocx logs index-status`. +### 인덱스 검사와 복구 + +기존 기록 인덱스를 처음 열면 읽기 전용 워커에서 무결성을 검사합니다. +기록 조회는 이 초기 검사를 기다리며, 프록시의 요청 처리 스레드를 막지 않습니다. +동기식 라우팅 조회는 검사 중에 busy를 반환하므로 라우팅 프로필의 +`unknownEvidence.health` 정책이 적용됩니다. 작은 인덱스를 인라인으로 재구축한 경우에는 +성공 직후 사용할 수 있으며, 워커에서 재구축한 인덱스는 게시 전에 검사를 마칩니다. + +검사나 재구축에 성공한 뒤 최소 5분이 지나면 다음 조회가 백그라운드 무결성 검사 하나를 +시작합니다. 이미 검증된 인덱스는 검사 중에도 조회할 수 있습니다. 일반 갱신은 스키마, +원본 파일 식별자와 바이트 오프셋을 확인하지만 전체 동기식 검사를 반복하지 않으며, +조회가 없는 동안에는 타이머를 실행하지 않습니다. 데이터베이스 잠금이나 워커 실행 실패 +같은 일시적인 검사 오류는 인덱스를 삭제하지 않고, 30초가 지난 뒤의 조회에서 다시 시도합니다. +초기 검증을 마치지 못한 인덱스는 그동안 사용할 수 없습니다. + +손상이 탐지되면 `usage.jsonl`에서 자동으로 재구축하며, 영향을 받은 비동기 기록·분석 +조회는 복구 후 한 번 재시도합니다. 인덱스를 닫거나 재구축할 때에는 이전 검사 결과를 +폐기하고 검사 워커가 파일을 해제한 뒤 인덱스를 교체합니다. 검사와 복구는 원본 기록을 +다시 쓰지 않습니다. 초기 검사에는 인덱스 크기에 비례하는 시간이 걸리며, +이후 백그라운드 검사는 인덱스를 사용하는 동안에만 실행됩니다. + ## 마이그레이션 `routingProfiles`는 선택적 추가 설정입니다. 기존 설정 파일과 이전 `usage.jsonl` 행은 그대로 읽힙니다. 인덱스는 일회용이며 삭제 시 다음 쿼리에서 `usage.jsonl`로 자동 재구축됩니다. 자동 튜닝은 없습니다. diff --git a/docs-site/src/content/docs/reference/configuration/routing.md b/docs-site/src/content/docs/reference/configuration/routing.md index e518b009789..63a3a0eae1f 100644 --- a/docs-site/src/content/docs/reference/configuration/routing.md +++ b/docs-site/src/content/docs/reference/configuration/routing.md @@ -401,6 +401,29 @@ CLI: `ocx logs history`, `ocx logs get `, `ocx logs explain `, `ocx logs rebuild-index`, `ocx logs index-status`, `ocx route policy list | show | dry-run | evaluate`. +### Index validation and recovery + +An existing history index is checked in a read-only worker when first opened. +History queries wait for that initial check without blocking the proxy's serving +thread. Synchronous routing reads report busy during validation, so routing +profiles apply their `unknownEvidence.health` policy. A successful small inline +rebuild is usable immediately; a worker rebuild is checked before publication. + +After a successful check or rebuild, the next read at least five minutes later +starts one background integrity check. Reads from the verified index continue +during that check. Normal refreshes retain schema, source-identity and offset +validation without a full synchronous scan, and an idle index starts no timer. +Temporary check failures, such as a busy database or unavailable worker, leave +the index intact and retry on a subsequent read after a 30-second backoff. +An index that has not completed initial validation remains unavailable meanwhile. + +Detected corruption triggers automatic reconstruction from `usage.jsonl`, with +one retry for an affected asynchronous history or analytics read. Closing or +rebuilding the index discards old check results and waits for the scanner to +release the file before replacing it. Validation and recovery never rewrite the +canonical ledger. The initial check still takes time proportional to index size; +later background checks run only when the index is used. + ## Migration `routingProfiles` is optional and additive: existing config files load diff --git a/scripts/test-layout/layout.json b/scripts/test-layout/layout.json index 551e1fa899a..6f2ce97bc1a 100644 --- a/scripts/test-layout/layout.json +++ b/scripts/test-layout/layout.json @@ -1495,7 +1495,7 @@ "repo-hygiene.test.ts": "ci-workflows", "request-decompress.test.ts": "usage", "request-evidence.test.ts": "usage", - "request-history-index.test.ts": "usage", + "request-history-index.test.ts": "usage", "request-history-integrity.test.ts": "usage", "request-log-attempt-identity.test.ts": "usage", "request-log-conversation.test.ts": "usage", "request-log-estimate-cap.test.ts": "usage", diff --git a/src/routing/analytics.ts b/src/routing/analytics.ts index ab919d88433..220a65e70f5 100644 --- a/src/routing/analytics.ts +++ b/src/routing/analytics.ts @@ -13,7 +13,7 @@ import { normalizePersistedUsageRow, type PersistedUsageEntry } from "../usage/log"; import { computeEntryCost } from "../usage/summary"; -import { openRequestHistoryIndex, requestHistoryDb } from "./history/indexer"; +import { withRequestHistoryRead } from "./history/indexer"; export const ANALYTICS_MAX_ROWS = 50_000; /** Default row cap for the management API (full cap remains available via `limit`). */ @@ -168,8 +168,6 @@ export async function computeRoutingAnalytics( filters: RoutingAnalyticsFilters, options: { maxRows?: number } = {}, ): Promise { - await openRequestHistoryIndex(); - const handle = requestHistoryDb(); const maxRows = Math.min( Math.max(1, Math.trunc(options.maxRows ?? ANALYTICS_MAX_ROWS)), ANALYTICS_MAX_ROWS, @@ -189,7 +187,7 @@ export async function computeRoutingAnalytics( if (filters.to !== undefined) add("timestamp <= ?", filters.to); const whereSql = where.length > 0 ? ` WHERE ${where.join(" AND ")}` : ""; - const rows = handle.query( + const rows = await withRequestHistoryRead(handle => handle.query( `SELECT provider, model, api_key_id AS apiKeyId, profile_id AS profileId, profile_revision AS profileRevision, status, duration_ms AS durationMs, first_output_ms AS firstOutputMs, @@ -197,7 +195,7 @@ export async function computeRoutingAnalytics( usage_status AS usageStatus, usage_json AS usageJson, attempt_count AS attemptCount, fallback, row_json AS rowJson FROM requests${whereSql} ORDER BY timestamp DESC LIMIT ?`, - ).all(...values, maxRows + 1) as ScannedRow[]; + ).all(...values, maxRows + 1) as ScannedRow[]); const scanned = rows.slice(0, maxRows); const historyTruncated = rows.length > maxRows; diff --git a/src/routing/health.ts b/src/routing/health.ts index ceab2e1b9a1..af4b20f5e42 100644 --- a/src/routing/health.ts +++ b/src/routing/health.ts @@ -17,7 +17,7 @@ */ import type { OcxConfig } from "../types"; -import { openRequestHistoryIndexSync, requestHistoryDb } from "./history/indexer"; +import { openRequestHistoryIndexSync, reportRequestHistoryCorruption, requestHistoryDb } from "./history/indexer"; import { OPENAI_CODEX_PROVIDER_ID } from "../providers/openai-tiers"; import { getCodexAccountCooldownUntil, @@ -251,9 +251,10 @@ function computeHistoricalHealthEvidence( input: Pick, now: number, ): HistoricalHealthEvidence { + let handle: ReturnType | undefined; try { openRequestHistoryIndexSync(); - const handle = requestHistoryDb(); + handle = requestHistoryDb(); const where: string[] = ["provider = ?", "model = ?", "timestamp >= ?"]; const values: Array = [input.provider, input.model, now - HEALTH_WINDOW_MS]; if (input.accountRef) { @@ -341,7 +342,8 @@ function computeHistoricalHealthEvidence( out.recencyWeight = decayWeight(samples[0]!.timestamp, now); } return out; - } catch { + } catch (error) { + if (handle) reportRequestHistoryCorruption(error, handle); /* index unreadable: evidence stays unknown */ return {}; } diff --git a/src/routing/history/build-file.ts b/src/routing/history/build-file.ts index 772697e990e..de443b549e2 100644 --- a/src/routing/history/build-file.ts +++ b/src/routing/history/build-file.ts @@ -79,6 +79,12 @@ export function buildIndexFile(buildPath: string, reason: string, revision: Usag expected: revision, endOffset: Number(revision.size), }); + // Validate before publication while still off the serving thread. The + // published handle can then be trusted until its periodic worker check. + const check = build.query("PRAGMA quick_check").get() as { quick_check?: string } | undefined; + if (check?.quick_check !== "ok") { + throw Object.assign(new Error("rebuilt history index failed integrity check"), { code: "SQLITE_CORRUPT" }); + } // The serving thread opens the published file in WAL mode; switching here // keeps that first open from rewriting the database header. build.exec("PRAGMA journal_mode = WAL"); diff --git a/src/routing/history/indexer.ts b/src/routing/history/indexer.ts index 342e98fab4b..68413390ab4 100644 --- a/src/routing/history/indexer.ts +++ b/src/routing/history/indexer.ts @@ -3,7 +3,7 @@ * * `usage.jsonl` stays canonical; this module maintains a rebuildable SQLite * projection (ADR-1, ADR-8). On every open/query it verifies schema version, - * file identity, integrity, and byte offset, then appends whatever complete + * file identity and byte offset, then appends whatever complete * JSONL rows arrived since the last index. Missing/corrupt/stale index or a * replaced/truncated source triggers an automatic full rebuild; canonical * history is never touched. @@ -12,6 +12,8 @@ * runs on a worker thread (#6990): the worker writes a private build file and * this thread swaps it in once complete. Async readers wait for it; the * routing-time sync entry never waits and throws `RequestHistoryIndexBusyError`. + * Full integrity scans run on that worker at open and periodically while in + * use, never synchronously on the serving thread (#7966). */ import { Database } from "bun:sqlite"; @@ -48,6 +50,8 @@ import { } from "./ingest"; import { buildFilePath, removeBuildFiles } from "./build-file"; import { RebuildWorkerJob } from "./rebuild-job"; +import { RequestHistoryIntegrityMonitor, type RequestHistoryIntegrityOptions } from "./integrity"; +import { isHistoryIndexCorruption } from "./sqlite-errors"; export { REQUEST_HISTORY_INSERT_BATCH, @@ -138,9 +142,15 @@ class RebuildHandedOff { constructor(readonly rebuild: WorkerRebuild) {} } +/** An initial integrity check, or a scanner draining before index replacement. */ +class IntegrityHandedOff { + constructor(readonly promise: Promise) {} +} + let db: Database | null = null; let dbPath = ""; let openPromise: Promise | null = null; +let manualRebuild: Promise | null = null; let workerRebuild: WorkerRebuild | null = null; let workerFailure: { at: number; error: unknown } | null = null; let workerRebuildMinBytes = REQUEST_HISTORY_WORKER_REBUILD_MIN_BYTES; @@ -148,6 +158,33 @@ let maxAsyncRefreshBuilds = MAX_ASYNC_REFRESH_BUILDS; let buildSequence = 0; // Bumped by closeRequestHistoryIndex, so a rebuild finishing after a close is discarded. let indexLifetime = 0; +let integrity = new RequestHistoryIntegrityMonitor(); +let integrityDrain: Promise | null = null; +let corruptHandle: Database | null = null; +let validatedBuildPath: string | null = null; + +/** Test seam: replace integrity scheduling without leaving a scanner on an old file. */ +export function setRequestHistoryIntegrityOptionsForTests(options?: RequestHistoryIntegrityOptions): void { + closeRequestHistoryIndex(); + integrity = new RequestHistoryIntegrityMonitor(options); +} + +function stopIntegrityScan(): Promise | null { + const pending = integrity.quiesce(); + if (pending && !integrityDrain) { + const drained = pending.finally(() => { + if (integrityDrain === drained) integrityDrain = null; + }); + integrityDrain = drained; + } + return integrityDrain; +} + +/** Never delete/rename a database that a cancelled scanner may still hold on Windows. */ +function prepareIndexReplacement(): void { + const pending = stopIntegrityScan(); + if (pending) throw new IntegrityHandedOff(pending); +} /** Test seam: move the worker threshold; `undefined` restores the default. */ export function setRequestHistoryWorkerRebuildMinBytesForTests(bytes: number | undefined): void { @@ -210,15 +247,6 @@ export function sourceIdentityMatches(dbHandle: Database, revision: UsageLogRevi && storedBirthtimeMs === Number(revision.birthtimeMs); } -function isHealthy(dbHandle: Database): boolean { - try { - const row = dbHandle.query("PRAGMA quick_check").get() as { quick_check?: string } | undefined; - return row?.quick_check === "ok"; - } catch { - return false; - } -} - /** Remove the index file and its WAL side files. */ function removeIndexFiles(path: string): void { // Windows: a partially-opened handle from a failed `new Database` can hold @@ -238,6 +266,7 @@ function removeIndexFiles(path: string): void { } function destroyAndRecreate(path: string, reason: string): Database { + prepareIndexReplacement(); if (db) { try { db.close(); } catch { /* already closed */ } db = null; @@ -249,10 +278,13 @@ function destroyAndRecreate(path: string, reason: string): Database { resetAndCreateSchema(fresh); setMeta(fresh, HISTORY_META_KEYS.lastError, reason); db = fresh; + corruptHandle = null; + validatedBuildPath = null; return fresh; } function openIndexDb(): Database { + if (integrityDrain) throw new IntegrityHandedOff(integrityDrain); const path = indexDbPath(); if (db) return db; let handle: Database | undefined; @@ -270,45 +302,64 @@ function openIndexDb(): Database { setMeta(handle, HISTORY_META_KEYS.builtAtMs, Date.now()); setMeta(handle, HISTORY_META_KEYS.lastError, "created"); } - } catch { + } catch (error) { // A partially-opened handle on a corrupt file can hold the OS lock on // Windows; close it before the destructive recreate. if (handle) { try { handle.close(); } catch { /* already unusable */ } } + if (!isHistoryIndexCorruption(error)) throw error; handle = destroyAndRecreate(path, "unreadable database recreated"); } dbPath = path; db = handle; + if (validatedBuildPath === path) { + integrity.acceptRebuilt(handle, path); + validatedBuildPath = null; + } return handle; } function ensureSchemaAndIdentity(dbHandle: Database): "ready" | "rebuilt" { try { + if (corruptHandle === dbHandle) { + destroyAndRecreate(dbPath, "integrity check failed; index rebuilt"); + return "rebuilt"; + } const storedVersion = metaValue(dbHandle, HISTORY_META_KEYS.schemaVersion); if (storedVersion !== String(HISTORY_SCHEMA_VERSION)) { destroyAndRecreate(dbPath, `schema version ${storedVersion ?? "missing"} -> ${HISTORY_SCHEMA_VERSION}`); return "rebuilt"; } - if (!isHealthy(dbHandle)) { - destroyAndRecreate(dbPath, "integrity check failed; index rebuilt"); - return "rebuilt"; - } const revision = sourceIdentity(); if (!sourceIdentityMatches(dbHandle, revision)) { destroyAndRecreate(dbPath, "source identity changed; index rebuilt"); return "rebuilt"; } + const check = integrity.inspect(dbHandle, dbPath); + if (check.state === "pending") throw new IntegrityHandedOff(check.promise); + if (check.state === "unavailable") { + throw new RequestHistoryIndexBusyError("request-history integrity check unavailable"); + } + if (check.state === "corrupt") { + corruptHandle = dbHandle; + destroyAndRecreate(dbPath, "integrity check failed; index rebuilt"); + return "rebuilt"; + } return "ready"; - } catch { + } catch (error) { + if (!isHistoryIndexCorruption(error)) throw error; // A file that opens but is not actually SQLite (or is mid-corruption) // throws on the first statement; treat it as corrupt and rebuild. + corruptHandle = dbHandle; + integrity.markCorrupt(dbHandle); destroyAndRecreate(dbPath, "index unreadable; rebuilt"); return "rebuilt"; } } function fullRebuild(dbHandle: Database, reason: string): void { + prepareIndexReplacement(); resetAndCreateSchema(dbHandle); setMeta(dbHandle, HISTORY_META_KEYS.lastError, reason); const path = usageLogPath(); @@ -319,6 +370,8 @@ function fullRebuild(dbHandle: Database, reason: string): void { setMeta(dbHandle, HISTORY_META_KEYS.indexedOffset, 0); setMeta(dbHandle, HISTORY_META_KEYS.indexedRows, 0); setMeta(dbHandle, HISTORY_META_KEYS.builtAtMs, Date.now()); + integrity.acceptRebuilt(dbHandle, dbPath); + corruptHandle = null; return; } const inserted = ingestSourceTail(dbHandle, path, 0); @@ -326,6 +379,8 @@ function fullRebuild(dbHandle: Database, reason: string): void { setMeta(dbHandle, HISTORY_META_KEYS.indexedRows, inserted); setMeta(dbHandle, HISTORY_META_KEYS.indexedOffset, Math.max(current.indexedOffset, 0)); setMeta(dbHandle, HISTORY_META_KEYS.builtAtMs, Date.now()); + integrity.acceptRebuilt(dbHandle, dbPath); + corruptHandle = null; } /** @@ -372,12 +427,15 @@ function startWorkerRebuild(reason: string, revision: UsageLogRevision): WorkerR /** Swap a complete worker build in for the current index file. */ function installBuild(buildPath: string, indexPath: string): void { + prepareIndexReplacement(); if (db) { try { db.close(); } catch { /* already closed */ } db = null; } removeIndexFiles(indexPath); renameSync(buildPath, indexPath); + corruptHandle = null; + validatedBuildPath = indexPath; } /** @@ -389,6 +447,7 @@ type RefreshCaller = "routing" | "reader"; /** Full rebuild, on the worker when the ledger is large enough to stall the event loop. */ function rebuildFromLedger(handle: Database, reason: string, caller: RefreshCaller): void { + prepareIndexReplacement(); const revision = sourceIdentity(); if (revision !== null && Number(revision.size) >= workerRebuildMinBytes) { if (workerCoolingDown()) { @@ -405,7 +464,7 @@ function rebuildFromLedger(handle: Database, reason: string, caller: RefreshCall fullRebuild(handle, reason); } -function refreshLockedSync(caller: RefreshCaller): RequestHistoryIndexMeta { +function refreshOnceLockedSync(caller: RefreshCaller): RequestHistoryIndexMeta { if (workerRebuild) throw new RebuildHandedOff(workerRebuild); openIndexDb(); const state = ensureSchemaAndIdentity(db!); @@ -436,27 +495,55 @@ function refreshLockedSync(caller: RefreshCaller): RequestHistoryIndexMeta { return metaFor(handle); } +function refreshLockedSync(caller: RefreshCaller): RequestHistoryIndexMeta { + try { + return refreshOnceLockedSync(caller); + } catch (error) { + // Metadata reads and incremental writes can encounter damage even between + // scheduled checks. Operational failures (busy, locked, I/O, full) propagate. + if (!isHistoryIndexCorruption(error)) throw error; + if (db) { + corruptHandle = db; + integrity.markCorrupt(db); + } + const handle = destroyAndRecreate(dbPath, "SQLite corruption; index rebuilt"); + rebuildFromLedger(handle, "SQLite corruption; index rebuilt", caller); + return metaFor(handle); + } +} + /** * Synchronous refresh for routing-time evidence reads (RI-06+). Never waits * for a worker rebuild: while one runs (this call may start it), throws * `RequestHistoryIndexBusyError`, which health scoring reads as unknown evidence. */ export function openRequestHistoryIndexSync(): RequestHistoryIndexMeta { + if (manualRebuild) throw new RequestHistoryIndexBusyError(); try { return refreshLockedSync("routing"); } catch (error) { - if (error instanceof RebuildHandedOff) throw new RequestHistoryIndexBusyError(); + if (error instanceof RebuildHandedOff || error instanceof IntegrityHandedOff) throw new RequestHistoryIndexBusyError(); throw error; } } -async function refreshWaitingForWorker(): Promise { +async function refreshWaitingForWorker(fromManualRebuild = false): Promise { const lifetime = indexLifetime; for (let builds = 0; ; ) { + if (manualRebuild && !fromManualRebuild) { + await manualRebuild; + if (lifetime !== indexLifetime) throw new RequestHistoryIndexClosedError(); + continue; + } let handedOff: RebuildHandedOff; try { return refreshLockedSync("reader"); } catch (error) { + if (error instanceof IntegrityHandedOff) { + await error.promise; + if (lifetime !== indexLifetime) throw new RequestHistoryIndexClosedError(); + continue; + } if (!(error instanceof RebuildHandedOff)) throw error; handedOff = error; } @@ -480,15 +567,19 @@ async function refreshWaitingForWorker(): Promise { */ export function openRequestHistoryIndex(): Promise { if (!openPromise) { - openPromise = refreshWaitingForWorker().finally(() => { - openPromise = null; + const pending = refreshWaitingForWorker().finally(() => { + if (openPromise === pending) openPromise = null; }); + openPromise = pending; } return openPromise; } export function closeRequestHistoryIndex(): void { indexLifetime += 1; + stopIntegrityScan(); + corruptHandle = null; + validatedBuildPath = null; const rebuild = workerRebuild; workerRebuild = null; workerFailure = null; @@ -499,21 +590,36 @@ export function closeRequestHistoryIndex(): void { db = null; } openPromise = null; + manualRebuild = null; } /** Force a full rebuild from the canonical ledger (CLI / tests). */ -export async function rebuildRequestHistoryIndex(): Promise { +export function rebuildRequestHistoryIndex(): Promise { + if (!manualRebuild) { + const pending = rebuildManually(indexLifetime).finally(() => { + if (manualRebuild === pending) manualRebuild = null; + }); + manualRebuild = pending; + } + return manualRebuild; +} + +async function rebuildManually(lifetime: number): Promise { + const draining = stopIntegrityScan(); + if (draining) await draining; + if (lifetime !== indexLifetime) throw new RequestHistoryIndexClosedError(); while (workerRebuild) await workerRebuild.promise.catch(() => undefined); + if (lifetime !== indexLifetime) throw new RequestHistoryIndexClosedError(); const handle = openIndexDb(); const revision = sourceIdentity(); if (revision !== null && Number(revision.size) >= workerRebuildMinBytes) { workerFailure = null; const rebuild = startWorkerRebuild("manual rebuild requested", revision); if (rebuild) { - const lifetime = indexLifetime; try { await rebuild.promise; - return openRequestHistoryIndex(); + if (lifetime !== indexLifetime) throw new RequestHistoryIndexClosedError(); + return refreshWaitingForWorker(true); } catch (error) { // A close is final; any other worker failure falls back to the inline rebuild below. if (lifetime !== indexLifetime || error instanceof RequestHistoryIndexClosedError) throw error; @@ -575,6 +681,29 @@ function requireDb(): Database { return handle; } +/** Invalidate only the live generation, including errors from routing's synchronous reads. */ +export function reportRequestHistoryCorruption(error: unknown, handle: Database): boolean { + if (!isHistoryIndexCorruption(error)) return false; + if (db === handle) { + corruptHandle = handle; + integrity.markCorrupt(handle); + } + return true; +} + +/** Read-only operations may retry once after repair; ordinary SQLite failures propagate. */ +export async function withRequestHistoryRead(read: (handle: Database, meta: RequestHistoryIndexMeta) => T): Promise { + for (let attempt = 0; ; attempt++) { + const meta = await openRequestHistoryIndex(); + const handle = requireDb(); + try { + return read(handle, meta); + } catch (error) { + if (!reportRequestHistoryCorruption(error, handle) || attempt > 0) throw error; + } + } +} + function hydrateRow(row: HistoryQueryRow | undefined): PersistedUsageEntry | null { if (!row) return null; try { @@ -593,7 +722,6 @@ export async function queryRequestHistory( rawCursor: string | null | undefined, pageSize: number | undefined, ): Promise { - const meta = await openRequestHistoryIndex(); const cursor = decodeHistoryCursor(rawCursor); if (rawCursor !== null && rawCursor !== undefined && cursor === null) { throw new InvalidCursorError(); @@ -602,8 +730,9 @@ export async function queryRequestHistory( Math.max(1, Math.trunc(pageSize ?? REQUEST_HISTORY_DEFAULT_PAGE_SIZE)), REQUEST_HISTORY_MAX_PAGE_SIZE, ); - const handle = requireDb(); - const { rows, fetched } = queryRows(handle, filters, cursor, limit); + const { rows, fetched, meta } = await withRequestHistoryRead((handle, meta) => ({ + ...queryRows(handle, filters, cursor, limit), meta, + })); const hasMore = fetched > limit; const pageRows = rows.slice(0, limit); const entries: PersistedUsageEntry[] = []; @@ -620,11 +749,9 @@ export async function queryRequestHistory( } export async function requestHistoryRowById(requestId: string): Promise { - await openRequestHistoryIndex(); - const handle = requireDb(); - const row = handle.query("SELECT row_json FROM requests WHERE request_id = ?").get(requestId) as + const row = await withRequestHistoryRead(handle => handle.query("SELECT row_json FROM requests WHERE request_id = ?").get(requestId) as | { row_json: string } - | undefined; + | undefined); return hydrateRow(row); } diff --git a/src/routing/history/ingest.ts b/src/routing/history/ingest.ts index 16a98d726b9..429fe4dc974 100644 --- a/src/routing/history/ingest.ts +++ b/src/routing/history/ingest.ts @@ -25,7 +25,7 @@ export const REQUEST_HISTORY_MAX_RECORD_BYTES = 1024 * 1024; // One small observation per live database handle, never retained ledger bytes. An // unterminated tail cannot advance indexedOffset, but need not be reread until its -// exact file revision changes. The indexer's schema/identity/quick_check gates still run. +// exact file revision changes. Schema/identity gates and lifecycle integrity checks still apply. const tailObservations = new WeakMap; + +export interface RequestHistoryIntegrityOptions { + createJob?: () => IntegrityJob; + now?: () => number; + intervalMs?: number; + failureCooldownMs?: number; +} + +export type RequestHistoryIntegrityState = + | { state: "ready" } + | { state: "corrupt" } + | { state: "unavailable"; error: unknown } + // Never rejects, including on cancellation or check failure. Completion + // proves the scanner exited; inspect again to obtain its verdict or error. + | { state: "pending"; promise: Promise }; + +interface Generation { + handle: object; + path: string; + verified: boolean; + corrupt: boolean; + nextCheckAt: number; + failure: { error: unknown } | null; +} + +interface ActiveCheck { + generation: Generation; + cancelled: boolean; + cancel: () => void; + promise: Promise; +} + +type CheckOutcome = + | { kind: "checked"; healthy: boolean } + | { kind: "failed"; error: unknown } + | { kind: "cancelled" }; + +export class RequestHistoryIntegrityMonitor { + private readonly createJob: () => IntegrityJob; + private readonly now: () => number; + private readonly intervalMs: number; + private readonly failureCooldownMs: number; + private current: Generation | null = null; + private active: ActiveCheck | null = null; + + constructor(options: RequestHistoryIntegrityOptions = {}) { + this.createJob = options.createJob ?? (() => new RebuildWorkerJob()); + this.now = options.now ?? Date.now; + this.intervalMs = options.intervalMs ?? REQUEST_HISTORY_INTEGRITY_INTERVAL_MS; + this.failureCooldownMs = options.failureCooldownMs ?? REQUEST_HISTORY_INTEGRITY_FAILURE_COOLDOWN_MS; + } + + inspect(handle: object, path: string): RequestHistoryIntegrityState { + if (this.current?.handle !== handle || this.current.path !== path) { + this.quiesce(); + this.current = { handle, path, verified: false, corrupt: false, nextCheckAt: -Infinity, failure: null }; + } + const generation = this.current; + if (generation.corrupt) return { state: "corrupt" }; + if (this.active) { + if (this.active.generation === generation && !this.active.cancelled && generation.verified) { + return { state: "ready" }; + } + return { state: "pending", promise: this.active.promise }; + } + if (this.now() >= generation.nextCheckAt) { + const check = this.start(generation); + if (check && !generation.verified) return { state: "pending", promise: check.promise }; + } + if (generation.verified) return { state: "ready" }; + return { state: "unavailable", error: generation.failure?.error ?? new Error("history integrity check unavailable") }; + } + + /** A statement detected corruption; an in-flight healthy verdict cannot erase it. */ + markCorrupt(handle: object): void { + if (this.current?.handle === handle) this.current.corrupt = true; + } + + /** + * Accept a newly reconstructed projection after successful inline ingest or + * validation of a private worker build. Existing persisted databases must + * use inspect instead. The caller drains scans before rebuilding/swapping. + */ + acceptRebuilt(handle: object, path: string): void { + if (this.active) throw new Error("history integrity worker must exit before accepting a rebuilt index"); + this.current = { + handle, path, verified: true, corrupt: false, + nextCheckAt: this.now() + this.intervalMs, failure: null, + }; + } + + /** + * Invalidate and stop the current check. Null means the index can be replaced + * now; otherwise await the returned barrier before deleting or renaming it. + * The barrier survives reset/reopen and resolves only after actual worker + * exit, including Windows' OS-thread settling, not the bounded disposal wait. + */ + quiesce(): Promise | null { + this.current = null; + this.active?.cancel(); + return this.active?.promise ?? null; + } + + reset(): void { + this.quiesce(); + } + + private start(generation: Generation): ActiveCheck | null { + let job: IntegrityJob; + try { + job = this.createJob(); + } catch (error) { + this.recordFailure(generation, error); + return null; + } + let cancel!: () => void; + const cancelled = new Promise(resolve => { cancel = () => resolve({ kind: "cancelled" }); }); + const check: ActiveCheck = { + generation, + cancelled: false, + cancel: () => { check.cancelled = true; cancel(); }, + promise: Promise.resolve(), + }; + this.active = check; + check.promise = this.run(check, job, cancelled); + return check; + } + + private recordFailure(generation: Generation, error: unknown): void { + generation.failure = { error: error ?? new Error("history integrity check failed") }; + generation.nextCheckAt = this.now() + this.failureCooldownMs; + } + + private async run(check: ActiveCheck, job: IntegrityJob, cancelled: Promise): Promise { + const observed = Promise.resolve().then(async (): Promise => { + if (check.cancelled) return { kind: "cancelled" }; + try { + return { kind: "checked", healthy: await job.check(check.generation.path) }; + } catch (error) { + return { kind: "failed", error }; + } + }); + const outcome = await Promise.race([observed, cancelled]); + await new Promise(resolve => { + // afterExit may return at its disposal timeout, before native I/O lets + // the worker exit. Only its callback releases the file replacement gate. + void job.afterExit(resolve).catch(() => undefined); + }); + const generation = check.generation; + if (this.current === generation && !check.cancelled && !generation.corrupt) { + if (outcome.kind === "checked") { + generation.verified = outcome.healthy; + generation.corrupt = !outcome.healthy; + generation.failure = null; + generation.nextCheckAt = this.now() + this.intervalMs; + } else if (outcome.kind === "failed") { + this.recordFailure(generation, outcome.error); + } + } + if (this.active === check) this.active = null; + } +} diff --git a/src/routing/history/rebuild-job.ts b/src/routing/history/rebuild-job.ts index 18467701835..e98e2050aec 100644 --- a/src/routing/history/rebuild-job.ts +++ b/src/routing/history/rebuild-job.ts @@ -13,6 +13,7 @@ import { RequestHistoryIndexStaleError } from "./ingest"; import type { RebuildWorkerReply, RebuildWorkerRequest } from "./rebuild-protocol"; const CLOSE_TIMEOUT_MS = 5_000; +type WorkerSuccess = Exclude; function delay(ms: number): Promise { return new Promise(resolve => setTimeout(resolve, ms)); @@ -34,7 +35,7 @@ function errorFromReply(reply: Extract): export class RebuildWorkerJob { private readonly worker: Worker; - private pending: { resolve: (rows: number) => void; reject: (error: unknown) => void } | null = null; + private pending: { resolve: (reply: WorkerSuccess) => void; reject: (error: unknown) => void } | null = null; private exited = false; private exitedCleanly = false; private disposal: Promise | null = null; @@ -49,8 +50,8 @@ export class RebuildWorkerJob { this.pending = null; if (!pending) return; const reply = event.data; - if (reply.type === "built") pending.resolve(reply.rows); - else pending.reject(errorFromReply(reply)); + if (reply.type === "error") pending.reject(errorFromReply(reply)); + else pending.resolve(reply); }); this.worker.addEventListener("error", (event: Event) => { this.fail(new Error((event as ErrorEvent).message || "request-history rebuild worker failed")); @@ -68,16 +69,29 @@ export class RebuildWorkerJob { pending?.reject(error); } - /** Build the complete private file; resolves with the ingested row count. */ - build(indexPath: string, buildPath: string, reason: string, revision: UsageLogRevision): Promise { + private send(request: RebuildWorkerRequest): Promise { if (this.exited || this.disposal) return Promise.reject(new Error("request-history rebuild worker is not running")); if (this.pending) return Promise.reject(new Error("request-history rebuild worker is busy")); return new Promise((resolve, reject) => { this.pending = { resolve, reject }; - this.worker.postMessage({ type: "build", indexPath, buildPath, reason, revision } satisfies RebuildWorkerRequest); + this.worker.postMessage(request); }); } + /** Build the complete private file; resolves with the ingested row count. */ + async build(indexPath: string, buildPath: string, reason: string, revision: UsageLogRevision): Promise { + const reply = await this.send({ type: "build", indexPath, buildPath, reason, revision }); + if (reply.type !== "built") throw new Error("unexpected request-history build reply"); + return reply.rows; + } + + /** Scan a read-only connection off-loop; operational errors are not corruption. */ + async check(indexPath: string): Promise { + const reply = await this.send({ type: "check", indexPath }); + if (reply.type !== "checked") throw new Error("unexpected request-history integrity reply"); + return reply.healthy; + } + /** Stop the thread; waits a bounded time for it to exit. */ dispose(): Promise { this.disposal ??= this.shutDown(); diff --git a/src/routing/history/rebuild-protocol.ts b/src/routing/history/rebuild-protocol.ts index eb5999d29a5..d0dde97af6e 100644 --- a/src/routing/history/rebuild-protocol.ts +++ b/src/routing/history/rebuild-protocol.ts @@ -8,8 +8,9 @@ export type RebuildWorkerRequest = { buildPath: string; reason: string; revision: UsageLogRevision; -}; +} | { type: "check"; indexPath: string }; export type RebuildWorkerReply = | { type: "built"; rows: number } + | { type: "checked"; healthy: boolean } | { type: "error"; name: string; message: string }; diff --git a/src/routing/history/rebuild-worker.ts b/src/routing/history/rebuild-worker.ts index 6ee44b081d8..a636ed4d93e 100644 --- a/src/routing/history/rebuild-worker.ts +++ b/src/routing/history/rebuild-worker.ts @@ -8,12 +8,30 @@ * closes it. The serving thread then swaps the finished file in. */ +import { Database } from "bun:sqlite"; import { buildIndexFile, removeAbandonedBuilds } from "./build-file"; +import { isHistoryIndexCorruption } from "./sqlite-errors"; import type { RebuildWorkerReply, RebuildWorkerRequest } from "./rebuild-protocol"; declare const self: Worker; function handle(request: RebuildWorkerRequest): RebuildWorkerReply { + if (request.type === "check") { + let handle: Database | undefined; + try { + handle = new Database(request.indexPath, { readonly: true }); + handle.exec("PRAGMA busy_timeout = 5000"); + const row = handle.query("PRAGMA quick_check").get() as { quick_check?: string } | undefined; + return { type: "checked", healthy: row?.quick_check === "ok" }; + } catch (error) { + if (isHistoryIndexCorruption(error)) return { type: "checked", healthy: false }; + throw error; + } finally { + // Release the live index before posting a verdict: the serving thread + // may immediately replace it, including on Windows. + handle?.close(); + } + } removeAbandonedBuilds(request.indexPath); const rows = buildIndexFile(request.buildPath, request.reason, request.revision); return { type: "built", rows }; diff --git a/src/routing/history/sqlite-errors.ts b/src/routing/history/sqlite-errors.ts new file mode 100644 index 00000000000..9e8101954d8 --- /dev/null +++ b/src/routing/history/sqlite-errors.ts @@ -0,0 +1,9 @@ +/** Only structural SQLite damage justifies discarding the derived index. */ +export function isHistoryIndexCorruption(error: unknown): boolean { + if (!error || typeof error !== "object") return false; + const { code, errno } = error as { code?: unknown; errno?: unknown }; + // Bun exposes extended result codes too; the low byte is the primary code. + if (typeof errno === "number" && ((errno & 0xff) === 11 || (errno & 0xff) === 26)) return true; + return typeof code === "string" + && /^(SQLITE_CORRUPT(?:_[A-Z]+)?|SQLITE_NOTADB)$/.test(code); +} diff --git a/structure/dashboard-and-usage.md b/structure/dashboard-and-usage.md index 084f60d1157..960bbdc128c 100644 --- a/structure/dashboard-and-usage.md +++ b/structure/dashboard-and-usage.md @@ -276,12 +276,12 @@ first two is the loss signal. Provider debug formats one ring line per finalized counts and writes no second record. `GET /api/usage?failures=1` groups failed rows by a versioned fingerprint over closed vocabularies only, rebuilt through the same cooperative scanner and inheriting its bounds, so deleting a ledger row removes it from the grouping. -`usageLedgerMaxBytes` is unset by default; when set, an append that crosses it publishes the newest -whole rows byte for byte through the shared atomic writer, refuses the rename unless the source is -the exact revision that was copied, and then discards the Logs ring, the retained aggregates and the -request-history index so no surface serves rows the ledger no longer has. That index (`src/routing/history/`) rebuilds a ledger of at least `REQUEST_HISTORY_WORKER_REBUILD_MIN_BYTES` (1 MiB) on a worker thread (#6990): `rebuild-worker.ts`, driven by `rebuild-job.ts`, ingests the ledger snapshot the refresh recorded into a private `.rebuild--` file through the same `ingest.ts` the inline path uses, switches it to WAL and closes it; the serving thread then closes the old index and renames the build over it. Async readers wait for the build; the routing-time sync entry never does and throws `RequestHistoryIndexBusyError`, which health scoring reads as unknown evidence. Health scoring (`src/routing/health.ts`) counts physical sends only: a request answered locally or refused before any send is no evidence for any target, and a row's terminal status and close reason score its last physical send, so a 200 stream cut mid-flight after a failover counts against the target that dropped it (`tests/server/health-scoring.test.ts`). A close discards the build, rejects waiting readers with `RequestHistoryIndexClosedError`, and removes the build files only after the worker thread exits. For 30 s after a worker build fails (other than on a replaced ledger), async readers and manual rebuilds rebuild inline instead, while routing-time reads keep reporting busy. -Ledger revisions in `src/usage/log.ts` capture device/inode identifiers from bigint descriptor stats as exact decimal strings; history metadata, ingestion, cooperative scans and retention compare them without narrowing to Numbers, preserving distinct NTFS identifiers above 2^53. An older index containing a rounded identifier fails the identity check and rebuilds once. `src/usage/summary.ts` turns that file into the `/api/usage` shape — totals, daily zero-filled -grid, model and provider breakdowns, and `measured / reported / unreported / unsupported / estimated` counts. Each scope also aggregates end-to-end output throughput (#6309): measured output tokens and wall-clock `durationMs` are summed over attempts reporting both, exposing `throughputTokensPerSec` — a token-sum-over-duration-sum, never a mean of per-request rates. `throughputSamples` counts qualifying attempts (legacy rows without attempts contribute one); nonpositive or nonfinite tokens/timing are excluded. The Usage summary and Models/Providers tables display the rate and sample basis, or unavailable when none qualify. +`usageLedgerMaxBytes` is unset by default; when set, an append that crosses it publishes the newest whole rows byte for byte through the shared atomic writer, refuses the rename unless the source is the exact revision that was copied, and then discards the Logs ring, the retained aggregates and the request-history index so no surface serves rows the ledger no longer has. +That index (`src/routing/history/`) rebuilds a ledger of at least `REQUEST_HISTORY_WORKER_REBUILD_MIN_BYTES` (1 MiB) on a worker thread (#6990): `rebuild-worker.ts`, driven by `rebuild-job.ts`, ingests the ledger snapshot the refresh recorded into a private `.rebuild--` file through the same `ingest.ts` the inline path uses, switches it to WAL and closes it; the serving thread then closes the old index and renames the build over it. Async readers wait for the build; the routing-time sync entry never does and throws `RequestHistoryIndexBusyError`, which health scoring reads as unknown evidence. Health scoring (`src/routing/health.ts`) counts physical sends only: a request answered locally or refused before any send is no evidence for any target, and a row's terminal status and close reason score its last physical send, so a 200 stream cut mid-flight after a failover counts against the target that dropped it (`tests/server/health-scoring.test.ts`). A close discards the build, rejects waiting readers with `RequestHistoryIndexClosedError`, and removes the build files only after the worker thread exits. For 30 s after a worker build fails (other than on a replaced ledger), async readers and manual rebuilds rebuild inline instead, while routing-time reads keep reporting busy. + +`src/routing/history/integrity.ts` validates an existing persisted index on first use with a read-only worker `PRAGMA quick_check` (#7966); serving refreshes retain schema/source/offset checks without a synchronous integrity scan. Async readers await initial validation; synchronous routing reports busy/unknown meanwhile. A successful fresh inline reconstruction is immediately usable, and a private worker build is integrity-checked before publication. After validation or reconstruction, the next refresh at least five minutes later starts one background check; verified reads remain available during it, and idle indexes start no timer. Operational check failures leave the index intact and delay retry for 30 s; an unverified index remains unavailable. A corrupt verdict or `SQLITE_CORRUPT`/`SQLITE_NOTADB` invalidates the live handle and enters the existing rebuild path; async history and analytics reads retry once after recovery. Close/rebuild discards stale verdicts and drains scanners through actual thread exit before index replacement. Neither validation nor recovery rewrites canonical `usage.jsonl`. `tests/usage/request-history-integrity.test.ts` covers scan scheduling, corruption recovery and lifecycle isolation. + +Ledger revisions in `src/usage/log.ts` capture device/inode identifiers from bigint descriptor stats as exact decimal strings; history metadata, ingestion, cooperative scans and retention compare them without narrowing to Numbers, preserving distinct NTFS identifiers above 2^53. An older index containing a rounded identifier fails the identity check and rebuilds once. `src/usage/summary.ts` turns that file into the `/api/usage` shape — totals, daily zero-filled grid, model and provider breakdowns, and `measured / reported / unreported / unsupported / estimated` counts. Each scope also aggregates end-to-end output throughput (#6309): measured output tokens and wall-clock `durationMs` are summed over attempts reporting both, exposing `throughputTokensPerSec` — a token-sum-over-duration-sum, never a mean of per-request rates. `throughputSamples` counts qualifying attempts (legacy rows without attempts contribute one); nonpositive or nonfinite tokens/timing are excluded. The Usage summary and Models/Providers tables display the rate and sample basis, or unavailable when none qualify. All three throughput displays use the same finite-number guard as their tooltip; malformed or nonfinite rates are unavailable rather than formatted. The management route scans the ledger from its beginning in fixed 1 MiB chunks on a cold rebuild, then retains compact numeric aggregate state and resumes at the last verified LF for diff --git a/tests/fixtures/test-layout-expected.json b/tests/fixtures/test-layout-expected.json index a4c1df1686d..ad30a6053a2 100644 --- a/tests/fixtures/test-layout-expected.json +++ b/tests/fixtures/test-layout-expected.json @@ -1200,7 +1200,7 @@ "fixture-teardown-helper.test.ts": "ci-workflows", "replay-refusal-parity.test.ts": "server", "fixture-windows-runtime-preload.test.ts": "ci-workflows", "repo-hygiene.test.ts": "ci-workflows", "request-decompress.test.ts": "usage", - "request-evidence.test.ts": "usage", "request-history-index.test.ts": "usage", + "request-evidence.test.ts": "usage", "request-history-index.test.ts": "usage", "request-history-integrity.test.ts": "usage", "request-log-attempt-identity.test.ts": "usage", "request-log-conversation.test.ts": "usage", "request-log-estimate-cap.test.ts": "usage", "request-log-jev.test.ts": "usage", "request-log-nonstream.test.ts": "usage", "request-log-protocol-trace.test.ts": "usage", diff --git a/tests/usage/request-history-integrity.test.ts b/tests/usage/request-history-integrity.test.ts new file mode 100644 index 00000000000..3c824e918db --- /dev/null +++ b/tests/usage/request-history-integrity.test.ts @@ -0,0 +1,525 @@ +/** Regression coverage for #7966: integrity scans never run on the serving thread. */ +import { afterEach, beforeEach, describe, expect, spyOn, test } from "bun:test"; +import { Database } from "bun:sqlite"; +import { closeSync, mkdtempSync, openSync, readFileSync, renameSync, writeFileSync, writeSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { + appendUsageEntry, + resetUsageReadCacheForTests, + usageLogPath, + type PersistedUsageEntry, +} from "../../src/usage/log"; +import { + closeRequestHistoryIndex, + openRequestHistoryIndex, + openRequestHistoryIndexSync, + queryRequestHistory, + rebuildRequestHistoryIndex, + requestHistoryDb, + requestHistoryIndexStatus, + requestHistoryRowById, + RequestHistoryIndexBusyError, + RequestHistoryIndexClosedError, + setRequestHistoryIntegrityOptionsForTests, + setRequestHistoryRebuildJobFactoryForTests, + setRequestHistoryWorkerRebuildMinBytesForTests, + withRequestHistoryRead, +} from "../../src/routing/history/indexer"; +import { HISTORY_META_KEYS, HISTORY_SCHEMA_VERSION } from "../../src/routing/history/schema"; +import { RequestHistoryIntegrityMonitor } from "../../src/routing/history/integrity"; +import { isHistoryIndexCorruption } from "../../src/routing/history/sqlite-errors"; +import { computeRoutingAnalytics } from "../../src/routing/analytics"; +import { clearHealthHistoryCacheForTests, healthEvidenceForCandidate } from "../../src/routing/health"; +import { flushConfigDirHardeningForTests } from "../../src/config/paths"; +import { flushWindowsSecretAclReapsBeforeRemoval } from "../../src/lib/windows-secret-acl"; +import { removeTreeWithRetry } from "../helpers/remove-tree"; + +let testDir = ""; +let previousHome: string | undefined; + +function entry(requestId: string, timestamp: number): PersistedUsageEntry { + return { requestId, timestamp, provider: "a", model: "m1", status: 200, durationMs: 10, usageStatus: "reported" }; +} + +beforeEach(() => { + previousHome = process.env.OPENCODEX_HOME; + testDir = mkdtempSync(join(tmpdir(), "ocx-integrity-")); + process.env.OPENCODEX_HOME = testDir; + resetUsageReadCacheForTests(); + clearHealthHistoryCacheForTests(); + closeRequestHistoryIndex(); + setRequestHistoryIntegrityOptionsForTests(undefined); +}); + +afterEach(async () => { + clearHealthHistoryCacheForTests(); + closeRequestHistoryIndex(); + setRequestHistoryIntegrityOptionsForTests(undefined); + setRequestHistoryRebuildJobFactoryForTests(undefined); + setRequestHistoryWorkerRebuildMinBytesForTests(undefined); + await flushConfigDirHardeningForTests(); + await flushWindowsSecretAclReapsBeforeRemoval(testDir); + if (previousHome === undefined) delete process.env.OPENCODEX_HOME; + else process.env.OPENCODEX_HOME = previousHome; + removeTreeWithRetry(testDir); +}); + +async function existingIndex(): Promise { + for (let index = 0; index < 4; index++) appendUsageEntry(entry(`req-${index}`, 1000 + index)); + const meta = await rebuildRequestHistoryIndex(); + closeRequestHistoryIndex(); + return meta.dbPath; +} + +interface Check { + path: string; + resolve(healthy: boolean): void; + reject(error: unknown): void; +} + +/** A pending check is controlled by the test; release is immediate once it settles or is disposed. */ +function controlledChecks() { + const checks: Check[] = []; + let clock = 0; + setRequestHistoryIntegrityOptionsForTests({ + now: () => clock, + intervalMs: 1000, + failureCooldownMs: 100, + createJob: () => ({ + check: (path: string) => new Promise((resolve, reject) => { checks.push({ path, resolve, reject }); }), + dispose: async () => {}, + afterExit: async (cleanup: () => void) => { cleanup(); }, + }), + }); + return { checks, advance: (ms: number) => { clock += ms; } }; +} + +async function until(predicate: () => boolean): Promise { + for (let attempt = 0; attempt < 200 && !predicate(); attempt++) await Bun.sleep(0); + expect(predicate()).toBe(true); +} + +async function verifyInitial(checks: Check[]): Promise { + const ready = openRequestHistoryIndex(); + await until(() => checks.length === 1); + checks[0]!.resolve(true); + await ready; +} + +function corruptModelIndex(handle: Database, path: string): void { + const { rootpage } = handle.query("SELECT rootpage FROM sqlite_master WHERE name = 'idx_requests_model'").get() as { rootpage: number }; + const { page_size: pageSize } = handle.query("PRAGMA page_size").get() as { page_size: number }; + expect(rootpage).toBeGreaterThan(1); + const checkpoint = handle.query("PRAGMA wal_checkpoint(TRUNCATE)").get() as { busy: number }; + expect(checkpoint.busy).toBe(0); + // Keep SQLite's header, schema and request table intact, but invalidate a + // separate index B-tree that the default timestamp-ordered page does not visit. + const fd = openSync(path, "r+"); + try { writeSync(fd, Buffer.from([0]), 0, 1, (rootpage - 1) * pageSize); } + finally { closeSync(fd); } + handle.exec("PRAGMA shrink_memory"); +} + +describe("request-history integrity lifecycle (#7966)", () => { + test("real worker checks leave repeated page, row, status and routing reads free of full serving-thread scans", async () => { + await existingIndex(); + const query = spyOn(Database.prototype, "query"); + const prepare = spyOn(Database.prototype, "prepare"); + const exec = spyOn(Database.prototype, "exec"); + try { + for (let repeat = 0; repeat < 4; repeat++) { + const page = await queryRequestHistory({}, undefined, 1); + expect(page.rows.map(row => row.requestId)).toEqual(["req-3"]); + expect((await requestHistoryRowById("req-1"))?.requestId).toBe("req-1"); + expect((await requestHistoryIndexStatus()).indexedRows).toBe(4); + expect(openRequestHistoryIndexSync().indexedRows).toBe(4); + } + appendUsageEntry(entry("tail", 2000)); + expect((await queryRequestHistory({}, undefined, 1)).rows[0]?.requestId).toBe("tail"); + const fullChecks = [...query.mock.calls, ...prepare.mock.calls, ...exec.mock.calls] + .filter(([sql]) => /\bPRAGMA\s+(?:quick_check|integrity_check)\b/i.test(String(sql))); + expect(fullChecks).toEqual([]); + } finally { + query.mockRestore(); + prepare.mockRestore(); + exec.mockRestore(); + } + }); + + test("existing-index validation is single-flight and routing never waits for the first check", async () => { + const path = await existingIndex(); + const { checks } = controlledChecks(); + let finished = false; + const page = queryRequestHistory({}, undefined, 1).then(value => { finished = true; return value; }); + const row = requestHistoryRowById("req-1"); + const status = requestHistoryIndexStatus(); + await until(() => checks.length === 1); + expect(checks[0]!.path).toBe(path); + expect(finished).toBe(false); + expect(() => openRequestHistoryIndexSync()).toThrow(RequestHistoryIndexBusyError); + expect(checks).toHaveLength(1); + checks[0]!.resolve(true); + const [result, found, meta] = await Promise.all([page, row, status]); + expect(result.rows[0]?.requestId).toBe("req-3"); + expect(found?.requestId).toBe("req-1"); + expect(meta.indexedRows).toBe(4); + expect(openRequestHistoryIndexSync().indexedRows).toBe(4); + expect(checks).toHaveLength(1); + }); + + test("periodic checks are single-flight and do not delay a verified index's reads", async () => { + await existingIndex(); + const { checks, advance } = controlledChecks(); + await verifyInitial(checks); + advance(999); + await queryRequestHistory({}, undefined, 1); + expect(checks).toHaveLength(1); + advance(1); + expect((await queryRequestHistory({}, undefined, 1)).rows[0]?.requestId).toBe("req-3"); + await until(() => checks.length === 2); + for (let repeat = 0; repeat < 3; repeat++) { + expect((await requestHistoryIndexStatus()).indexedRows).toBe(4); + expect(openRequestHistoryIndexSync().indexedRows).toBe(4); + } + expect(checks).toHaveLength(2); + checks[1]!.resolve(true); + await Bun.sleep(0); + }); + + test("a transient initial check failure preserves the database and retries only after cooldown", async () => { + await existingIndex(); + const canonical = readFileSync(usageLogPath()); + const { checks, advance } = controlledChecks(); + const first = openRequestHistoryIndex(); + const failure = first.catch((error: unknown) => error); + await until(() => checks.length === 1); + const handle = requestHistoryDb(); + checks[0]!.reject(Object.assign(new Error("database is locked"), { code: "SQLITE_BUSY" })); + expect(await failure).toBeInstanceOf(RequestHistoryIndexBusyError); + for (let repeat = 0; repeat < 3; repeat++) { + await expect(openRequestHistoryIndex()).rejects.toBeInstanceOf(RequestHistoryIndexBusyError); + expect(() => openRequestHistoryIndexSync()).toThrow(RequestHistoryIndexBusyError); + } + expect(requestHistoryDb()).toBe(handle); + expect(checks).toHaveLength(1); + expect(handle.query("SELECT count(*) AS n FROM requests").get()).toEqual({ n: 4 }); + advance(100); + const retry = openRequestHistoryIndex(); + await until(() => checks.length === 2); + checks[1]!.resolve(true); + expect((await retry).indexedRows).toBe(4); + expect(requestHistoryDb()).toBe(handle); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("a background check failure leaves verified reads available without a worker retry storm", async () => { + await existingIndex(); + const { checks, advance } = controlledChecks(); + await verifyInitial(checks); + const handle = requestHistoryDb(); + advance(1000); + await openRequestHistoryIndex(); + await until(() => checks.length === 2); + checks[1]!.reject(new Error("worker exited")); + await Bun.sleep(0); + for (let repeat = 0; repeat < 3; repeat++) expect((await openRequestHistoryIndex()).indexedRows).toBe(4); + expect(checks).toHaveLength(2); + expect(requestHistoryDb()).toBe(handle); + advance(100); + await openRequestHistoryIndex(); + await until(() => checks.length === 3); + checks[2]!.resolve(true); + await Bun.sleep(0); + }); + + test("a late corrupt verdict from a closed lifetime cannot rebuild the reopened index", async () => { + await existingIndex(); + const { checks } = controlledChecks(); + const first = openRequestHistoryIndex(); + const closed = first.catch((error: unknown) => error); + await until(() => checks.length === 1); + closeRequestHistoryIndex(); + expect(await closed).toBeInstanceOf(RequestHistoryIndexClosedError); + const next = openRequestHistoryIndex(); + await until(() => checks.length === 2); + const reopened = requestHistoryDb(); + checks[0]!.resolve(false); + checks[1]!.resolve(true); + expect((await next).indexedRows).toBe(4); + expect(requestHistoryDb()).toBe(reopened); + expect((await queryRequestHistory({}, undefined, 10)).rows).toHaveLength(4); + expect(checks).toHaveLength(2); + }); + + test("a manual rebuild shares one flight and releases readers waiting on an initial scan", async () => { + await existingIndex(); + const { checks } = controlledChecks(); + const reader = openRequestHistoryIndex(); + await until(() => checks.length === 1); + setRequestHistoryWorkerRebuildMinBytesForTests(0); + const rebuild = rebuildRequestHistoryIndex(); + expect(rebuildRequestHistoryIndex()).toBe(rebuild); + expect(() => openRequestHistoryIndexSync()).toThrow(RequestHistoryIndexBusyError); + const [readMeta, rebuildMeta] = await Promise.all([reader, rebuild]); + expect(readMeta.indexedRows).toBe(4); + expect(rebuildMeta.indexedRows).toBe(4); + checks[0]!.resolve(false); + await Bun.sleep(0); + expect(openRequestHistoryIndexSync().indexedRows).toBe(4); + expect(checks).toHaveLength(1); + }); + + test("close prevents a manual rebuild waiting on an existing worker from reopening the index", async () => { + appendUsageEntry(entry("only", 1000)); + setRequestHistoryWorkerRebuildMinBytesForTests(0); + let builds = 0; + let rejectBuild: ((error: unknown) => void) | undefined; + setRequestHistoryRebuildJobFactoryForTests(() => ({ + build: () => new Promise((_resolve, reject) => { builds += 1; rejectBuild = reject; }), + dispose: async () => { rejectBuild?.(new Error("worker stopped")); }, + afterExit: async (cleanup: () => void) => { cleanup(); }, + })); + const reader = openRequestHistoryIndex().catch((error: unknown) => error); + await until(() => builds === 1); + const manual = rebuildRequestHistoryIndex().catch((error: unknown) => error); + closeRequestHistoryIndex(); + expect(await reader).toBeInstanceOf(RequestHistoryIndexClosedError); + expect(await manual).toBeInstanceOf(RequestHistoryIndexClosedError); + expect(builds).toBe(1); + expect(() => requestHistoryDb()).toThrow("not open"); + }); + + test("source replacement cancels a background scan and reprojects only the replacement ledger", async () => { + await existingIndex(); + const { checks, advance } = controlledChecks(); + await verifyInitial(checks); + advance(1000); + await openRequestHistoryIndex(); + await until(() => checks.length === 2); + const path = usageLogPath(); + const replacement = JSON.stringify(entry("replacement", 5000)) + "\n"; + writeFileSync(`${path}.next`, replacement); + renameSync(`${path}.next`, path); + const page = await queryRequestHistory({}, undefined, 10); + expect(page.rows.map(row => row.requestId)).toEqual(["replacement"]); + const rebuilt = requestHistoryDb(); + checks[1]!.resolve(false); + await Bun.sleep(0); + expect((await requestHistoryIndexStatus()).indexedRows).toBe(1); + expect(requestHistoryDb()).toBe(rebuilt); + expect(readFileSync(path, "utf8")).toBe(replacement); + expect(checks).toHaveLength(2); + }); + + test("a periodic corrupt verdict rebuilds the projection on the next read", async () => { + await existingIndex(); + const canonical = readFileSync(usageLogPath()); + const { checks, advance } = controlledChecks(); + await verifyInitial(checks); + const handle = requestHistoryDb(); + advance(1000); + await openRequestHistoryIndex(); + await until(() => checks.length === 2); + checks[1]!.resolve(false); + await Bun.sleep(0); + expect((await queryRequestHistory({}, undefined, 10)).rows).toHaveLength(4); + expect(requestHistoryDb()).not.toBe(handle); + expect(checks).toHaveLength(2); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("worker spawn failures observe cooldown and never delete an unverified index", async () => { + await existingIndex(); + let clock = 0; + let spawns = 0; + setRequestHistoryIntegrityOptionsForTests({ + now: () => clock, + failureCooldownMs: 100, + createJob: () => { spawns += 1; throw new Error("worker unavailable"); }, + }); + await expect(openRequestHistoryIndex()).rejects.toBeInstanceOf(RequestHistoryIndexBusyError); + const handle = requestHistoryDb(); + await expect(openRequestHistoryIndex()).rejects.toBeInstanceOf(RequestHistoryIndexBusyError); + expect(spawns).toBe(1); + clock = 100; + await expect(openRequestHistoryIndex()).rejects.toBeInstanceOf(RequestHistoryIndexBusyError); + expect(spawns).toBe(2); + expect(requestHistoryDb()).toBe(handle); + expect(handle.query("SELECT count(*) AS n FROM requests").get()).toEqual({ n: 4 }); + }); + + test("the real worker detects an unqueried damaged B-tree and rebuilds from untouched canonical rows", async () => { + const path = await existingIndex(); + const canonical = readFileSync(usageLogPath()); + const damaged = new Database(path); + try { + corruptModelIndex(damaged, path); + expect(damaged.query("SELECT value FROM schema_meta WHERE key = ?").get(HISTORY_META_KEYS.schemaVersion)) + .toEqual({ value: String(HISTORY_SCHEMA_VERSION) }); + expect(damaged.query("SELECT request_id FROM requests ORDER BY timestamp DESC, request_id DESC LIMIT 1").get()) + .toEqual({ request_id: "req-3" }); + expect(() => damaged.query("SELECT request_id FROM requests INDEXED BY idx_requests_model WHERE model = ?").all("m1")) + .toThrow(); + } finally { damaged.close(); } + setRequestHistoryWorkerRebuildMinBytesForTests(0); + const repaired = await queryRequestHistory({ model: "m1" }, undefined, 10); + expect(repaired.rows.map(row => row.requestId)).toEqual(["req-3", "req-2", "req-1", "req-0"]); + expect(repaired.meta.lastError).toMatch(/rebuilt|integrity|corrupt/i); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("corruption encountered by a live query rebuilds once even before the next periodic check", async () => { + const path = await existingIndex(); + await openRequestHistoryIndex(); + const original = requestHistoryDb(); + const canonical = readFileSync(usageLogPath()); + corruptModelIndex(original, path); + let reads = 0; + const rows = await withRequestHistoryRead(handle => { + reads += 1; + return handle.query("SELECT request_id FROM requests INDEXED BY idx_requests_model WHERE model = ? ORDER BY request_id").all("m1"); + }); + expect(reads).toBe(2); + expect(rows).toEqual([0, 1, 2, 3].map(index => ({ request_id: `req-${index}` }))); + expect(requestHistoryDb()).not.toBe(original); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("routing analytics recovers a corrupted model index through its read wrapper", async () => { + const path = await existingIndex(); + await openRequestHistoryIndex(); + const handle = requestHistoryDb(); + const canonical = readFileSync(usageLogPath()); + corruptModelIndex(handle, path); + const analytics = await computeRoutingAnalytics({ model: "m1" }); + expect(analytics.totalRequests).toBe(4); + expect(analytics.successRate).toBe(1); + expect(requestHistoryDb()).not.toBe(handle); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("routing health marks query corruption for repair and recovers current historical evidence", async () => { + const path = await existingIndex(); + const now = Date.now(); + appendUsageEntry(entry("recent", now)); + await openRequestHistoryIndex(); + const input = { provider: "a", model: "m1", now }; + expect(healthEvidenceForCandidate(input).sampleCount).toBe(1); + clearHealthHistoryCacheForTests(); + const handle = requestHistoryDb(); + const canonical = readFileSync(usageLogPath()); + corruptModelIndex(handle, path); + expect(healthEvidenceForCandidate(input)).toEqual({}); + expect((await openRequestHistoryIndex()).indexedRows).toBe(5); + expect(requestHistoryDb()).not.toBe(handle); + clearHealthHistoryCacheForTests(); + const repaired = healthEvidenceForCandidate(input); + expect(repaired.sampleCount).toBe(1); + expect(repaired.successRate).toBe(1); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("tail ingestion recovers corruption in a secondary index before inserting the appended row", async () => { + const path = await existingIndex(); + await openRequestHistoryIndex(); + const handle = requestHistoryDb(); + corruptModelIndex(handle, path); + appendUsageEntry(entry("after-corruption", 2000)); + const canonical = readFileSync(usageLogPath()); + const page = await queryRequestHistory({ model: "m1" }, undefined, 10); + expect(page.rows.map(row => row.requestId)).toEqual(["after-corruption", "req-3", "req-2", "req-1", "req-0"]); + expect(page.meta.indexedRows).toBe(5); + expect(requestHistoryDb()).not.toBe(handle); + expect(readFileSync(usageLogPath())).toEqual(canonical); + }); + + test("query retries are bounded and ordinary SQLite lock errors do not recreate the index", async () => { + await existingIndex(); + await openRequestHistoryIndex(); + const handle = requestHistoryDb(); + const busy = Object.assign(new Error("database is locked"), { code: "SQLITE_BUSY" }); + let reads = 0; + await expect(withRequestHistoryRead(() => { reads += 1; throw busy; })).rejects.toBe(busy); + expect(reads).toBe(1); + expect(requestHistoryDb()).toBe(handle); + const corrupt = Object.assign(new Error("database disk image is malformed"), { code: "SQLITE_CORRUPT" }); + reads = 0; + await expect(withRequestHistoryRead(() => { reads += 1; throw corrupt; })).rejects.toBe(corrupt); + expect(reads).toBe(2); + }); + + test("extended SQLite corruption codes are repairable while operational failures are not", () => { + for (const error of [ + { code: "SQLITE_CORRUPT" }, { code: "SQLITE_CORRUPT_INDEX" }, { code: "SQLITE_NOTADB" }, + { errno: 11 }, { errno: 267 }, { errno: 26 }, + ]) expect(isHistoryIndexCorruption(error)).toBe(true); + for (const error of [ + { code: "SQLITE_BUSY", errno: 5 }, { code: "SQLITE_LOCKED", errno: 6 }, + { code: "SQLITE_IOERR", errno: 10 }, { code: "SQLITE_FULL", errno: 13 }, + { code: "SQLITE_CANTOPEN", errno: 14 }, new Error("database disk image is malformed"), null, + ]) expect(isHistoryIndexCorruption(error)).toBe(false); + }); + + test("a cancelled check holds the replacement barrier until its actual exit callback", async () => { + const checks: Check[] = []; + const exits: Array<() => void> = []; + const monitor = new RequestHistoryIntegrityMonitor({ + createJob: () => ({ + check: (path: string) => new Promise((resolve, reject) => { checks.push({ path, resolve, reject }); }), + dispose: async () => {}, + // Simulate bounded disposal returning while the native thread is still alive. + afterExit: async (cleanup: () => void) => { exits.push(cleanup); }, + }), + }); + const first = monitor.inspect({}, "index.sqlite"); + if (first.state !== "pending") throw new Error("initial check must be pending"); + await until(() => checks.length === 1); + monitor.reset(); + const replacement = {}; + const blocked = monitor.inspect(replacement, "index.sqlite"); + expect(blocked.state).toBe("pending"); + await until(() => exits.length === 1); + let released = false; + void first.promise.then(() => { released = true; }); + checks[0]!.resolve(false); + await Bun.sleep(0); + expect(released).toBe(false); + expect(checks).toHaveLength(1); + exits[0]!(); + await first.promise; + const next = monitor.inspect(replacement, "index.sqlite"); + if (next.state !== "pending") throw new Error("replacement needs its own check"); + await until(() => checks.length === 2); + checks[1]!.resolve(true); + await until(() => exits.length === 2); + exits[1]!(); + await next.promise; + expect(monitor.inspect(replacement, "index.sqlite").state).toBe("ready"); + }); + + test("a delayed healthy check cannot clear corruption reported by a statement", async () => { + let clock = 0; + let finish: ((healthy: boolean) => void) | undefined; + let released = false; + const monitor = new RequestHistoryIntegrityMonitor({ + now: () => clock, + intervalMs: 100, + createJob: () => ({ + check: () => new Promise(resolve => { finish = resolve; }), + dispose: async () => {}, + afterExit: async (cleanup: () => void) => { released = true; cleanup(); }, + }), + }); + const handle = {}; + monitor.acceptRebuilt(handle, "index.sqlite"); + clock = 100; + expect(monitor.inspect(handle, "index.sqlite").state).toBe("ready"); + await until(() => finish !== undefined); + monitor.markCorrupt(handle); + finish!(true); + await until(() => released); + await Bun.sleep(0); + expect(monitor.inspect(handle, "index.sqlite").state).toBe("corrupt"); + }); +});