51b160bfc9
A line identical to the last persisted row (level+source+message+path) within a 5-min refreshing window updates that row — context._repeat counts the fold, _firstAt keeps the first occurrence, createdAt tracks the latest so the storm stays at the top of the newest-first viewer. A continuous storm stays ONE row however long it rages, so it can't evict unrelated history via the 50k row cap or grind the appliance disk. LogsViewer badges coalesced rows ×N (tooltip: count + first occurrence, sq/en). In-memory last-row cache only; a pruned-under-us row falls through to a fresh insert. Claude-Session: https://claude.ai/code/session_01Xcm6ikLgGoCxxHrxtjkk5V
295 lines
11 KiB
TypeScript
295 lines
11 KiB
TypeScript
import { randomUUID } from "node:crypto";
|
|
import { and, appLogs, desc, eq, sql, type Db } from "@parking/db";
|
|
import {
|
|
LOG_LEVEL_ORDER,
|
|
type AppLogRecord,
|
|
type ClientLogInput,
|
|
type LogLevel,
|
|
type LogSource,
|
|
} from "@parking/shared";
|
|
|
|
// Application/diagnostic LOG SINK — the host-side store behind the third log stream
|
|
// (app_logs), distinct from the signed ledger and device telemetry. It persists:
|
|
// - BACKEND warn/error/fatal, fed by a pino stream (see pinoDbStream) so any
|
|
// app.log.warn/error lands in the DB without changing call sites.
|
|
// - FRONTEND errors POSTed to /api/logs (failed requests, uncaught errors).
|
|
// Everything here is UNSIGNED + prunable. Pruned by age AND a row cap so an offline
|
|
// appliance with finite disk can't be filled by a log storm. See
|
|
// wiki/concepts/app-logs.md, decisions/event-streams-split.md.
|
|
|
|
/** Only warn and above are persisted from the backend (info/debug stay stdout-only). */
|
|
const BACKEND_PERSIST_MIN: LogLevel = "warn";
|
|
|
|
/** Defensive caps so one runaway log can't bloat a row (chars). */
|
|
const MAX_MESSAGE = 4_000;
|
|
const MAX_STACK = 16_000;
|
|
const MAX_CONTEXT_JSON = 16_000;
|
|
|
|
/** Storm coalescing: a line identical to the LAST persisted one (level+source+message+
|
|
* path) within this window of its previous occurrence UPDATES that row (bumping a
|
|
* `_repeat` counter in its context) instead of inserting a new one. A continuous storm
|
|
* keeps refreshing the window, so it stays ONE row however long it rages — repeated
|
|
* errors can't evict unrelated history or grind the appliance disk (field incident
|
|
* 2026-07-07: one unreachable controller ≈ hundreds of identical rows/minute). */
|
|
const COALESCE_WINDOW_MS = 300_000;
|
|
|
|
export interface LogRetention {
|
|
/** Delete logs older than this many days. */
|
|
readonly maxAgeDays: number;
|
|
/** Hard cap on total rows — the oldest beyond this are pruned. */
|
|
readonly maxRows: number;
|
|
}
|
|
|
|
export const DEFAULT_RETENTION: LogRetention = {
|
|
// 60 days (~2 months) — the operator's chosen diagnostic window (2026-07-04),
|
|
// matched by the container-log rotation caps in docker-compose.prod.yml. The row
|
|
// cap below still bounds a burst regardless of age.
|
|
maxAgeDays: Number(process.env.LOG_RETENTION_DAYS ?? 60),
|
|
maxRows: Number(process.env.LOG_RETENTION_MAX_ROWS ?? 50_000),
|
|
};
|
|
|
|
function clamp(s: string | null | undefined, max: number): string | null {
|
|
if (s == null) return null;
|
|
return s.length > max ? s.slice(0, max) : s;
|
|
}
|
|
|
|
/** Serialize context to JSON, bounded — never throw on a circular/huge object. */
|
|
function safeContext(ctx: Record<string, unknown> | null | undefined): Record<string, unknown> | null {
|
|
if (ctx == null) return null;
|
|
try {
|
|
const json = JSON.stringify(ctx);
|
|
if (json.length <= MAX_CONTEXT_JSON) return ctx;
|
|
return { _truncated: true, preview: json.slice(0, MAX_CONTEXT_JSON) };
|
|
} catch {
|
|
return { _unserializable: true };
|
|
}
|
|
}
|
|
|
|
export class LogService {
|
|
readonly #db: Db;
|
|
readonly #retention: LogRetention;
|
|
/** Reentrancy guard: never let persisting a log itself emit a persisted log. */
|
|
#writing = false;
|
|
/** The last persisted row, for storm coalescing (in-memory only; a restart just
|
|
* starts a fresh row — best-effort, like everything in this sink). */
|
|
#last: {
|
|
id: string;
|
|
key: string;
|
|
count: number;
|
|
firstAt: string;
|
|
lastAtMs: number;
|
|
baseContext: Record<string, unknown> | null;
|
|
} | null = null;
|
|
|
|
constructor(db: Db, retention: LogRetention = DEFAULT_RETENTION) {
|
|
this.#db = db;
|
|
this.#retention = retention;
|
|
}
|
|
|
|
/** Low-level insert. Best-effort: a logging failure must never break a request or
|
|
* recurse (a DB error here would otherwise log → insert → error → log …). */
|
|
#insert(row: {
|
|
level: LogLevel;
|
|
source: LogSource;
|
|
message: string;
|
|
context?: Record<string, unknown> | null;
|
|
httpStatus?: number | null;
|
|
path?: string | null;
|
|
stack?: string | null;
|
|
userId?: string | null;
|
|
userAgent?: string | null;
|
|
createdAt?: string;
|
|
}): void {
|
|
if (this.#writing) return;
|
|
this.#writing = true;
|
|
try {
|
|
const createdAt = row.createdAt ?? new Date().toISOString();
|
|
const message = clamp(row.message, MAX_MESSAGE) ?? "";
|
|
const path = clamp(row.path, 512);
|
|
const key = `${row.level}|${row.source}|${message}|${path ?? ""}`;
|
|
const nowMs = Date.now();
|
|
|
|
// Storm coalescing: identical to the last persisted row, within the window →
|
|
// bump that row instead of inserting. createdAt moves to the LATEST occurrence
|
|
// (keeps the storm visible at the top of the newest-first viewer); the first
|
|
// occurrence's time is preserved in context._firstAt.
|
|
const last = this.#last;
|
|
if (last && last.key === key && nowMs - last.lastAtMs <= COALESCE_WINDOW_MS) {
|
|
const res = this.#db
|
|
.update(appLogs)
|
|
.set({
|
|
context: { ...(last.baseContext ?? {}), _repeat: last.count + 1, _firstAt: last.firstAt },
|
|
createdAt,
|
|
})
|
|
.where(eq(appLogs.id, last.id))
|
|
.run();
|
|
if ((res.changes ?? 0) > 0) {
|
|
last.count += 1;
|
|
last.lastAtMs = nowMs;
|
|
return;
|
|
}
|
|
// The row was pruned out from under us — fall through to a fresh insert.
|
|
}
|
|
|
|
const id = randomUUID();
|
|
const baseContext = safeContext(row.context);
|
|
this.#db
|
|
.insert(appLogs)
|
|
.values({
|
|
id,
|
|
level: row.level,
|
|
source: row.source,
|
|
message,
|
|
context: baseContext,
|
|
httpStatus: row.httpStatus ?? null,
|
|
path,
|
|
stack: clamp(row.stack, MAX_STACK),
|
|
userId: row.userId ?? null,
|
|
userAgent: clamp(row.userAgent, 512),
|
|
createdAt,
|
|
})
|
|
.run();
|
|
this.#last = { id, key, count: 1, firstAt: createdAt, lastAtMs: nowMs, baseContext };
|
|
} catch {
|
|
// Swallow — diagnostics must never take down the path they observe. (Can't log
|
|
// it; that's the recursion we're guarding against.)
|
|
} finally {
|
|
this.#writing = false;
|
|
}
|
|
}
|
|
|
|
/** Persist a BACKEND log line (called by the pino stream). Below warn is dropped. */
|
|
recordBackend(level: LogLevel, message: string, context?: Record<string, unknown> | null): void {
|
|
if (LOG_LEVEL_ORDER[level] < LOG_LEVEL_ORDER[BACKEND_PERSIST_MIN]) return;
|
|
this.#insert({ level, source: "backend", message, context });
|
|
}
|
|
|
|
/** Persist a FRONTEND-reported log (from POST /api/logs). The server stamps the
|
|
* user + receive time; the client supplies level/message/context. */
|
|
recordClient(
|
|
input: ClientLogInput,
|
|
meta: { userId?: string | null; userAgent?: string | null },
|
|
): void {
|
|
this.#insert({
|
|
level: input.level,
|
|
source: "frontend",
|
|
message: input.message,
|
|
context: input.context ?? null,
|
|
httpStatus: input.httpStatus ?? null,
|
|
path: input.path ?? null,
|
|
stack: input.stack ?? null,
|
|
userId: meta.userId ?? null,
|
|
userAgent: meta.userAgent ?? null,
|
|
// Keep the client's capture time in context for ordering; createdAt is server time.
|
|
createdAt: new Date().toISOString(),
|
|
});
|
|
}
|
|
|
|
/** Read recent logs, newest first, with optional level/source/since filters. */
|
|
query(opts: {
|
|
limit: number;
|
|
level?: LogLevel;
|
|
source?: LogSource;
|
|
since?: string;
|
|
}): AppLogRecord[] {
|
|
const conds = [];
|
|
if (opts.level) conds.push(eq(appLogs.level, opts.level));
|
|
if (opts.source) conds.push(eq(appLogs.source, opts.source));
|
|
if (opts.since) conds.push(sql`${appLogs.createdAt} >= ${opts.since}`);
|
|
const rows = this.#db
|
|
.select()
|
|
.from(appLogs)
|
|
.where(conds.length ? and(...conds) : undefined)
|
|
.orderBy(desc(appLogs.createdAt))
|
|
.limit(opts.limit)
|
|
.all();
|
|
return rows as unknown as AppLogRecord[];
|
|
}
|
|
|
|
/** Prune by age then by row cap. Returns how many rows were deleted. Safe to call
|
|
* on a timer; cheap (indexed on created_at). */
|
|
prune(): number {
|
|
let deleted = 0;
|
|
try {
|
|
const cutoff = new Date(Date.now() - this.#retention.maxAgeDays * 86_400_000).toISOString();
|
|
const byAge = this.#db.delete(appLogs).where(sql`${appLogs.createdAt} < ${cutoff}`).run();
|
|
deleted += byAge.changes ?? 0;
|
|
|
|
// Row cap: keep the newest maxRows, delete the rest. One subquery — find the
|
|
// created_at boundary of the keep-window, delete older.
|
|
const total = this.#db.select({ c: sql<number>`count(*)` }).from(appLogs).get();
|
|
const count = total?.c ?? 0;
|
|
if (count > this.#retention.maxRows) {
|
|
const boundary = this.#db
|
|
.select({ createdAt: appLogs.createdAt })
|
|
.from(appLogs)
|
|
.orderBy(desc(appLogs.createdAt))
|
|
.limit(1)
|
|
.offset(this.#retention.maxRows - 1)
|
|
.get();
|
|
if (boundary) {
|
|
const byCap = this.#db
|
|
.delete(appLogs)
|
|
.where(sql`${appLogs.createdAt} < ${boundary.createdAt}`)
|
|
.run();
|
|
deleted += byCap.changes ?? 0;
|
|
}
|
|
}
|
|
} catch {
|
|
// best-effort
|
|
}
|
|
return deleted;
|
|
}
|
|
}
|
|
|
|
/**
|
|
* A pino-compatible write stream that forwards BACKEND warn+ lines into the LogService.
|
|
* Pino writes one JSON object per line to this stream; we parse, resolve the level
|
|
* (name or numeric encoding), and persist. Returned as `{ write }` so it can be passed
|
|
* as pino's stream. stdout still receives the same line (we tee), so console logging is
|
|
* unchanged.
|
|
*/
|
|
export function pinoDbStream(
|
|
service: LogService,
|
|
tee: NodeJS.WritableStream,
|
|
): { write: (line: string) => void } {
|
|
const NUM_TO_LEVEL: Record<number, LogLevel> = {
|
|
10: "trace",
|
|
20: "debug",
|
|
30: "info",
|
|
40: "warn",
|
|
50: "error",
|
|
60: "fatal",
|
|
};
|
|
return {
|
|
write(line: string): void {
|
|
// Always tee to the original destination first (don't lose stdout logging).
|
|
try {
|
|
tee.write(line);
|
|
} catch {
|
|
/* ignore */
|
|
}
|
|
try {
|
|
const obj = JSON.parse(line) as {
|
|
level?: number | string;
|
|
msg?: string;
|
|
err?: { stack?: string; message?: string };
|
|
[k: string]: unknown;
|
|
};
|
|
// The logger emits level NAMES (formatters.level in server.ts, for human-
|
|
// readable container logs); a default pino config emits numbers. Accept both.
|
|
const level: LogLevel =
|
|
typeof obj.level === "string" && obj.level in LOG_LEVEL_ORDER
|
|
? (obj.level as LogLevel)
|
|
: NUM_TO_LEVEL[typeof obj.level === "number" ? obj.level : 30] ?? "info";
|
|
if (LOG_LEVEL_ORDER[level] < LOG_LEVEL_ORDER[BACKEND_PERSIST_MIN]) return;
|
|
// Strip pino's noisy standard fields from the persisted context.
|
|
const { level: _l, time: _t, pid: _p, hostname: _h, msg, ...rest } = obj;
|
|
service.recordBackend(level, typeof msg === "string" ? msg : "", rest);
|
|
} catch {
|
|
// A non-JSON line (shouldn't happen with pino) — ignore for persistence.
|
|
}
|
|
},
|
|
};
|
|
}
|