julian
22544ecf63
button-light-indicator: failure backoff + rate-limited logging rationale; app-logs: storm coalescing invariant + --diagnostics wipe; local-dev-workflow and appliance-provisioning §7d: new reset flag table + drift guard; log entry tying all three layers to the ENETUNREACH incident. Claude-Session: https://claude.ai/code/session_01Xcm6ikLgGoCxxHrxtjkk5V
133 lines
8.3 KiB
Markdown
133 lines
8.3 KiB
Markdown
---
|
||
type: concept
|
||
tags: [parking, observability, diagnostics, logging, frontend, backend]
|
||
sources: []
|
||
updated: 2026-07-08
|
||
status: open
|
||
---
|
||
|
||
# Application logs (diagnostics) — the third stream
|
||
|
||
A **third data stream**, deliberately distinct from the two in [[event-streams-split]]:
|
||
|
||
| Stream | Table | Signed? | Purpose |
|
||
| --- | --- | --- | --- |
|
||
| Business ledger | `ledger_events` | ✅ ATECC608 | money/accountability ([[append-only-event-chain]]) |
|
||
| Device telemetry | `device_events` | ❌ | hardware chatter ([[device-events]]) |
|
||
| **App logs** | **`app_logs`** | ❌ | **operational/diagnostic logs** (this page) |
|
||
|
||
App logs answer *"why did the booth misbehave?"* — a question neither of the other streams should
|
||
absorb (logs are neither business facts nor hardware telemetry). On an **offline appliance** there's
|
||
no Sentry/Datadog to ship to, so the host **is** the log store: backend warnings/errors AND frontend
|
||
errors land in one queryable table, viewable at the booth. Built 2026-06-19.
|
||
|
||
## What's captured
|
||
|
||
- **Backend `warn` / `error` / `fatal`** — a pino stream tees these into `app_logs` (and still writes
|
||
them to stdout, unchanged). `info`/`debug`/`trace` stay **stdout-only** — they'd bloat the DB. So
|
||
every `app.log.warn/error(...)` already in the codebase is now persisted with **no call-site
|
||
change**.
|
||
- **Frontend errors** (always): every **failed API request** (`apiFetch`'s non-OK path → method,
|
||
path, status, server error body — except `401`, which is normal pre-login churn), every **uncaught
|
||
error** (`window.onerror`), every **unhandled promise rejection**, and a top-level **React
|
||
ErrorBoundary** (a render crash is reported as `fatal` instead of a white screen).
|
||
- **`console.warn` / `console.error`** — only forwarded when the **client log level is `debug`/`trace`**
|
||
(off by default; they're noisy with third-party chatter). The high-signal sources above are always
|
||
on. Toggle via `VITE_LOG_LEVEL` / `setClientLogLevel()`.
|
||
|
||
## Shape
|
||
|
||
`app_logs`: `level` (pino names), `source` (`frontend`|`backend`), `message`, `context` (one JSON
|
||
column — the failed request, error name, component stack, anything), plus pulled-out `httpStatus` /
|
||
`path` for cheap filtering, `stack`, `userId`, `userAgent`, `createdAt`. Indexed on `created_at` +
|
||
`level`. Shared types: `AppLogRecord` / `ClientLogInput` / `LogLevel` in `@parking/shared`.
|
||
|
||
## The API + the access split
|
||
|
||
- **`POST /api/logs`** — the frontend ships errors here. **Any signed-in user** may write (it's their
|
||
own browser's diagnostics) — `requireAuth`, not a permission. CSRF still applies (it's a mutation).
|
||
Accepts one entry or a `{ entries: [...] }` batch (capped at 50). **Deliberately never 4xx's on a
|
||
malformed entry** — a client erroring *while reporting an error* must not get a second error.
|
||
- **`GET /api/logs`** — read the store (level/source/since filters), gated by the **new `log:read`
|
||
permission** (a new `log` resource in the dynamic [[local-jwt-auth|RBAC]] grid). Admin holds it;
|
||
it's grantable to a diagnostic role. *Verified: a cashier without `log:read` gets 403 on GET but
|
||
204 on POST — the intended asymmetry.*
|
||
|
||
## Reliability invariants (a logger must never make things worse)
|
||
|
||
- **No infinite loop.** The frontend collector never logs the `/api/logs` request itself, and flushes
|
||
via **raw `fetch`/`sendBeacon`**, not `apiFetch` (so a flush failure can't recurse into a new log).
|
||
The backend `LogService` has a **reentrancy guard** — persisting a log can't emit a persisted log.
|
||
- **Best-effort, never fatal.** Every write is wrapped; a DB/logging failure is swallowed (it can't be
|
||
logged — that's the recursion we guard). Diagnostics must never break the path they observe.
|
||
- **Bounded.** Frontend queue capped (drops oldest); message/stack/context clamped per row;
|
||
ingest batch capped.
|
||
- **Storm coalescing (2026-07-08).** A line identical to the *last persisted row*
|
||
(level+source+message+path) arriving within **5 min** of its previous occurrence **updates that
|
||
row** instead of inserting: `context._repeat` counts the fold, `context._firstAt` keeps the first
|
||
occurrence, `createdAt` moves to the latest (so the storm stays at the top of the newest-first
|
||
viewer, which badges it `×N`). A *continuous* storm refreshes the window each hit, so it stays ONE
|
||
row however long it rages. Motivation: the 2026-07-07 field incident — one unreachable controller
|
||
(`ENETUNREACH`) produced hundreds of identical error rows per minute, evicting unrelated history
|
||
(see [[button-light-indicator]] for the send-side fix: retry backoff + rate-limited logging).
|
||
In-memory last-row cache only (a restart just starts a fresh row); if the row was pruned
|
||
underneath, it falls through to a fresh insert.
|
||
|
||
## 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 **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.
|
||
|
||
Also wipeable on demand: `reset-db.mjs --diagnostics` (new category 2026-07-08 — `app_logs`
|
||
previously belonged to NO category and silently survived even `--all`; a drift guard in the script
|
||
now refuses to run if any table is uncategorized). See [[local-dev-workflow]].
|
||
|
||
## 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
|
||
|
||
A **Logs screen** under Setup (`/setup/logs`, gated by `log:read`, sq+en) — filter by
|
||
level/source/since, newest first, each row expands to the structured `context` + stack. Read-only
|
||
(logs are evidence, never edited). Polls every 15 s (no WS — diagnostics aren't latency-critical).
|
||
Sits alongside the other admin tabs in [[booth-console]].
|
||
|
||
## As-built (2026-06-19)
|
||
|
||
- `packages/db`: `app_logs` table + migration `0009_app_logs.sql` (+ journal idx 9; seeds admin
|
||
`log:read`). Applied to the live `apps/server/parking.sqlite`.
|
||
- `@parking/shared`: `log` resource + `log:read` permission; `LogLevel`/`LogSource`/`AppLogRecord`/
|
||
`ClientLogInput`/`LOG_LEVEL_ORDER`.
|
||
- `apps/server`: `log-service.ts` (`LogService` + `pinoDbStream`), `routes/logs.ts`, wired in
|
||
`server.ts` (DB built before Fastify so the pino stream has the sink; prune timer).
|
||
- `apps/web`: `lib/logger.ts` (collector + global handlers), `lib/ErrorBoundary.tsx`, `apiFetch` hook,
|
||
`LogsViewer.tsx` + route/nav, i18n.
|
||
|
||
## Open
|
||
|
||
- **No automated test** (the standing harness gap) — though the ingest/read/gate path was verified by
|
||
in-process `app.inject` smoke (login → POST 204 → GET 200 with the record; non-admin 403/204 split).
|
||
- **Server API error strings stay English** — unchanged here; this is about *persisting* logs, not
|
||
localizing them. The localized-ledger-reason pattern ([[i18n]]) is the template if log *display*
|
||
ever needs translation (currently the message is whatever the thrower wrote).
|
||
- **Surfacing critical logs live** — a `fatal`/`error` count badge on the booth footer over the
|
||
existing `/api/ws` could flag problems without opening the viewer. Deferred.
|
||
- **Correlation id** — no request-id threads a frontend failed-request log to its backend log yet;
|
||
add a `x-request-id` echo if cross-stream correlation is wanted.
|