feat: durable log4cl-backed logging facility (stdout default, init-file sinks) #78

Merged

nsaspy merged 3 commits from feat/durable-logging into main

2026-09-08 13:20:57 +00:00

nsaspy commented

2026-09-08 09:36:55 +00:00

Owner

Closes #77.

What

One coherent logging facility for Quasar, built on log4cl, replacing the mix of diagnostic-log-to-stderr and scattered raw format writes.

quasar.log package (control-plane/src/logging.lisp): structured log-event API — level, subsystem, event, structured fields. Keeps the historical control-plane command.received / workspace operation.begin vocabulary verbatim, plus app start/start-failed/stop, websocket server.listening, connection.accepted, handshake.rejected, command.crashed, subscriber.failed and friends.
Default = stdout: the historical [quasar] ISO8601Z LEVEL subsystem event key=value text layout on *standard-output*; no files created unless configured. npm run dev keeps showing server output (dev.mjs pipes child stdout).
Durable sink: :file opens the log append-only (survives restarts), one JSON object per line (timestamp, level, subsystem, event, message, fields, lifted request_id/workspace_id), immediate flush per record by default (SIGKILL loses at most the in-flight record), interval flush available for throughput, flush+close on shutdown (SIGINT/SIGTERM path).
Concurrency safety: log4cl serialized appenders lock each record; 4-thread × 100-event test proves line-complete, parseable records with no interleaving.
Failure containment: a failing sink is reported and detached by log4cl's appender error path — the caller (and Quasar) never sees logging errors; covered by a test.
Init-file config surface (extends the existing quasar.config system, no parallel mechanism): *log-sink* (:stdout/:stderr/:file/:off), *log-file-path* (nil → $XDG_DATA_HOME/quasar/logs/quasar.log), *log-level* (nil → QUASAR_LOG_LEVEL → CI→info → debug), *log-file-format* (:json/:text), *log-immediate-flush*. Invalid values abort startup with a clear error before any sink state changes (fail closed, like the rest of the init file).
Routing: control-plane dispatch crashes, subscriber failures, and all websocket-server diagnostics now flow through the facility; diagnostic-log remains as a compatibility alias; QUASAR_LOG_LEVEL semantics unchanged.
Performance harness: npm run bench:logging — per-event µs and bytes for stdout text, durable JSON (immediate + interval flush), and the filtered path (reference numbers in the issue comment; e.g. stdout 4.4 µs/event, filtered 0.07 µs/event).
Docs: docs/CONFIGURATION.md gains a Logging section (defaults, init-file examples, durability guarantees, file locations, systemd/container recommendations); example_configs/init.lisp gains commented examples.

Testing

control-plane/tests/logging-tests.lisp: 14 focused tests — stdout default, init override to file, level filtering, structured fields (text+JSON), concurrency line-completeness, restart persistence, flush/shutdown, sink failure, invalid config fail-closed, dispatch/workspace event vocabulary compatibility, level precedence.
Full Lisp suite (quasar-tests incl. all subsystem runners) verified against this branch's sources: pass (0 failures on a clean run; one intermittent pre-existing melissa-tests pending-stop timing race reproduces on main).
node scripts/check-control-plane-deps.mjs: pass.
Frontend: unit 73 files / 360 tests pass; integration pass. npm run smoke: pass.
End-to-end launcher verification: 45 structured log lines on stdout, 0 on stderr.

Notes / limitations

Log4cl daily rotation is available if a deployment needs it; not wired by default (YAGNI).
On machines where ~/quicklisp/local-projects/ holds symlinks to another quasar checkout, quicklisp's scan can shadow the repo's own systems/ resolution (pre-existing, reproduces on main); noted in the issue for a future hardening pass.

Closes #77. ## What One coherent logging facility for Quasar, built on log4cl, replacing the mix of `diagnostic-log`-to-stderr and scattered raw `format` writes. - **`quasar.log` package** (`control-plane/src/logging.lisp`): structured `log-event` API — level, subsystem, event, structured fields. Keeps the historical `control-plane command.received` / `workspace operation.begin` vocabulary verbatim, plus `app start/start-failed/stop`, `websocket server.listening`, `connection.accepted`, `handshake.rejected`, `command.crashed`, `subscriber.failed` and friends. - **Default = stdout**: the historical `[quasar] ISO8601Z LEVEL subsystem event key=value` text layout on `*standard-output*`; no files created unless configured. `npm run dev` keeps showing server output (dev.mjs pipes child stdout). - **Durable sink**: `:file` opens the log append-only (survives restarts), one JSON object per line (`timestamp`, `level`, `subsystem`, `event`, `message`, `fields`, lifted `request_id`/`workspace_id`), immediate flush per record by default (`SIGKILL` loses at most the in-flight record), interval flush available for throughput, flush+close on shutdown (SIGINT/SIGTERM path). - **Concurrency safety**: log4cl serialized appenders lock each record; 4-thread × 100-event test proves line-complete, parseable records with no interleaving. - **Failure containment**: a failing sink is reported and detached by log4cl's appender error path — the caller (and Quasar) never sees logging errors; covered by a test. - **Init-file config surface** (extends the existing `quasar.config` system, no parallel mechanism): `*log-sink*` (`:stdout`/`:stderr`/`:file`/`:off`), `*log-file-path*` (nil → `$XDG_DATA_HOME/quasar/logs/quasar.log`), `*log-level*` (nil → `QUASAR_LOG_LEVEL` → CI→info → debug), `*log-file-format*` (`:json`/`:text`), `*log-immediate-flush*`. Invalid values abort startup with a clear error before any sink state changes (fail closed, like the rest of the init file). - **Routing**: control-plane dispatch crashes, subscriber failures, and all websocket-server diagnostics now flow through the facility; `diagnostic-log` remains as a compatibility alias; `QUASAR_LOG_LEVEL` semantics unchanged. - **Performance harness**: `npm run bench:logging` — per-event µs and bytes for stdout text, durable JSON (immediate + interval flush), and the filtered path (reference numbers in the issue comment; e.g. stdout 4.4 µs/event, filtered 0.07 µs/event). - **Docs**: `docs/CONFIGURATION.md` gains a Logging section (defaults, init-file examples, durability guarantees, file locations, systemd/container recommendations); `example_configs/init.lisp` gains commented examples. ## Testing - `control-plane/tests/logging-tests.lisp`: 14 focused tests — stdout default, init override to file, level filtering, structured fields (text+JSON), concurrency line-completeness, restart persistence, flush/shutdown, sink failure, invalid config fail-closed, dispatch/workspace event vocabulary compatibility, level precedence. - Full Lisp suite (`quasar-tests` incl. all subsystem runners) verified against this branch's sources: pass (0 failures on a clean run; one intermittent pre-existing `melissa-tests` pending-stop timing race reproduces on `main`). - `node scripts/check-control-plane-deps.mjs`: pass. - Frontend: unit 73 files / 360 tests pass; integration pass. `npm run smoke`: pass. - End-to-end launcher verification: 45 structured log lines on stdout, 0 on stderr. ## Notes / limitations - Log4cl daily rotation is available if a deployment needs it; not wired by default (YAGNI). - On machines where `~/quicklisp/local-projects/` holds symlinks to another quasar checkout, quicklisp's scan can shadow the repo's own `systems/` resolution (pre-existing, reproduces on `main`); noted in the issue for a future hardening pass.

nsaspy added 3 commits

2026-09-08 09:36:55 +00:00

feat: durable log4cl-backed logging facility with stdout default e998164769

Add quasar.log on top of log4cl:

- structured log-event API (level, subsystem, event, fields) preserving
  the historical [quasar] ISO8601Z LEVEL subsystem event key=value text
  format and the command.*/operation.* event vocabulary
- text layout for console sinks and a JSON-lines layout for the durable
  file sink, with request_id/workspace_id lifted into dedicated fields
- sink selection (:stdout default, :stderr, :file, :off) plus level,
  file format, and flush policy configured through the existing
  quasar.config init-file variables; invalid configuration fails closed
  before any sink state changes
- durable file sink: append-only across restarts, immediate-flush by
  default, per-record locking from log4cl serialized appenders so
  concurrent Sento actors cannot interleave records, and appender error
  containment so sink failures never signal into callers
- flush-logs/shutdown-logging wired into quasar.app:stop and lifecycle
  events (app start/start-failed/stop) on the app paths
- scattered raw stderr format writes in control-plane, async
  control-plane dispatch, and websocket-server now route through the
  facility with structured events
- diagnostic-log remains as a compatibility alias
- 14 focused tests (sinks, filtering, fields, concurrency line
  completeness, restart persistence, flush/shutdown, sink failure,
  invalid config, vocabulary compat) plus log4cl in the quickload
  dependency contract guarded by check-control-plane-deps

Refs: #77

bench: logging performance harness for sinks and flush policies 30529b71d3

scripts/bench-logging measures per-event latency and allocation for
20000 events per scenario: the default stdout text sink, the durable
JSON file sink under immediate and interval flush policies, and the
level-filtered path. Exposed as npm run bench:logging.

Reference numbers on this machine (SBCL 2.6.6):
  stdout text (debug):           4.4 us/event, ~544 B/event
  file json (immediate flush):   6.7 us/event, ~1244 B/event
  file json (interval flush):    4.5 us/event, ~860 B/event
  filtered event (disabled):     0.07 us/event, ~96 B/event

Refs: #77

docs: logging configuration, durability guarantees, deployment guidance 886706bff7

Document the stdout default, the init-file logging surface, the
durable file sink's append/flush/interleave guarantees, level
precedence, file locations, systemd/container recommendations, and the
benchmark harness. example_configs/init.lisp gains commented logging
examples.

Refs: #77

nsaspy merged commit 505835ceb7 into main

2026-09-08 13:20:57 +00:00