From c21babf293f30cbba12c98041ab78d36a5515649 Mon Sep 17 00:00:00 2001 From: Julian Cuni Date: Sat, 4 Jul 2026 19:47:53 +0200 Subject: [PATCH] feat(logging): ~2-month container rotation, ISO timestamps, level names MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Operator asked for bounded container logs (~2 months of history), human- readable timestamps, and clarity on levels. Levels already existed (LOG_LEVEL env → pino, default info; warn+ teed into app_logs, queryable at /setup/logs) — the "level":30 / epoch-ms "time" in docker logs were pino defaults. - server.ts logger: stamp ISO-8601 UTC time (timestamp fn) and level NAMES (formatters.level) so `docker logs` reads human. - log-service.ts pinoDbStream: accept BOTH level encodings (name + numeric) — the label switch would otherwise have silently stopped warn+ persistence into app_logs. New log-service-stream.test.ts pins both encodings, the info-stays-stdout-only rule, and the never-throws fallback. - docker-compose.prod.yml: json-file caps resized from 10m×3 (≈30 MB — days, not months) to ≈2 months by volume: server 20m×30, vision 20m×10, proxy 10m×5. json-file rotates by SIZE; time-based isn't a driver feature — comment says to revisit if `docker logs` holds under ~60 days. - app_logs retention default aligned 30→60 days (LOG_RETENTION_DAYS still overrides). Wiki: app-logs.md gains the container-log store section (rotation, format, LOG_LEVEL knob) + retention update; log.md entry. Suite 282 green. Claude-Session: https://claude.ai/code/session_01Xcm6ikLgGoCxxHrxtjkk5V --- apps/server/src/log-service-stream.test.ts | 54 ++++++++++++++++++++++ apps/server/src/log-service.ts | 21 ++++++--- apps/server/src/server.ts | 7 +++ docker-compose.prod.yml | 18 ++++++-- wiki/concepts/app-logs.md | 25 ++++++++-- wiki/log.md | 10 ++++ 6 files changed, 120 insertions(+), 15 deletions(-) create mode 100644 apps/server/src/log-service-stream.test.ts diff --git a/apps/server/src/log-service-stream.test.ts b/apps/server/src/log-service-stream.test.ts new file mode 100644 index 0000000..469c83d --- /dev/null +++ b/apps/server/src/log-service-stream.test.ts @@ -0,0 +1,54 @@ +import { beforeEach, describe, expect, it } from "vitest"; +import { appLogs, type Db } from "@parking/db"; +import { createTestDb } from "@parking/db/testing"; +import { LogService, pinoDbStream } from "./log-service.js"; + +// pinoDbStream feeds backend warn+ lines into app_logs. Since 2026-07-04 the logger +// emits level NAMES ("warn") instead of pino's numeric codes (40) — for human-readable +// container logs — and the stream must accept BOTH encodings (numeric covers any +// default-configured pino). A level the tee can't resolve falls back to info → not +// persisted, never a crash. + +let db: Db; +let stream: { write: (line: string) => void }; +let teed: string[]; + +beforeEach(() => { + ({ db } = createTestDb()); + teed = []; + stream = pinoDbStream(new LogService(db), { + write: (line: string) => { + teed.push(line); + return true; + }, + } as unknown as NodeJS.WritableStream); +}); + +const rows = () => db.select().from(appLogs).all(); + +describe("pinoDbStream level encodings", () => { + it("persists a LABEL-level warn line (the current logger format)", () => { + stream.write(`{"level":"warn","time":"2026-07-04T18:14:11.453Z","msg":"label warn"}\n`); + expect(rows()).toHaveLength(1); + expect(rows()[0]).toMatchObject({ level: "warn", source: "backend", message: "label warn" }); + }); + + it("still persists a NUMERIC-level error line (legacy/default pino)", () => { + stream.write(`{"level":50,"time":1783179038453,"msg":"numeric error"}\n`); + expect(rows()[0]).toMatchObject({ level: "error", message: "numeric error" }); + }); + + it("info stays stdout-only in both encodings (teed, not persisted)", () => { + stream.write(`{"level":"info","msg":"label info"}\n`); + stream.write(`{"level":30,"msg":"numeric info"}\n`); + expect(rows()).toHaveLength(0); + expect(teed).toHaveLength(2); // stdout tee always happens + }); + + it("an unresolvable level falls back to info (dropped), never throws", () => { + stream.write(`{"level":"loud","msg":"weird"}\n`); + stream.write(`not json at all\n`); + expect(rows()).toHaveLength(0); + expect(teed).toHaveLength(2); + }); +}); diff --git a/apps/server/src/log-service.ts b/apps/server/src/log-service.ts index 2be170e..df4a59b 100644 --- a/apps/server/src/log-service.ts +++ b/apps/server/src/log-service.ts @@ -33,7 +33,10 @@ export interface LogRetention { } export const DEFAULT_RETENTION: LogRetention = { - maxAgeDays: Number(process.env.LOG_RETENTION_DAYS ?? 30), + // 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), }; @@ -192,9 +195,10 @@ export class LogService { /** * 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. + * 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, @@ -218,12 +222,17 @@ export function pinoDbStream( } try { const obj = JSON.parse(line) as { - level?: number; + level?: number | string; msg?: string; err?: { stack?: string; message?: string }; [k: string]: unknown; }; - const level = NUM_TO_LEVEL[obj.level ?? 30] ?? "info"; + // 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; diff --git a/apps/server/src/server.ts b/apps/server/src/server.ts index 056c56c..0993bf8 100644 --- a/apps/server/src/server.ts +++ b/apps/server/src/server.ts @@ -71,7 +71,14 @@ export async function buildServer(opts: BuildOptions = {}): Promise `,"time":"${new Date().toISOString()}"`, + formatters: { level: (label) => ({ level: label }) }, stream: pinoDbStream(logService, process.stdout), }, }); diff --git a/docker-compose.prod.yml b/docker-compose.prod.yml index 2c8919f..b35907c 100644 --- a/docker-compose.prod.yml +++ b/docker-compose.prod.yml @@ -26,11 +26,12 @@ services: - caddy-config:/config depends_on: - server + # ≈2 months (see the server note): Caddy logs errors only — 10 MB × 5 is plenty. logging: driver: json-file options: max-size: "10m" - max-file: "3" + max-file: "5" server: restart: always @@ -73,11 +74,17 @@ services: - /dev/usb:/dev/usb device_cgroup_rules: - "c 180:* rmw" + # LOG ROTATION (2026-07-04). Docker's json-file driver rotates by SIZE, not time — + # these caps are sized to hold ≈2 MONTHS at observed booth rates (the operator's + # chosen diagnostic window; revisit if `docker logs` shows less than ~60 days of + # history). Server gets the most (request + device chatter): 20 MB × 30 = 600 MB + # ceiling. NB: `docker logs` only reaches back as far as these files. The queryable + # warn+ store (app_logs, /setup/logs) has its own matching 60-day retention. logging: driver: json-file options: - max-size: "10m" - max-file: "3" + max-size: "20m" + max-file: "30" vision: restart: always @@ -89,11 +96,12 @@ services: VISION_RECOGNIZER: fast_alpr ports: - "127.0.0.1:8089:8089" + # ≈2 months (see the server note): vision logs less — 20 MB × 10 = 200 MB ceiling. logging: driver: json-file options: - max-size: "10m" - max-file: "3" + max-size: "20m" + max-file: "10" volumes: caddy-data: diff --git a/wiki/concepts/app-logs.md b/wiki/concepts/app-logs.md index 9ab0eba..7dec8ec 100644 --- a/wiki/concepts/app-logs.md +++ b/wiki/concepts/app-logs.md @@ -2,7 +2,7 @@ type: concept tags: [parking, observability, diagnostics, logging, frontend, backend] sources: [] -updated: 2026-06-19 +updated: 2026-07-04 status: open --- @@ -66,9 +66,26 @@ column — the failed request, error name, component stack, anything), plus pull ## Retention (offline appliance ⇒ must be bounded) Pruned by **age AND a row cap** (a burst could blow past an age-only window): delete older than -`LOG_RETENTION_DAYS` (default 30) **and** keep only the newest `LOG_RETENTION_MAX_ROWS` (default -50 000). Runs **hourly** (unref'd timer) + once at startup. Both env-configurable. Same "prunable, -not precious" durability class as `device_events` — the opposite of the append-only ledger. +`LOG_RETENTION_DAYS` (default **60** — the operator's ≈2-month diagnostic window, 2026-07-04; +was 30) **and** keep only the newest `LOG_RETENTION_MAX_ROWS` (default 50 000). Runs **hourly** +(unref'd timer) + once at startup. Both env-configurable. Same "prunable, not precious" +durability class as `device_events` — the opposite of the append-only ledger. + +## Container (stdout) logs — the OTHER log store (2026-07-04) + +`docker logs` is a separate, size-bounded store from `app_logs` — it holds **everything** +(info/debug too), while `app_logs` keeps only warn+. Three knobs, all set 2026-07-04: + +- **Rotation:** Docker's json-file driver rotates by SIZE, not time; the caps in + `docker-compose.prod.yml` are sized to hold **≈2 months** at observed booth rates (server + 20 MB × 30, vision 20 MB × 10, proxy 10 MB × 5). `docker logs` reaches back only that far — + revisit the caps if it shows under ~60 days. (Dev compose is uncapped — laptop concern only.) +- **Human-readable lines:** the pino logger stamps **ISO-8601 UTC** `time` (was epoch-ms) and + **level NAMES** (`"warn"`, was `40`) via `timestamp` + `formatters.level` in `server.ts`. + `pinoDbStream` accepts BOTH level encodings, so the app_logs tee survives either config. +- **Level knob:** `LOG_LEVEL` env (trace|debug|info|warn|error|fatal; default `info`) — a booth + under diagnosis runs `LOG_LEVEL=debug` with no code change; warn+ persistence is unaffected + (it filters independently in the tee). ## The booth viewer diff --git a/wiki/log.md b/wiki/log.md index 6d743b2..acad2c3 100644 --- a/wiki/log.md +++ b/wiki/log.md @@ -2272,3 +2272,13 @@ card, unknown SUB- code) still signs the normal anomaly; enrolled credentials ma filter and can never be hidden by it. Works for legacy unprefixed reads too, so the feed cleans up before the vendor-tool visit. 6 new tests; suite 278 green. Also this session: reader channel tagging (clone defense) — see the prior entry. + +## [2026-07-04] update | Logging: 2-month rotation, ISO timestamps, level names + +Operator asked for bounded container logs (~2 months), human-readable timestamps, and clarity on +levels. Findings + changes on [[app-logs]]: levels EXISTED (LOG_LEVEL env, pino, warn+ teed to +app_logs); the "level":30 numbers and epoch-ms times were pino defaults — the logger now stamps +ISO-8601 UTC + level names (pinoDbStream hardened to accept both encodings so the DB tee can't +silently break). Rotation: docker json-file caps in docker-compose.prod.yml resized from 10m×3 +(≈30 MB!) to ≈2 months by volume (server 20m×30, vision 20m×10, proxy 10m×5; json-file rotates by +SIZE — time-based isn't a driver feature). app_logs retention default aligned 30→60 days.