feat(logs): app log store — backend pino DB sink + frontend error collection

Add a third data stream (app_logs), distinct from the signed ledger and device telemetry, for operational/diagnostic logs — an offline appliance has no Sentry to ship to, so the host is the log store. Backend: a pino stream tees warn/error/fatal into app_logs (info/debug stay stdout-only) with no call-site change; the DB is built before Fastify so the logger has its sink. Frontend (lib/logger.ts): ships failed API requests (minus 401 churn), window.onerror, unhandledrejection, and a top-level React ErrorBoundary; console warn/error forwarded only at debug/trace. Batched/throttled POST, sendBeacon on pagehide, loop-safe (never logs the /api/logs call), best-effort everywhere. POST /api/logs (any signed-in user, CSRF, tolerant) + GET /api/logs gated by a new log:read permission (new `log` RBAC resource; admin holds it). Retention: pruned by age + row cap, hourly + at startup. UI: a Logs screen under /setup (filter level/source/since, expand to context+stack), sq+en. Migration 0009_app_logs. Verified end-to-end via app.inject: login -> POST 204 -> GET 200 with the record; backend warn/error persisted, info dropped; non-admin GET 403 / POST 204. Claude-Session: https://claude.ai/code/session_01Xcm6ikLgGoCxxHrxtjkk5V
2026-06-19 12:54:22 +02:00
parent 0074e82a2a
commit bfb6ab0b36
20 changed files with 1064 additions and 9 deletions
@@ -0,0 +1,236 @@
+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;
+
+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 = {
+  maxAgeDays: Number(process.env.LOG_RETENTION_DAYS ?? 30),
+  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;
+
+  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 {
+      this.#db
+        .insert(appLogs)
+        .values({
+          id: randomUUID(),
+          level: row.level,
+          source: row.source,
+          message: clamp(row.message, MAX_MESSAGE) ?? "",
+          context: safeContext(row.context),
+          httpStatus: row.httpStatus ?? null,
+          path: clamp(row.path, 512),
+          stack: clamp(row.stack, MAX_STACK),
+          userId: row.userId ?? null,
+          userAgent: clamp(row.userAgent, 512),
+          createdAt: row.createdAt ?? new Date().toISOString(),
+        })
+        .run();
+    } 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, map the numeric level
+ * to a name, 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;
+          msg?: string;
+          err?: { stack?: string; message?: string };
+          [k: string]: unknown;
+        };
+        const level = NUM_TO_LEVEL[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.
+      }
+    },
+  };
+}
@@ -0,0 +1,66 @@
+import type { FastifyInstance } from "fastify";
+import type { AppLogRecord, ClientLogInput, LogLevel } from "@parking/shared";
+import { requireAuth, requirePermission } from "../auth.js";
+import type { LogService } from "../log-service.js";
+
+// Application/diagnostic logs (app_logs) — see wiki/concepts/app-logs.md. Two ends:
+//   - POST /api/logs  : the FRONTEND ships its errors here (failed requests, uncaught
+//                       exceptions). Any signed-in user may write (it's their own
+//                       browser's diagnostics); CSRF still applies (mutation).
+//   - GET  /api/logs  : read the store — gated by `log:read` (admin/diagnostic role).
+// Writes go through the shared LogService (bounded, best-effort, reentrancy-guarded);
+// the DB sink for BACKEND warn+ is wired at the pino stream, not here.
+
+const LEVELS: ReadonlySet<string> = new Set(["trace", "debug", "info", "warn", "error", "fatal"]);
+
+/** Cap a single ingest batch so a misbehaving client can't flood the store. */
+const MAX_BATCH = 50;
+
+function isValidEntry(e: unknown): e is ClientLogInput {
+  if (!e || typeof e !== "object") return false;
+  const o = e as Record<string, unknown>;
+  return typeof o.message === "string" && typeof o.level === "string" && LEVELS.has(o.level);
+}
+
+export async function logRoutes(app: FastifyInstance, logService: LogService): Promise<void> {
+  // INGEST — accept one entry or a small batch ({ entries: [...] }). Returns 204.
+  // Deliberately tolerant: it never 4xx's on a malformed entry (a client erroring
+  // while reporting an error shouldn't get a second error) — invalid items are skipped.
+  app.post<{ Body: ClientLogInput | { entries?: unknown[] } }>(
+    "/api/logs",
+    { preHandler: requireAuth },
+    async (req, reply) => {
+      const body = req.body as ClientLogInput | { entries?: unknown[] };
+      const raw = Array.isArray((body as { entries?: unknown[] }).entries)
+        ? (body as { entries: unknown[] }).entries
+        : [body];
+      const userId = req.user?.sub ?? null;
+      const userAgent = req.headers["user-agent"] ?? null;
+      for (const entry of raw.slice(0, MAX_BATCH)) {
+        if (!isValidEntry(entry)) continue;
+        logService.recordClient(entry, { userId, userAgent });
+      }
+      reply.code(204).send();
+    },
+  );
+
+  // READ — newest first, with optional level/source/since filters + a limit. The
+  // booth Logs viewer calls this. Gated by log:read.
+  app.get<{ Querystring: { limit?: string; level?: string; source?: string; since?: string } }>(
+    "/api/logs",
+    { preHandler: requirePermission("log:read") },
+    async (req): Promise<{ logs: AppLogRecord[] }> => {
+      const limit = Math.min(Math.max(Number(req.query.limit) || 200, 1), 2000);
+      const level = (req.query.level ?? "").trim();
+      const source = (req.query.source ?? "").trim();
+      const since = (req.query.since ?? "").trim();
+      const logs = logService.query({
+        limit,
+        level: LEVELS.has(level) ? (level as LogLevel) : undefined,
+        source: source === "frontend" || source === "backend" ? source : undefined,
+        since: since || undefined,
+      });
+      return { logs };
+    },
+  );
+}
@@ -17,6 +17,8 @@ import { CredentialCapture } from "./credential-capture.js";
 import { PrinterMonitor } from "./printer-monitor.js";
 import { DeviceMonitor } from "./device-monitor.js";
 import { buildSigner, buildVerifier } from "./signer.js";
+import { LogService, pinoDbStream } from "./log-service.js";
+import { logRoutes } from "./routes/logs.js";
 import { authRoutes } from "./routes/auth.js";
 import { userRoutes } from "./routes/users.js";
 import { roleRoutes } from "./routes/roles.js";
@@ -43,12 +45,20 @@ export interface BuildOptions {
 }

 export async function buildServer(opts: BuildOptions = {}): Promise<FastifyInstance> {
-  const app = Fastify({
-    logger: { level: process.env.LOG_LEVEL ?? "info" },
-  });
-
+  // DB first — the logger's DB sink needs it before Fastify is constructed.
  const db = opts.db ?? createDb();

+  // Application-log store: a pino stream tees warn+ lines into app_logs (and still
+  // writes them to stdout), so backend warnings/errors are queryable from the booth
+  // alongside frontend errors. See log-service.ts + wiki/concepts/app-logs.md.
+  const logService = new LogService(db);
+  const app = Fastify({
+    logger: {
+      level: process.env.LOG_LEVEL ?? "info",
+      stream: pinoDbStream(logService, process.stdout),
+    },
+  });
+
  // Wire the RBAC permission resolver to this DB (route guards resolve a user's
  // role → permission set through it). See auth.ts.
  initAuth(db);
@@ -188,6 +198,20 @@ export async function buildServer(opts: BuildOptions = {}): Promise<FastifyInsta
  // at capacity) is in the entry flow. See wiki/concepts/capacity-occupancy.md.
  await siteRoutes(app, db);

+  // Application logs: ingest frontend errors (POST /api/logs, any signed-in user) +
+  // read the store (GET /api/logs, log:read). See wiki/concepts/app-logs.md.
+  await logRoutes(app, logService);
+
+  // Periodic retention prune (age + row cap) so the log table stays bounded on the
+  // offline appliance. Runs hourly; unref'd so it never holds the process open.
+  const pruneTimer = setInterval(() => {
+    const n = logService.prune();
+    if (n > 0) app.log.debug(`pruned ${n} app_log rows`);
+  }, 60 * 60 * 1000);
+  pruneTimer.unref();
+  logService.prune(); // once at startup
+  app.addHook("onClose", async () => clearInterval(pruneTimer));
+
  const unsubscribeInput = deviceEvents.onInput((e) => {
    // Record every input edge as unsigned telemetry, keyed to the device that fired
    // (provenance). No lane — the pool-of-spaces model has none. The entry flow