From 9e86a738ed42e98c12d94bfbff51c4ea49130e92 Mon Sep 17 00:00:00 2001 From: Xiangzhe <32761048+xz-dev@users.noreply.github.com> Date: Thu, 13 Aug 2026 18:52:46 +0800 Subject: [PATCH] perf(logging): bound call-log rotation work (#10125) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * perf(logging): bound call-log rotation work * refactor(usage): extract call-log rotation/pruning from callLogs.ts to satisfy the file-size gate Move the bounded rotation scheduler, orphan-artifact scanner, and row/overflow pruning helpers (deleteCallLogsBefore, trimCallLogsToMaxRows, cleanupOverflowCallLogFiles, cleanupOrphanCallLogFiles, rotateCallLogs, scheduleCallLogRotation) into a new src/lib/usage/callLogRotation.ts module. Pure extraction, no behavior change — callLogs.ts re-exports the same public symbols so existing importers (usageDb.ts, compliance/index.ts, the purge-logs route, and the rotation/cap test suite) are unaffected. Brings callLogs.ts from 1108 to 787 lines, under the 1000-line file-size cap. Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --------- Co-authored-by: diegosouzapw <8016841+diegosouzapw@users.noreply.github.com> --- .../10125-incremental-call-log-rotation.md | 1 + src/lib/usage/callLogArtifacts.ts | 15 +- src/lib/usage/callLogRotation.ts | 361 ++++++++++++++++++ src/lib/usage/callLogs.ts | 227 +---------- src/lib/usage/callLogsBoundedQueries.ts | 34 +- tests/unit/call-log-cap.test.ts | 3 + tests/unit/call-log-file-rotation.test.ts | 258 +++++++++---- .../unit/call-log-oom-unbounded-5618.test.ts | 26 +- .../unit/call-log-trim-sql-vars-5217.test.ts | 3 + 9 files changed, 646 insertions(+), 282 deletions(-) create mode 100644 changelog.d/fixes/10125-incremental-call-log-rotation.md create mode 100644 src/lib/usage/callLogRotation.ts diff --git a/changelog.d/fixes/10125-incremental-call-log-rotation.md b/changelog.d/fixes/10125-incremental-call-log-rotation.md new file mode 100644 index 0000000000..50657fb19e --- /dev/null +++ b/changelog.d/fixes/10125-incremental-call-log-rotation.md @@ -0,0 +1 @@ +- **perf(logging):** bound each scheduled call-log rotation pass to incremental database and filesystem work (#10125) diff --git a/src/lib/usage/callLogArtifacts.ts b/src/lib/usage/callLogArtifacts.ts index 6fdfb4a4e1..cdac96345d 100644 --- a/src/lib/usage/callLogArtifacts.ts +++ b/src/lib/usage/callLogArtifacts.ts @@ -253,13 +253,22 @@ export function readCallArtifact(relativePath: string | null): { } } -export function deleteCallArtifact(relativePath: string | null): boolean { - if (!CALL_LOGS_DIR || !relativePath) return false; +export function deleteCallArtifact(relativePath: string | null, baseDir = CALL_LOGS_DIR): boolean { + if (!baseDir || !relativePath) return false; try { - const absPath = path.join(CALL_LOGS_DIR, relativePath); + const resolvedBaseDir = path.resolve(baseDir); + const absPath = path.join(resolvedBaseDir, relativePath); if (!fs.existsSync(absPath)) return false; fs.rmSync(absPath, { force: true }); + const parentDir = path.dirname(absPath); + if (parentDir !== resolvedBaseDir) { + try { + fs.rmdirSync(parentDir); + } catch { + // Directory is non-empty or already gone. + } + } return true; } catch { return false; diff --git a/src/lib/usage/callLogRotation.ts b/src/lib/usage/callLogRotation.ts new file mode 100644 index 0000000000..a5d63a5d7e --- /dev/null +++ b/src/lib/usage/callLogRotation.ts @@ -0,0 +1,361 @@ +/** + * Bounded call-log rotation and pruning. + * + * Extracted from callLogs.ts (#8249/#10125 file-size gate) — deletion of expired/overflow + * rows, orphan artifact scanning, and the throttled rotation scheduler. Pure extraction, no + * behavior change: callLogs.ts re-exports these symbols so existing importers are unaffected. + */ + +import fs from "node:fs"; +import path from "node:path"; +import { getDbInstance } from "../db/core"; +import { + findReferencedArtifacts, + selectCallLogIdsBefore, + selectOverflowArtifactPaths, +} from "./callLogsBoundedQueries"; +import { + CALL_LOGS_DIR, + deleteCallArtifact, + type CallLogDetailState, +} from "./callLogArtifacts"; +import { getCallLogMaxEntries, getCallLogRetentionDays, getCallLogsTableMaxRows } from "../logEnv"; + +const CALL_LOG_ROTATE_THROTTLE_MS = 60_000; +const CALL_LOG_ROTATE_BATCH_SIZE = 100; +const CALL_LOG_ORPHAN_MIN_AGE_MS = 5 * 60_000; +let lastCallLogRotationScheduledAt = 0; +let callLogRotateInFlight = false; +let callLogRotateScheduled = false; + +export type DeleteResult = { + deletedRows: number; + deletedArtifacts: number; +}; + +export function clearArtifactReference(relativePath: string, nextState: CallLogDetailState) { + const db = getDbInstance(); + db.prepare( + ` + UPDATE call_logs + SET detail_state = ?, + artifact_relpath = NULL, + artifact_size_bytes = NULL, + artifact_sha256 = NULL + WHERE artifact_relpath = ? + ` + ).run(nextState, relativePath); +} + +// #5217: SQLite caps a statement at SQLITE_MAX_VARIABLE_NUMBER bound params +// (~999 on many builds). Callers like trimCallLogsToMaxRows() passed up to 5000 +// ids in one `IN (...)` → "too many SQL variables" aborted trimming. Chunk well +// under the limit so each DELETE/SELECT stays valid. +const DELETE_ID_CHUNK_SIZE = 500; + +function deleteCallLogRowsByIds(ids: string[]): DeleteResult { + if (ids.length === 0) { + return { deletedRows: 0, deletedArtifacts: 0 }; + } + + const db = getDbInstance(); + let deletedRows = 0; + let deletedArtifacts = 0; + + for (let i = 0; i < ids.length; i += DELETE_ID_CHUNK_SIZE) { + const chunk = ids.slice(i, i + DELETE_ID_CHUNK_SIZE); + const placeholders = chunk.map(() => "?").join(", "); + const rows = db + .prepare(`SELECT artifact_relpath FROM call_logs WHERE id IN (${placeholders})`) + .all(...chunk) as Array<{ artifact_relpath: string | null }>; + + const result = db.prepare(`DELETE FROM call_logs WHERE id IN (${placeholders})`).run(...chunk); + deletedRows += result.changes; + for (const row of rows) { + if (deleteCallArtifact(row.artifact_relpath)) { + deletedArtifacts++; + } + } + } + + return { + deletedRows, + deletedArtifacts, + }; +} + +type OrphanScanCursor = { + baseDir: string; + root: fs.Dir; + day: fs.Dir | null; + dayName: string | null; + pendingDayName: string | null; +}; + +type OrphanScanBatch = { + candidates: string[]; + exhausted: boolean; + scannedEntries: number; +}; + +let orphanScanCursor: OrphanScanCursor | null = null; + +function closeOrphanScanCursor(): void { + try { + orphanScanCursor?.day?.closeSync(); + } catch {} + try { + orphanScanCursor?.root.closeSync(); + } catch {} + orphanScanCursor = null; +} + +function readOrphanCandidates( + baseDir: string, + candidateLimit: number, + scanLimit: number +): OrphanScanBatch { + let scannedEntries = 0; + if (!orphanScanCursor || orphanScanCursor.baseDir !== baseDir) { + closeOrphanScanCursor(); + if (scannedEntries >= scanLimit) { + return { candidates: [], exhausted: false, scannedEntries }; + } + scannedEntries++; + orphanScanCursor = { + baseDir, + root: fs.opendirSync(baseDir), + day: null, + dayName: null, + pendingDayName: null, + }; + } + + const candidates: string[] = []; + let exhausted = false; + while (candidates.length < candidateLimit && scannedEntries < scanLimit) { + if (!orphanScanCursor.day) { + if (orphanScanCursor.pendingDayName) { + scannedEntries++; + const dayName = orphanScanCursor.pendingDayName; + orphanScanCursor.pendingDayName = null; + try { + orphanScanCursor.day = fs.opendirSync(path.join(baseDir, dayName)); + orphanScanCursor.dayName = dayName; + } catch { + continue; + } + continue; + } + + scannedEntries++; + const dayEntry = orphanScanCursor.root.readSync(); + if (!dayEntry) { + closeOrphanScanCursor(); + exhausted = true; + break; + } + if (!dayEntry.isDirectory()) continue; + orphanScanCursor.pendingDayName = dayEntry.name; + continue; + } + + scannedEntries++; + const fileEntry = orphanScanCursor.day.readSync(); + if (!fileEntry) { + try { + orphanScanCursor.day.closeSync(); + } catch {} + orphanScanCursor.day = null; + orphanScanCursor.dayName = null; + continue; + } + if (!fileEntry.isFile() || !fileEntry.name.endsWith(".json")) continue; + candidates.push(path.posix.join(orphanScanCursor.dayName!, fileEntry.name)); + } + return { candidates, exhausted, scannedEntries }; +} + +export function cleanupOrphanCallLogFiles( + baseDir = CALL_LOGS_DIR, + options: { maxCandidates?: number; maxScanEntries?: number; minAgeMs?: number } = {} +) { + if (!baseDir || !fs.existsSync(baseDir)) return 0; + + const maxCandidates = options.maxCandidates ?? Number.POSITIVE_INFINITY; + const maxScanEntries = options.maxScanEntries ?? Number.POSITIVE_INFINITY; + const minAgeMs = options.minAgeMs ?? 0; + if (maxCandidates <= 0 || maxScanEntries <= 0) return 0; + + try { + let deleted = 0; + let remainingCandidates = maxCandidates; + let remainingScanEntries = maxScanEntries; + while (remainingCandidates > 0 && remainingScanEntries > 0) { + const { candidates, exhausted, scannedEntries } = readOrphanCandidates( + baseDir, + Math.min(remainingCandidates, DELETE_ID_CHUNK_SIZE), + remainingScanEntries + ); + remainingCandidates -= candidates.length; + remainingScanEntries -= scannedEntries; + const oldEnough = candidates.filter((relativePath) => { + if (minAgeMs <= 0) return true; + try { + return Date.now() - fs.statSync(path.join(baseDir, relativePath)).mtimeMs >= minAgeMs; + } catch { + return false; + } + }); + const referenced = findReferencedArtifacts(oldEnough); + for (const relativePath of oldEnough) { + if (!referenced.has(relativePath) && deleteCallArtifact(relativePath, baseDir)) deleted++; + } + if (exhausted || scannedEntries === 0) break; + } + return deleted; + } catch (error) { + closeOrphanScanCursor(); + console.error("[callLogs] Failed to prune orphan request artifacts:", (error as Error).message); + return 0; + } +} + +export function cleanupOverflowCallLogFiles( + baseDir = CALL_LOGS_DIR, + maxEntries?: number, + maxDeletes = Number.POSITIVE_INFINITY +) { + if (!baseDir || !fs.existsSync(baseDir)) return 0; + + const limit = maxEntries ?? getCallLogMaxEntries(); + if (!Number.isInteger(limit) || limit < 1 || maxDeletes <= 0) return 0; + + try { + let deleted = 0; + while (deleted < maxDeletes) { + const paths = selectOverflowArtifactPaths( + limit, + Math.min(DELETE_ID_CHUNK_SIZE, maxDeletes - deleted) + ); + if (paths.length === 0) break; + let progress = 0; + for (const relativePath of paths) { + if (deleteCallArtifact(relativePath, baseDir)) { + clearArtifactReference(relativePath, "missing"); + deleted++; + progress++; + } + } + if (progress === 0) break; + } + return deleted; + } catch (error) { + console.error( + "[callLogs] Failed to prune overflow request artifacts:", + (error as Error).message + ); + return 0; + } +} + +export function deleteCallLogsBefore( + cutoff: string, + maxDeletes = Number.POSITIVE_INFINITY +): DeleteResult { + let deletedRows = 0; + let deletedArtifacts = 0; + while (deletedRows < maxDeletes) { + const ids = selectCallLogIdsBefore(cutoff, Math.min(5000, maxDeletes - deletedRows)); + if (ids.length === 0) break; + const result = deleteCallLogRowsByIds(ids); + deletedRows += result.deletedRows; + deletedArtifacts += result.deletedArtifacts; + if (result.deletedRows === 0) break; + } + return { deletedRows, deletedArtifacts }; +} + +export function trimCallLogsToMaxRows( + maxRows = getCallLogsTableMaxRows(), + maxDeletes = Number.POSITIVE_INFINITY +) { + if (!Number.isInteger(maxRows) || maxRows < 1 || maxDeletes <= 0) { + return { deletedRows: 0, deletedArtifacts: 0 }; + } + + const db = getDbInstance(); + let deletedRows = 0; + let deletedArtifacts = 0; + + while (deletedRows < maxDeletes) { + const currentCount = db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { + cnt: number; + }; + if (currentCount.cnt <= maxRows) break; + + const toDelete = Math.min(currentCount.cnt - maxRows, 5000, maxDeletes - deletedRows); + const ids = db + .prepare("SELECT id FROM call_logs ORDER BY timestamp ASC LIMIT ?") + .all(toDelete) + .map((row) => String((row as { id: string }).id)); + const result = deleteCallLogRowsByIds(ids); + deletedRows += result.deletedRows; + deletedArtifacts += result.deletedArtifacts; + if (result.deletedRows === 0) break; + } + + return { deletedRows, deletedArtifacts }; +} + +export function rotateCallLogs() { + try { + if (!CALL_LOGS_DIR || !fs.existsSync(CALL_LOGS_DIR)) return; + + const retentionMs = getCallLogRetentionDays() * 24 * 60 * 60 * 1000; + const cutoff = new Date(Date.now() - retentionMs).toISOString(); + + deleteCallLogsBefore(cutoff, CALL_LOG_ROTATE_BATCH_SIZE); + trimCallLogsToMaxRows(getCallLogsTableMaxRows(), CALL_LOG_ROTATE_BATCH_SIZE); + cleanupOverflowCallLogFiles(CALL_LOGS_DIR, getCallLogMaxEntries(), CALL_LOG_ROTATE_BATCH_SIZE); + cleanupOrphanCallLogFiles(CALL_LOGS_DIR, { + maxCandidates: CALL_LOG_ROTATE_BATCH_SIZE, + maxScanEntries: CALL_LOG_ROTATE_BATCH_SIZE, + minAgeMs: CALL_LOG_ORPHAN_MIN_AGE_MS, + }); + } catch (error) { + console.error("[callLogs] Failed to rotate request artifacts:", (error as Error).message); + } +} + +function runScheduledCallLogRotation() { + if (callLogRotateInFlight) return; + callLogRotateInFlight = true; + setImmediate(() => { + try { + rotateCallLogs(); + } catch (error) { + console.error("[callLogs] Failed to rotate request artifacts:", (error as Error).message); + } finally { + callLogRotateInFlight = false; + } + }); +} + +export function scheduleCallLogRotation() { + if (!CALL_LOGS_DIR) return; + const elapsed = Date.now() - lastCallLogRotationScheduledAt; + if (elapsed >= CALL_LOG_ROTATE_THROTTLE_MS) { + lastCallLogRotationScheduledAt = Date.now(); + runScheduledCallLogRotation(); + return; + } + if (callLogRotateScheduled) return; + callLogRotateScheduled = true; + lastCallLogRotationScheduledAt = Date.now(); + const timer = setTimeout(() => { + callLogRotateScheduled = false; + runScheduledCallLogRotation(); + }, CALL_LOG_ROTATE_THROTTLE_MS - elapsed); + timer.unref?.(); +} diff --git a/src/lib/usage/callLogs.ts b/src/lib/usage/callLogs.ts index b2713c64f3..77f1a60a76 100644 --- a/src/lib/usage/callLogs.ts +++ b/src/lib/usage/callLogs.ts @@ -9,7 +9,6 @@ import fs from "node:fs"; import path from "node:path"; import type { RequestPipelinePayloads } from "@omniroute/open-sse/utils/requestLogger.ts"; import { getDbInstance } from "../db/core"; -import { collectReferencedArtifacts, selectCallLogIdsBefore } from "./callLogsBoundedQueries"; import { getRequestDetailLogByCallLogId } from "../db/detailedLogs"; import { shouldPersistToDisk } from "./migrations"; import { getCallLogApiKeyContext } from "./callLogApiKeyContext"; @@ -23,13 +22,9 @@ import { } from "./tokenAccounting"; import { isNoLog } from "../compliance/noLog"; import { protectPayloadForLog, parseStoredPayload } from "../logPayloads"; -import { getCallLogMaxEntries, getCallLogRetentionDays, getCallLogsTableMaxRows } from "../logEnv"; import { pickDisplayValue } from "@/shared/utils/maskEmail"; import { CALL_LOGS_DIR, - cleanupEmptyCallLogDirs, - deleteCallArtifact, - listCallLogArtifactFiles, readCallArtifact, writeCallArtifact, type CallLogArtifact, @@ -45,14 +40,30 @@ import { protectPipelinePayloads, buildRequestSummary, } from "./callLogs/format"; +import { + clearArtifactReference, + cleanupOrphanCallLogFiles, + cleanupOverflowCallLogFiles, + deleteCallLogsBefore, + trimCallLogsToMaxRows, + rotateCallLogs, + scheduleCallLogRotation, +} from "./callLogRotation"; + +// Re-exported for existing importers (usageDb.ts, compliance/index.ts, purge-logs route, +// and the call-log rotation/cap test suite) — the implementation now lives in +// ./callLogRotation.ts (extracted to satisfy the file-size gate, #10125). +export { + cleanupOrphanCallLogFiles, + cleanupOverflowCallLogFiles, + deleteCallLogsBefore, + trimCallLogsToMaxRows, + rotateCallLogs, + scheduleCallLogRotation, +}; type JsonRecord = Record; -const CALL_LOG_ROTATE_THROTTLE_MS = 60_000; -let lastCallLogRotationScheduledAt = 0; -let callLogRotateInFlight = false; -let callLogRotateScheduled = false; - type CallLogSummaryRow = { id: string; timestamp: string | null; @@ -326,154 +337,6 @@ function readLegacyLogFromDisk(entry: { return null; } -function clearArtifactReference(relativePath: string, nextState: CallLogDetailState) { - const db = getDbInstance(); - db.prepare( - ` - UPDATE call_logs - SET detail_state = ?, - artifact_relpath = NULL, - artifact_size_bytes = NULL, - artifact_sha256 = NULL - WHERE artifact_relpath = ? - ` - ).run(nextState, relativePath); -} - -function listReferencedArtifacts() { - // #5618: paged to avoid an unbounded `.all()` OOM on large call_logs tables. - return collectReferencedArtifacts(); -} - -// #5217: SQLite caps a statement at SQLITE_MAX_VARIABLE_NUMBER bound params -// (~999 on many builds). Callers like trimCallLogsToMaxRows() passed up to 5000 -// ids in one `IN (...)` → "too many SQL variables" aborted trimming. Chunk well -// under the limit so each DELETE/SELECT stays valid. -const DELETE_ID_CHUNK_SIZE = 500; - -function deleteCallLogRowsByIds(ids: string[]): DeleteResult { - if (ids.length === 0) { - return { deletedRows: 0, deletedArtifacts: 0 }; - } - - const db = getDbInstance(); - let deletedRows = 0; - let deletedArtifacts = 0; - - for (let i = 0; i < ids.length; i += DELETE_ID_CHUNK_SIZE) { - const chunk = ids.slice(i, i + DELETE_ID_CHUNK_SIZE); - const placeholders = chunk.map(() => "?").join(", "); - const rows = db - .prepare(`SELECT artifact_relpath FROM call_logs WHERE id IN (${placeholders})`) - .all(...chunk) as Array<{ artifact_relpath: string | null }>; - - const result = db.prepare(`DELETE FROM call_logs WHERE id IN (${placeholders})`).run(...chunk); - deletedRows += result.changes; - for (const row of rows) { - if (deleteCallArtifact(row.artifact_relpath)) { - deletedArtifacts++; - } - } - } - cleanupEmptyCallLogDirs(); - - return { - deletedRows, - deletedArtifacts, - }; -} - -export function cleanupOrphanCallLogFiles(baseDir = CALL_LOGS_DIR) { - if (!baseDir || !fs.existsSync(baseDir)) return 0; - - try { - const referenced = listReferencedArtifacts(); - let deleted = 0; - for (const file of listCallLogArtifactFiles(baseDir)) { - if (referenced.has(file.relativePath)) continue; - if (deleteCallArtifact(file.relativePath)) { - deleted++; - } - } - cleanupEmptyCallLogDirs(baseDir); - return deleted; - } catch (error) { - console.error("[callLogs] Failed to prune orphan request artifacts:", (error as Error).message); - return 0; - } -} - -export function cleanupOverflowCallLogFiles(baseDir = CALL_LOGS_DIR, maxEntries?: number) { - if (!baseDir || !fs.existsSync(baseDir)) return 0; - - const limit = maxEntries ?? getCallLogMaxEntries(); - if (!Number.isInteger(limit) || limit < 1) return 0; - - try { - let deleted = 0; - const files = listCallLogArtifactFiles(baseDir); - for (const file of files.slice(limit)) { - if (deleteCallArtifact(file.relativePath)) { - clearArtifactReference(file.relativePath, "missing"); - deleted++; - } - } - cleanupEmptyCallLogDirs(baseDir); - return deleted; - } catch (error) { - console.error( - "[callLogs] Failed to prune overflow request artifacts:", - (error as Error).message - ); - return 0; - } -} - -export function deleteCallLogsBefore(cutoff: string): DeleteResult { - // #5618: page the id selection so a large backlog never loads in one `.all()`. - let deletedRows = 0; - let deletedArtifacts = 0; - for (;;) { - const ids = selectCallLogIdsBefore(cutoff); - if (ids.length === 0) break; - const result = deleteCallLogRowsByIds(ids); - deletedRows += result.deletedRows; - deletedArtifacts += result.deletedArtifacts; - if (result.deletedRows === 0) break; - } - return { deletedRows, deletedArtifacts }; -} - -export function trimCallLogsToMaxRows(maxRows = getCallLogsTableMaxRows()) { - if (!Number.isInteger(maxRows) || maxRows < 1) { - return { deletedRows: 0, deletedArtifacts: 0 }; - } - - const db = getDbInstance(); - let deletedRows = 0; - let deletedArtifacts = 0; - const batchSize = 5000; - - while (true) { - const currentCount = db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { - cnt: number; - }; - if (currentCount.cnt <= maxRows) break; - - const toDelete = Math.min(currentCount.cnt - maxRows, batchSize); - const ids = db - .prepare("SELECT id FROM call_logs ORDER BY timestamp ASC LIMIT ?") - .all(toDelete) - .map((row) => String((row as { id: string }).id)); - const result = deleteCallLogRowsByIds(ids); - deletedRows += result.deletedRows; - deletedArtifacts += result.deletedArtifacts; - if (result.deletedRows === 0) break; - } - - return { deletedRows, deletedArtifacts }; -} - function resolveProviderDisplay( provider: string | null, nodeName: string | null, @@ -714,54 +577,6 @@ export async function saveCallLog(entry: any) { } } -export function rotateCallLogs() { - try { - if (!CALL_LOGS_DIR || !fs.existsSync(CALL_LOGS_DIR)) return; - - const retentionMs = getCallLogRetentionDays() * 24 * 60 * 60 * 1000; - const cutoff = new Date(Date.now() - retentionMs).toISOString(); - - deleteCallLogsBefore(cutoff); - trimCallLogsToMaxRows(getCallLogsTableMaxRows()); - cleanupOverflowCallLogFiles(CALL_LOGS_DIR, getCallLogMaxEntries()); - cleanupOrphanCallLogFiles(CALL_LOGS_DIR); - } catch (error) { - console.error("[callLogs] Failed to rotate request artifacts:", (error as Error).message); - } -} - -function runScheduledCallLogRotation() { - if (callLogRotateInFlight) return; - callLogRotateInFlight = true; - setImmediate(() => { - try { - rotateCallLogs(); - } catch (error) { - console.error("[callLogs] Failed to rotate request artifacts:", (error as Error).message); - } finally { - callLogRotateInFlight = false; - } - }); -} - -export function scheduleCallLogRotation() { - if (!CALL_LOGS_DIR) return; - const elapsed = Date.now() - lastCallLogRotationScheduledAt; - if (elapsed >= CALL_LOG_ROTATE_THROTTLE_MS) { - lastCallLogRotationScheduledAt = Date.now(); - runScheduledCallLogRotation(); - return; - } - if (callLogRotateScheduled) return; - callLogRotateScheduled = true; - lastCallLogRotationScheduledAt = Date.now(); - const timer = setTimeout(() => { - callLogRotateScheduled = false; - runScheduledCallLogRotation(); - }, CALL_LOG_ROTATE_THROTTLE_MS - elapsed); - timer.unref?.(); -} - if (shouldPersistToDisk && process.env.NODE_ENV !== "test") { scheduleCallLogRotation(); } diff --git a/src/lib/usage/callLogsBoundedQueries.ts b/src/lib/usage/callLogsBoundedQueries.ts index 5fa9719178..b0f27b89f6 100644 --- a/src/lib/usage/callLogsBoundedQueries.ts +++ b/src/lib/usage/callLogsBoundedQueries.ts @@ -19,7 +19,9 @@ export function collectReferencedArtifacts(): Set { "SELECT artifact_relpath FROM call_logs WHERE artifact_relpath IS NOT NULL LIMIT ? OFFSET ?" ); for (let offset = 0; ; offset += CALL_LOG_QUERY_PAGE) { - const rows = stmt.all(CALL_LOG_QUERY_PAGE, offset) as Array<{ artifact_relpath: string | null }>; + const rows = stmt.all(CALL_LOG_QUERY_PAGE, offset) as Array<{ + artifact_relpath: string | null; + }>; for (const row of rows) { if (typeof row.artifact_relpath === "string") referenced.add(row.artifact_relpath); } @@ -40,3 +42,33 @@ export function selectCallLogIdsBefore(cutoff: string, limit = CALL_LOG_QUERY_PA .all(cutoff, limit) as Array<{ id: string }>; return rows.map((row) => String(row.id)); } + +export function selectOverflowArtifactPaths(maxEntries: number, limit: number): string[] { + const db = getDbInstance(); + const rows = db + .prepare( + `SELECT artifact_relpath + FROM call_logs + WHERE artifact_relpath IS NOT NULL + ORDER BY timestamp DESC, id DESC + LIMIT ? OFFSET ?` + ) + .all(limit, maxEntries) as Array<{ artifact_relpath: string }>; + return rows.map((row) => row.artifact_relpath); +} + +export function findReferencedArtifacts(relativePaths: string[]): Set { + if (relativePaths.length === 0) return new Set(); + + const db = getDbInstance(); + const placeholders = relativePaths.map(() => "?").join(", "); + const rows = db + .prepare( + `SELECT DISTINCT artifact_relpath + FROM call_logs + WHERE artifact_relpath IN (${placeholders}) + LIMIT ?` + ) + .all(...relativePaths, relativePaths.length) as Array<{ artifact_relpath: string }>; + return new Set(rows.map((row) => row.artifact_relpath)); +} diff --git a/tests/unit/call-log-cap.test.ts b/tests/unit/call-log-cap.test.ts index 6c676de0bd..f1e63a6474 100644 --- a/tests/unit/call-log-cap.test.ts +++ b/tests/unit/call-log-cap.test.ts @@ -4,6 +4,9 @@ import fs from "node:fs"; import os from "node:os"; import path from "node:path"; +import { useDecollidedMigrationsDir } from "./helpers/decollidedMigrationsDir.ts"; + +useDecollidedMigrationsDir(); const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-calllogs-artifacts-")); process.env.DATA_DIR = TEST_DATA_DIR; process.env.CALL_LOG_RETENTION_DAYS = "3650"; diff --git a/tests/unit/call-log-file-rotation.test.ts b/tests/unit/call-log-file-rotation.test.ts index d6f2e3ade1..06fe48aa11 100644 --- a/tests/unit/call-log-file-rotation.test.ts +++ b/tests/unit/call-log-file-rotation.test.ts @@ -4,19 +4,24 @@ import fs from "node:fs"; import os from "node:os"; import path from "node:path"; +import { useDecollidedMigrationsDir } from "./helpers/decollidedMigrationsDir.ts"; + +useDecollidedMigrationsDir(); const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-call-log-files-")); const ORIGINAL_DATA_DIR = process.env.DATA_DIR; const ORIGINAL_RETENTION_DAYS = process.env.CALL_LOG_RETENTION_DAYS; const ORIGINAL_MAX_ENTRIES = process.env.CALL_LOG_MAX_ENTRIES; +const ORIGINAL_MAX_ROWS = process.env.CALL_LOGS_TABLE_MAX_ROWS; process.env.DATA_DIR = TEST_DATA_DIR; process.env.CALL_LOG_RETENTION_DAYS = "7"; process.env.CALL_LOG_MAX_ENTRIES = "2"; const core = await import("../../src/lib/db/core.ts"); -const { rotateCallLogs, cleanupOverflowCallLogFiles } = +const { rotateCallLogs, cleanupOverflowCallLogFiles, cleanupOrphanCallLogFiles } = await import("../../src/lib/usage/callLogs.ts"); -const { CALL_LOGS_DIR } = await import("../../src/lib/usage/callLogArtifacts.ts"); +const { CALL_LOGS_DIR, deleteCallArtifact } = + await import("../../src/lib/usage/callLogArtifacts.ts"); async function resetTestDataDir() { fs.mkdirSync(TEST_DATA_DIR, { recursive: true }); @@ -33,7 +38,7 @@ async function resetTestDataDir() { const db = core.getDbInstance(); db.prepare("DELETE FROM call_logs").run(); return; - } catch (error: any) { + } catch (error: unknown) { lastError = error; await new Promise((resolve) => setTimeout(resolve, 25)); } @@ -105,6 +110,12 @@ test.after(async () => { process.env.CALL_LOG_MAX_ENTRIES = ORIGINAL_MAX_ENTRIES; } + if (ORIGINAL_MAX_ROWS === undefined) { + delete process.env.CALL_LOGS_TABLE_MAX_ROWS; + } else { + process.env.CALL_LOGS_TABLE_MAX_ROWS = ORIGINAL_MAX_ROWS; + } + await resetTestDataDir(); }); @@ -176,7 +187,11 @@ test("call log file rotation honors both retention days and file count", () => { const db = core.getDbInstance(); assert.equal( - (db.prepare("SELECT COUNT(*) AS cnt FROM call_logs WHERE id = ?").get("old-log") as any).cnt, + ( + db.prepare("SELECT COUNT(*) AS cnt FROM call_logs WHERE id = ?").get("old-log") as { + cnt: number; + } + ).cnt, 0 ); assert.equal(fs.existsSync(path.join(CALL_LOGS_DIR, oldRelPath)), false); @@ -184,8 +199,9 @@ test("call log file rotation honors both retention days and file count", () => { const keepARow = db .prepare("SELECT detail_state, artifact_relpath FROM call_logs WHERE id = ?") .get("keep-a"); - assert.equal((keepARow as any).detail_state, "missing"); - (assert as any).equal((keepARow as any).artifact_relpath, null); + const typedKeepARow = keepARow as { detail_state: string; artifact_relpath: string | null }; + assert.equal(typedKeepARow.detail_state, "missing"); + assert.equal(typedKeepARow.artifact_relpath, null); assert.equal(fs.existsSync(path.join(CALL_LOGS_DIR, keepARelPath)), false); assert.equal(fs.existsSync(path.join(CALL_LOGS_DIR, keepBRelPath)), true); @@ -196,12 +212,12 @@ test("rotateCallLogs swallows filesystem errors during cleanup", () => { assert.ok(CALL_LOGS_DIR, "CALL_LOGS_DIR should resolve for test data dir"); fs.mkdirSync(CALL_LOGS_DIR, { recursive: true }); - const originalReaddirSync = fs.readdirSync; + const originalOpendirSync = fs.opendirSync; const originalConsoleError = console.error; const consoleCalls = []; - fs.readdirSync = () => { - throw new Error("simulated readdir failure"); + fs.opendirSync = () => { + throw new Error("simulated opendir failure"); }; console.error = (...args) => { consoleCalls.push(args.join(" ")); @@ -210,69 +226,11 @@ test("rotateCallLogs swallows filesystem errors during cleanup", () => { try { assert.doesNotThrow(() => rotateCallLogs()); } finally { - fs.readdirSync = originalReaddirSync; + fs.opendirSync = originalOpendirSync; console.error = originalConsoleError; } - assert.ok(consoleCalls.length >= 1); - assert.ok(consoleCalls.some((line) => /simulated readdir failure/.test(line))); -}); - -test("cleanupOverflowCallLogFiles logs and returns when directory scanning fails", () => { - assert.ok(CALL_LOGS_DIR, "CALL_LOGS_DIR should resolve for test data dir"); - fs.mkdirSync(CALL_LOGS_DIR, { recursive: true }); - - const originalReaddirSync = fs.readdirSync; - const originalConsoleError = console.error; - const consoleCalls = []; - - fs.readdirSync = (targetPath, ...args) => { - if (targetPath === CALL_LOGS_DIR) { - throw new Error("simulated overflow scan failure"); - } - return originalReaddirSync.call(fs, targetPath, ...args); - }; - console.error = (...args) => { - consoleCalls.push(args.join(" ")); - }; - - try { - assert.doesNotThrow(() => cleanupOverflowCallLogFiles(CALL_LOGS_DIR, 2)); - } finally { - fs.readdirSync = originalReaddirSync; - console.error = originalConsoleError; - } - - assert.equal(consoleCalls.length, 1); - assert.match(consoleCalls[0], /Failed to prune overflow request artifacts/); - assert.match(consoleCalls[0], /simulated overflow scan failure/); -}); - -test("cleanupOverflowCallLogFiles ignores directory entries that fail nested inspection", () => { - assert.ok(CALL_LOGS_DIR, "CALL_LOGS_DIR should resolve for test data dir"); - fs.rmSync(CALL_LOGS_DIR, { recursive: true, force: true }); - fs.mkdirSync(CALL_LOGS_DIR, { recursive: true }); - - const nestedDir = path.join(CALL_LOGS_DIR, "2026-04-01"); - fs.mkdirSync(nestedDir, { recursive: true }); - fs.writeFileSync(path.join(nestedDir, "100000_keep.json"), "{}"); - - const originalReaddirSync = fs.readdirSync; - fs.readdirSync = (targetPath, ...args) => { - if (targetPath === nestedDir) { - throw new Error("simulated nested scan failure"); - } - return originalReaddirSync.call(fs, targetPath, ...args); - }; - - try { - assert.doesNotThrow(() => cleanupOverflowCallLogFiles(CALL_LOGS_DIR, 1)); - } finally { - fs.readdirSync = originalReaddirSync; - } - - assert.equal(fs.existsSync(nestedDir), true); - assert.equal(fs.existsSync(path.join(nestedDir, "100000_keep.json")), true); + assert.ok(consoleCalls.some((line) => /simulated opendir failure/.test(line))); }); test("cleanupOverflowCallLogFiles ignores rmSync failures for old artifacts", () => { @@ -322,3 +280,165 @@ test("cleanupOverflowCallLogFiles ignores rmSync failures for old artifacts", () assert.equal(fs.existsSync(newerFile), true); assert.equal(fs.existsSync(olderFile), true); }); + +test("artifact deletion never removes an equivalent trailing-slash root", () => { + const baseDir = path.join(TEST_DATA_DIR, "root-preservation"); + const artifactPath = path.join(baseDir, "root.json"); + fs.mkdirSync(baseDir, { recursive: true }); + fs.writeFileSync(artifactPath, "{}"); + + assert.equal(deleteCallArtifact("root.json", `${baseDir}${path.sep}`), true); + assert.equal(fs.existsSync(artifactPath), false); + assert.equal(fs.existsSync(baseDir), true); +}); + +test("scheduled rotation caps retention and max-row trimming at 100 each", () => { + assert.ok(CALL_LOGS_DIR); + fs.mkdirSync(CALL_LOGS_DIR, { recursive: true }); + process.env.CALL_LOG_RETENTION_DAYS = "1"; + process.env.CALL_LOGS_TABLE_MAX_ROWS = "150"; + + const oldBase = Date.parse("2020-01-01T00:00:00.000Z"); + const freshBase = Date.now() - 60_000; + for (let i = 0; i < 250; i++) { + insertCallLog({ id: `old-${i}`, timestamp: new Date(oldBase + i).toISOString() }); + } + for (let i = 0; i < 250; i++) { + insertCallLog({ id: `fresh-${i}`, timestamp: new Date(freshBase + i).toISOString() }); + } + + rotateCallLogs(); + const db = core.getDbInstance(); + assert.equal( + ( + db.prepare("SELECT COUNT(*) AS cnt FROM call_logs WHERE id LIKE 'old-%'").get() as { + cnt: number; + } + ).cnt, + 50 + ); + assert.equal( + (db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { cnt: number }).cnt, + 300 + ); +}); + +test("overflow cleanup removes at most 100 artifacts and continues across calls", () => { + assert.ok(CALL_LOGS_DIR); + const now = Date.now(); + for (let i = 0; i < 205; i++) { + const relPath = `2026-04-03/${String(i).padStart(4, "0")}.json`; + const absPath = path.join(CALL_LOGS_DIR, relPath); + fs.mkdirSync(path.dirname(absPath), { recursive: true }); + fs.writeFileSync(absPath, "{}"); + insertCallLog({ + id: `overflow-${i}`, + timestamp: new Date(now + i).toISOString(), + artifact_relpath: relPath, + }); + } + + assert.equal(cleanupOverflowCallLogFiles(CALL_LOGS_DIR, 5, 100), 100); + assert.equal(cleanupOverflowCallLogFiles(CALL_LOGS_DIR, 5, 100), 100); + assert.equal(cleanupOverflowCallLogFiles(CALL_LOGS_DIR, 5, 100), 0); + assert.equal( + ( + core + .getDbInstance() + .prepare("SELECT COUNT(*) AS cnt FROM call_logs WHERE artifact_relpath IS NOT NULL") + .get() as { cnt: number } + ).cnt, + 5 + ); +}); + +test("orphan cleanup scans at most 100 candidates, resumes, and protects fresh files", () => { + assert.ok(CALL_LOGS_DIR); + const dayDir = path.join(CALL_LOGS_DIR, "2026-04-04"); + fs.mkdirSync(dayDir, { recursive: true }); + const old = new Date(Date.now() - 10 * 60_000); + for (let i = 0; i < 205; i++) { + const file = path.join(dayDir, `${String(i).padStart(4, "0")}.json`); + fs.writeFileSync(file, "{}"); + fs.utimesSync(file, old, old); + } + assert.equal(cleanupOrphanCallLogFiles(CALL_LOGS_DIR, { maxCandidates: 100, minAgeMs: 0 }), 100); + assert.equal(cleanupOrphanCallLogFiles(CALL_LOGS_DIR, { maxCandidates: 100, minAgeMs: 0 }), 100); + + const freshFile = path.join(dayDir, "fresh.json"); + fs.writeFileSync(freshFile, "{}"); + const third = cleanupOrphanCallLogFiles(CALL_LOGS_DIR, { + maxCandidates: 100, + minAgeMs: 5 * 60_000, + }); + assert.equal(third, 5); + assert.equal(fs.existsSync(freshFile), true); +}); + +test("orphan traversal bounds every directory operation and resumes", () => { + const baseDir = path.join(TEST_DATA_DIR, "odd-artifact-tree"); + const dayDir = path.join(baseDir, "2026-04-05"); + fs.mkdirSync(dayDir, { recursive: true }); + for (let i = 0; i < 150; i++) { + fs.writeFileSync(path.join(dayDir, `${String(i).padStart(4, "0")}.tmp`), "{}"); + } + for (let i = 0; i < 10; i++) { + fs.writeFileSync(path.join(dayDir, `${String(i).padStart(4, "0")}.json`), "{}"); + } + + const originalOpendirSync = fs.opendirSync; + let operations = 0; + fs.opendirSync = ((...args: Parameters) => { + operations++; + const dir = originalOpendirSync(...args); + const originalReadSync = dir.readSync.bind(dir); + dir.readSync = () => { + operations++; + return originalReadSync(); + }; + return dir; + }) as typeof fs.opendirSync; + + const passOperations: number[] = []; + let deleted = 0; + try { + for (let pass = 0; pass < 2; pass++) { + operations = 0; + deleted += cleanupOrphanCallLogFiles(baseDir, { + maxCandidates: 100, + maxScanEntries: 100, + minAgeMs: 0, + }); + passOperations.push(operations); + } + } finally { + fs.opendirSync = originalOpendirSync; + } + + assert.equal(passOperations[0], 100); + assert.ok(passOperations[1] > 0 && passOperations[1] <= 100); + assert.equal(deleted, 10); + assert.equal(fs.readdirSync(dayDir).filter((entry) => entry.endsWith(".json")).length, 0); +}); + +test("hot rotation avoids full artifact listing and bounds stat calls", () => { + assert.ok(CALL_LOGS_DIR); + const dayDir = path.join(CALL_LOGS_DIR, "2026-04-05"); + fs.mkdirSync(dayDir, { recursive: true }); + for (let i = 0; i < 150; i++) { + fs.writeFileSync(path.join(dayDir, `${String(i).padStart(4, "0")}.json`), "{}"); + } + + const originalStatSync = fs.statSync; + let statCalls = 0; + fs.statSync = (...args) => { + statCalls++; + return originalStatSync.apply(fs, args); + }; + try { + rotateCallLogs(); + } finally { + fs.statSync = originalStatSync; + } + assert.ok(statCalls <= 100, `expected at most 100 stat calls, got ${statCalls}`); +}); diff --git a/tests/unit/call-log-oom-unbounded-5618.test.ts b/tests/unit/call-log-oom-unbounded-5618.test.ts index e5ff9757f7..49d52be057 100644 --- a/tests/unit/call-log-oom-unbounded-5618.test.ts +++ b/tests/unit/call-log-oom-unbounded-5618.test.ts @@ -4,6 +4,9 @@ import fs from "node:fs"; import os from "node:os"; import path from "node:path"; +import { useDecollidedMigrationsDir } from "./helpers/decollidedMigrationsDir.ts"; + +useDecollidedMigrationsDir(); // #5618 — `cleanupExpiredLogs` → `rotateCallLogs` ran at daemon startup and used // unbounded `SELECT … FROM call_logs … .all()` calls. node:sqlite's // StatementSync.all() materializes the whole result set, so on a large @@ -58,9 +61,7 @@ function captureSql(run: () => void): string[] { } const unboundedSelectsOnCallLogs = (sqls: string[]) => - sqls.filter( - (s) => /SELECT/i.test(s) && /\bFROM\s+call_logs\b/i.test(s) && !/LIMIT/i.test(s) - ); + sqls.filter((s) => /SELECT/i.test(s) && /\bFROM\s+call_logs\b/i.test(s) && !/LIMIT/i.test(s)); test.beforeEach(() => { core.resetDbInstance(); @@ -90,6 +91,25 @@ test("#5618 collectReferencedArtifacts pages with LIMIT and collects across page ); }); +test("bounded reference lookup keeps every candidate despite duplicate rows", () => { + const db = core.getDbInstance(); + db.transaction(() => { + for (let i = 0; i < 150; i++) { + insertCallLog( + `duplicate-${i}`, + `2026-01-01T00:00:${String(i % 60).padStart(2, "0")}.000Z`, + "2026-01/duplicate.json" + ); + } + insertCallLog("second-path", "2026-01-01T00:01:00.000Z", "2026-01/second.json"); + })(); + + assert.deepEqual( + bounded.findReferencedArtifacts(["2026-01/duplicate.json", "2026-01/second.json"]), + new Set(["2026-01/duplicate.json", "2026-01/second.json"]) + ); +}); + test("#5618 deleteCallLogsBefore selects ids with LIMIT (bounded) instead of all at once", () => { const total = 1200; seed(total, false); diff --git a/tests/unit/call-log-trim-sql-vars-5217.test.ts b/tests/unit/call-log-trim-sql-vars-5217.test.ts index aedee5360c..7f7dab57aa 100644 --- a/tests/unit/call-log-trim-sql-vars-5217.test.ts +++ b/tests/unit/call-log-trim-sql-vars-5217.test.ts @@ -4,6 +4,9 @@ import fs from "node:fs"; import os from "node:os"; import path from "node:path"; +import { useDecollidedMigrationsDir } from "./helpers/decollidedMigrationsDir.ts"; + +useDecollidedMigrationsDir(); /** * #5217 — `trimCallLogsToMaxRows()` deleted up to batchSize=5000 ids in a single * `DELETE … IN (?, ?, …)` via `deleteCallLogRowsByIds`. SQLite caps a statement at