/** * The dashboard's server-log store. * * Operators debugging a routing decision, a benched key or a retired model have * had exactly one place to look: the terminal the process was started from. On * a desktop install, a container, or a systemd unit that is either awkward or * gone entirely. This module keeps the same lines the server already prints and * makes them readable from the dashboard. * * Two tiers, ONE id space: * - a ring buffer (RING_CAPACITY entries, every level) backs the live view * and is the only thing the polling endpoint reads; * - warn/error rows are ALSO written to the `server_logs` table, so the * lines that matter survive a restart. * * Ids are assigned here, not by SQLite, because the client polls with a * `sinceId` cursor and that cursor has to mean the same thing for a line that * only ever lived in memory and for one that came back from the table. The * counter is seeded from MAX(id) at init, so ids keep increasing across * restarts and a cursor held by an open dashboard tab never goes backwards. * * Capture is a TAP inside lib/log-redaction.ts rather than a second console * wrapper: there is exactly one console patch in this process, it redacts * first, and this store only ever sees the redacted form. */ import { inspect } from 'node:util'; import { getDb } from '../db/index.js'; import { redactSecrets } from './log-redaction.js'; import type { Db } from '../db/types.js'; /** Levels the store understands. console.log maps to 'info'; debug and trace * keep their own identity so a noisy trace can be filtered out on its own. */ export const LOG_LEVELS = ['trace', 'debug', 'info', 'warn', 'error'] as const; export type ServerLogLevel = (typeof LOG_LEVELS)[number]; /** Levels durable enough to be worth a row. Mirrors the migration's CHECK. */ const PERSISTED_LEVELS = new Set(['warn', 'error']); /** Live-view depth. A thousand lines is a few minutes of a busy gateway and * costs well under a megabyte at the message cap below. */ export const RING_CAPACITY = 1000; /** How much persisted history is pulled back into the ring at init, so the * dashboard shows the warnings that preceded the restart instead of an empty * panel that fills up only if something goes wrong again. */ export const PRELOAD_LIMIT = 200; /** A single log line is a diagnostic, not a document. Long provider bodies and * multi-frame stacks are truncated rather than dropped — the head is where the * information is. */ export const MAX_MESSAGE_LENGTH = 6000; const TRUNCATION_SUFFIX = '… [truncated]'; /** * Ceiling on warn/error rows written per second. The table is pruned only on * the request path, so an idle server has no retention at all; a log storm (a * dead stdout feeding the safety net, a provider erroring in a tight loop) must * not be able to grow it without bound. Lines over the cap still reach the live * ring — only the row is skipped — and the next line after the window rolls * writes one summary row saying how many were dropped. */ export const PERSIST_MAX_PER_SECOND = 50; const PERSIST_WINDOW_MS = 1000; /** * The viewer polls GET /api/logs every couple of seconds. If the deployment in * front of us emits access-log lines, those polls would be the loudest thing in * the buffer and every poll would manufacture the content of the next one. * * NOTE (verified in this tree): this server installs NO access-log middleware — * there is no morgan/pino/winston dependency and no request-logging middleware * in app.ts or src/middleware/. So today nothing matches this filter. It stays * because the cost is one regex test at ingest and the failure mode it prevents * (a self-feeding buffer) is one an operator cannot work around; a reverse * proxy, a future middleware, or a debug line added during triage all produce * exactly these lines. */ const NOISE_RE = /\b(?:GET|HEAD)\s+\/api\/(?:logs|ping)\b/i; export interface ServerLogMeta { provider?: string; model?: string; event?: string; requestId?: string; } export interface ServerLogEntry extends ServerLogMeta { id: number; tsMs: number; level: ServerLogLevel; /** The `[Tag]` a line opens with, when it has one ('Health', 'CooldownProbe'…). */ source?: string; message: string; } // ── State ──────────────────────────────────────────────────────────────────── let ring: ServerLogEntry[] = []; let lastId = 0; let seeded = false; /** * Set while providerLog() mirrors its message to stdout. The console it calls * is the WRAPPED one (that is the point — the redaction wrapper must still see * it), and the wrapper taps back into this module, so without this flag every * structured event would land in the ring twice. */ let mirroring = false; /** * Set while a persist is in flight. The DB layer can log — a busy-timeout * warning, a permissions warning from db/index.ts — and that log would come * straight back here and try to insert again. The ring still accepts the line; * only the write is skipped. */ let persisting = false; /** Reentrancy guard for the boot seed, for the same reason as `persisting`. */ let seeding = false; /** Persist rate-cap window (see PERSIST_MAX_PER_SECOND). */ let persistWindowStartMs = 0; let persistWindowCount = 0; let persistSuppressed = 0; // ── Formatting ─────────────────────────────────────────────────────────────── /** One console argument, rendered the way it reaches stdout: strings verbatim, * Errors with their stack, everything else inspected at bounded depth. */ function formatArg(arg: unknown): string { if (typeof arg === 'string') return arg; if (arg instanceof Error) return arg.stack ?? `${arg.name}: ${arg.message}`; if (arg === null) return 'null'; if (arg === undefined) return 'undefined'; if (typeof arg === 'object') { try { return inspect(arg, { depth: 2, breakLength: Infinity, maxStringLength: 1000 }); } catch { return String(arg); } } return String(arg); } export function formatLogArgs(args: readonly unknown[]): string { return args.map(formatArg).join(' '); } function truncate(message: string): string { if (message.length <= MAX_MESSAGE_LENGTH) return message; return message.slice(0, MAX_MESSAGE_LENGTH - TRUNCATION_SUFFIX.length) + TRUNCATION_SUFFIX; } /** The subsystem tag the codebase already prefixes its lines with. Deriving it * instead of asking every call site for one is what makes the `source` column * useful for lines nobody edited. */ const SOURCE_RE = /^\s*\[([A-Za-z][\w .:/-]{0,39})\]/; function deriveSource(message: string): string | undefined { return SOURCE_RE.exec(message)?.[1]; } // ── Ingest ─────────────────────────────────────────────────────────────────── function trimField(value: string | undefined): string | undefined { if (typeof value !== 'string') return undefined; const trimmed = value.trim(); return trimmed === '' ? undefined : trimmed.slice(0, 200); } export interface RecordLogOptions extends ServerLogMeta { level: ServerLogLevel; message: string; source?: string; tsMs?: number; } /** * The single ingest point. Everything — the console tap, providerLog, the boot * preload's live siblings — arrives here, which is what makes the noise filter, * the length cap and the id counter impossible to bypass. * * Returns the stored entry, or null when the line was filtered out. */ export function recordLogEntry(options: RecordLogOptions): ServerLogEntry | null { const message = truncate(options.message); if (message.trim() === '') return null; if (NOISE_RE.test(message)) return null; ensureSeeded(); const entry: ServerLogEntry = { id: ++lastId, tsMs: options.tsMs ?? Date.now(), level: options.level, message, }; const source = trimField(options.source) ?? deriveSource(message); if (source) entry.source = source; const provider = trimField(options.provider); if (provider) entry.provider = provider; const model = trimField(options.model); if (model) entry.model = model; const event = trimField(options.event); if (event) entry.event = event; const requestId = trimField(options.requestId); if (requestId) entry.requestId = requestId; push(entry); if (PERSISTED_LEVELS.has(entry.level)) persistCapped(entry); return entry; } function persistCapped(entry: ServerLogEntry): void { if (entry.tsMs - persistWindowStartMs >= PERSIST_WINDOW_MS || entry.tsMs < persistWindowStartMs) { const dropped = persistSuppressed; persistWindowStartMs = entry.tsMs; persistWindowCount = 0; persistSuppressed = 0; if (dropped > 0) { const summary: ServerLogEntry = { id: ++lastId, tsMs: entry.tsMs, level: 'warn', source: 'server-logs', message: `[server-logs] ${dropped} warn/error lines not persisted (over ${PERSIST_MAX_PER_SECOND}/s); they reached the live view only`, }; // Keep ids increasing in arrival order: the summary takes the next id and // the line that rolled the window is re-stamped after it. entry.id = ++lastId; ring.splice(ring.length - 1, 0, summary); if (ring.length > RING_CAPACITY) ring.shift(); persist(summary); persistWindowCount++; } } if (persistWindowCount >= PERSIST_MAX_PER_SECOND) { persistSuppressed++; return; } persistWindowCount++; persist(entry); } function push(entry: ServerLogEntry): void { ring.push(entry); if (ring.length > RING_CAPACITY) ring.splice(0, ring.length - RING_CAPACITY); } /** * Called by the console wrapper in lib/log-redaction.ts, AFTER redaction. Never * throws: a log line must not be able to fail the call that emitted it. */ export function recordConsoleLine(level: ServerLogLevel, args: readonly unknown[]): void { if (mirroring) return; try { recordLogEntry({ level, message: formatLogArgs(args) }); } catch { // Swallowed on purpose — see above. } } /** * Emit a structured operational event: recorded with its provider/model/event * metadata for the dashboard AND mirrored to stdout, so nothing an operator * needs exists only behind a login. * * The message is passed through redactSecrets() here because the recording * bypasses the console wrapper; the stdout mirror goes through the wrapped * console (already-redacted text is idempotent under a second pass) so that a * restored console — tests, an embedder — still sees the line. */ export function providerLog( level: ServerLogLevel, message: string, meta: ServerLogMeta = {}, ): void { const redacted = redactSecrets(message); try { recordLogEntry({ level, message: redacted, ...meta }); } catch { // Never let the store break the caller's control flow. } mirroring = true; try { const write = level === 'error' ? console.error : level === 'warn' ? console.warn : level === 'debug' ? console.debug : level === 'trace' ? console.trace : console.log; write(redacted); } catch { // A console that throws is not this module's problem to solve. } finally { mirroring = false; } } // ── Persistence ────────────────────────────────────────────────────────────── interface ServerLogRow { id: number; level: string; source: string | null; provider: string | null; model: string | null; event: string | null; request_id: string | null; message: string; created_at_ms: number; } function tryDb(): Db | null { try { return getDb(); } catch { // Pre-initDb boot lines, and tests that never open a database. return null; } } function hasTable(db: Db): boolean { try { return !!db .prepare("SELECT name FROM sqlite_master WHERE type='table' AND name='server_logs'") .get(); } catch { return false; } } function persist(entry: ServerLogEntry): void { if (persisting) return; persisting = true; try { const db = tryDb(); if (!db) return; db.prepare(` INSERT INTO server_logs (id, level, source, provider, model, event, request_id, message, created_at_ms) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?) `).run( entry.id, entry.level, entry.source ?? null, entry.provider ?? null, entry.model ?? null, entry.event ?? null, entry.requestId ?? null, entry.message, entry.tsMs, ); } catch { // Best effort by design: the table may not exist yet (a boot line racing // the migration), the DB may be locked, the disk may be full. None of that // is worth losing the live line — or crashing the caller — over. } finally { persisting = false; } } function rowToEntry(row: ServerLogRow): ServerLogEntry { const entry: ServerLogEntry = { id: row.id, tsMs: row.created_at_ms, level: (LOG_LEVELS as readonly string[]).includes(row.level) ? (row.level as ServerLogLevel) : 'error', message: row.message, }; if (row.source) entry.source = row.source; if (row.provider) entry.provider = row.provider; if (row.model) entry.model = row.model; if (row.event) entry.event = row.event; if (row.request_id) entry.requestId = row.request_id; return entry; } /** * Seed the id counter and preload recent history. Idempotent, and safe to call * before the database exists — it simply stays unseeded and tries again on the * next line, which is what covers the handful of boot logs emitted between * installLogRedaction() and initDb(). * * Lines already buffered when the database appears keep their order but are * re-stamped ABOVE the persisted maximum, because ids have to be unique across * both tiers and a pre-DB line was numbered from a counter that started at zero. */ function ensureSeeded(): void { if (seeded || seeding) return; // Same reasoning as `persisting`: the two probes below touch the DB layer, // which can log, and that log comes straight back into recordLogEntry. seeding = true; try { seedNow(); } finally { seeding = false; } } function seedNow(): void { const db = tryDb(); if (!db || !hasTable(db)) return; seeded = true; try { const pending = ring.splice(0, ring.length); const max = db.prepare('SELECT MAX(id) AS maxId FROM server_logs').get() as | { maxId: number | null } | undefined; lastId = Math.max(lastId, max?.maxId ?? 0); const rows = db.prepare(` SELECT id, level, source, provider, model, event, request_id, message, created_at_ms FROM server_logs ORDER BY created_at_ms DESC, id DESC LIMIT ? `).all(PRELOAD_LIMIT) as ServerLogRow[]; // Read newest-first so LIMIT keeps the recent end; the ring is oldest-first. for (const row of rows.reverse()) push(rowToEntry(row)); for (const entry of pending) { entry.id = ++lastId; push(entry); if (PERSISTED_LEVELS.has(entry.level)) persist(entry); } } catch { // A seed that fails leaves the counter where it was; ids stay increasing // within this process, which is the guarantee the cursor actually needs. } } /** Force the seed/preload now (the route calls this so an idle server still * shows persisted history on the first poll). */ export function initServerLogs(): void { ensureSeeded(); } // ── Read side ──────────────────────────────────────────────────────────────── /** Counts over the CURRENT ring, unfiltered, so the UI can render level badges * without fetching every entry. Trace is folded into debug: it is a debug-tier * detail and the dashboard shows four badges. */ export interface LogLevelCounts { debug: number; info: number; warn: number; error: number; } export interface LogQuery { levels?: ServerLogLevel[]; q?: string; provider?: string; sinceId?: number; limit?: number; } export const DEFAULT_LIMIT = 200; export const MAX_LIMIT = 500; export const MIN_LIMIT = 1; export function clampLimit(raw: number | undefined): number { if (raw === undefined || !Number.isFinite(raw)) return DEFAULT_LIMIT; return Math.min(MAX_LIMIT, Math.max(MIN_LIMIT, Math.trunc(raw))); } /** Highest id handed out so far — what the client sends back as sinceId, even * when every entry it would have matched was filtered away. */ export function currentMaxId(): number { ensureSeeded(); return lastId; } export function levelCounts(): LogLevelCounts { ensureSeeded(); const counts: LogLevelCounts = { debug: 0, info: 0, warn: 0, error: 0 }; for (const entry of ring) { if (entry.level === 'trace' || entry.level === 'debug') counts.debug++; else counts[entry.level]++; } return counts; } function matches(entry: ServerLogEntry, levels: Set | null, needle: string | null, provider: string | null): boolean { if (levels && !levels.has(entry.level)) return false; if (provider !== null && entry.provider !== provider) return false; if (needle !== null) { const haystack = `${entry.message} ${entry.provider ?? ''} ${entry.source ?? ''} ${entry.event ?? ''}`.toLowerCase(); if (!haystack.includes(needle)) return false; } return true; } /** The newest `limit` entries of the filtered set, oldest→newest. */ export function queryLogs(query: LogQuery = {}): ServerLogEntry[] { ensureSeeded(); const sinceId = query.sinceId; // A caller already caught up costs one comparison, not a scan. if (sinceId !== undefined && sinceId >= lastId) return []; const levels = query.levels && query.levels.length > 0 ? new Set(query.levels) : null; const needle = query.q && query.q.trim() !== '' ? query.q.trim().toLowerCase() : null; const provider = query.provider && query.provider.trim() !== '' ? query.provider.trim() : null; const limit = clampLimit(query.limit); const out: ServerLogEntry[] = []; // Walk backwards so `limit` bounds the work, not just the result. for (let i = ring.length - 1; i >= 0 && out.length < limit; i--) { const entry = ring[i]!; if (sinceId !== undefined && entry.id <= sinceId) break; if (matches(entry, levels, needle, provider)) out.push(entry); } return out.reverse(); } /** Empty both tiers. The id counter is deliberately NOT reset: a dashboard tab * holding a cursor would otherwise be handed ids it has already seen. */ export function clearLogs(): void { ensureSeeded(); ring = []; const db = tryDb(); if (!db) return; try { db.prepare('DELETE FROM server_logs').run(); } catch { // Same best-effort contract as persist(). } } /** Test seam: drop every entry AND the counter/seed state, so a suite can * simulate a cold start against a database that still holds rows. */ export function resetServerLogsForTest(): void { ring = []; lastId = 0; seeded = false; seeding = false; mirroring = false; persisting = false; persistWindowStartMs = 0; persistWindowCount = 0; persistSuppressed = 0; } /** Test/introspection seam: the ring exactly as stored. */ export function ringSnapshot(): readonly ServerLogEntry[] { return ring; }