Skip to content

Feat: Enable LOG_LEVEL and LOG_FORMAT for 'historic' console.log/warn/error logging - #178

Open
mrramam wants to merge 2 commits into
jherforth:mainfrom
mrramam:feat/console-shim-log-format
Open

mrramam wants to merge 2 commits into
jherforth:mainfrom
mrramam:feat/console-shim-log-format

Conversation

@mrramam

@mrramam mrramam commented Sep 15, 2026

Copy link
Copy Markdown
Contributor

The problem

The database connection is opened with { verbose: console.log }, unconditionally, so every SQL statement the server runs is printed. On a Pi with one family calendar that measured ~8,450 journal lines per 15-minute sync cycle. That is 32 MB per 12 hours, enough to roll a 1 GB journald cap in about two days.

It is also a disclosure. better-sqlite3's verbose hook receives the expanded statement with bound values inlined, so calendar event titles and locations land in the journal in the clear. Parameterized statements do not protect the log.

There was no way to turn it down. No LOG_LEVEL existed, and the hook writes through console.log without touching Fastify's logger, so a Fastify level could not have suppressed it either.

What this changes

LOG_LEVEL, using pino's own vocabulary since Fastify's logger is pino: trace, debug, info, warn, error, fatal, silent. Default is warn, not pino's info. HomeGlow runs unattended on a display whose kiosk polls continuously, and a log nobody reads daily is most useful holding things that describe a problem.

SQL tracing moves to debug. The verbose hook is attached only when the level would emit it, because passing the hook at all makes the driver expand every statement whether or not anything consumes the result.

The global console is routed through the logger. The server has ~386 console.log/warn/error calls written over a year, and at every one of them the author already chose a severity by picking the method. This honors those choices. Each method maps to the level of the same name, so LOG_LEVEL governs all of it with no call-site changes. Arguments are flattened with util.format first: pino drops trailing arguments when the message has no placeholders, so a bare logger.info(msg, obj) would silently lose obj. This is an adoption shim, not an architecture; migration to explicit logger calls can proceed file by file, or never.

LOG_FORMAT: pretty (default) or json. Pretty drops pid and hostname since journald already stamps them, and keeps one event per line. json is for anyone feeding a pipeline. Adds pino-pretty.

Calendar sync logs at real levels: chatter at debug, a per-source summary at info, a missing source at warn, failures at error. A sync that breaks is still visible at the default, where before it was buried under ten lines a second of SQL.

The preHandler that printed Incoming request: per request is removed. Fastify's logger already emits incoming and completed lines with request id, status and duration, and obeys the level; the hook was a second, poorer copy no level could switch off.

Worth knowing

  • At the default, a healthy boot prints nothing. Server running on port, Calendar sync service started and Fastify's own Server listening are all info. That is consistent and deliberate; /api/stats is the health check. Promoting a banner line to warn would misstate its severity.
  • A successful sync is silent at the default; only failures surface. LOG_LEVEL=info brings back the per-sync summary, and per-request logging with it.
  • Patching console is global: dependencies' console output obeys the level too. A reader who sees console.error in this codebase should know it is not writing to stderr.
  • An invalid LOG_LEVEL or LOG_FORMAT falls back and says so at warn, so a misspelling is distinguishable from a value that worked.
  • Not addressed here: the raw-rows dumps on GET /api/settings still print secret values whenever the level is info. That is a separate fix (remove the values), not a level.

Testing

23 tests across logLevel, logFormat and consoleShim. The ones that matter: at debug the driver is shown to echo bound values (the positive control), and at every quieter level nothing is captured; and console.log('Raw settings:', rows) keeps rows through the shim, the case a naive rewrite would lose.

Measured on the built image, 30 requests each: default 1 line (dotenv's, pre-shim); info 78; debug 127 with 49 SQL statements. Running on my own instance since 2026-09-15; a full sync cycle and 60 requests produced one journal line.

mrramam added 2 commits September 15, 2026 12:18
…default

The database connection was opened with `{ verbose: console.log }`
unconditionally, so every statement the process executed was printed. On a
production Pi that measured ~6,700 statements/hour and 32MB of journal per 12
hours, enough to roll a 1GB cap in about two days.

It is also a disclosure. better-sqlite3's `verbose` hook receives the expanded
SQL with bound parameters inlined, and the calendar cache insert binds
`JSON.stringify(event.raw)` -- the unmodified upstream event. So event titles,
locations, attendees, organiser addresses and descriptions all reached the log.
Parameterised statements do not protect it.

There was no way to turn this down: no LOG_LEVEL existed, and the hook writes
to stdout through console.log without passing Fastify's logger, so a Fastify
level could not have suppressed it either.

Add LOG_LEVEL using pino's own vocabulary, since Fastify's logger is pino:
trace, debug, info, warn, error, fatal, silent. SQL tracing moves to debug --
the only level at which that volume is reasonable -- and the hook is attached
only when the level would emit it, because passing `verbose` at all makes the
driver expand every statement whether or not anything consumes the result.

Default to warn rather than pino's info. HomeGlow runs unattended on a display
whose kiosk polls continuously; a log nobody reads daily is most useful holding
things that describe a problem. Calendar sync now logs at levels that respect
that: per-cycle chatter at debug, a per-source summary at info, a missing or
disabled source at warn, and failures at error -- so a sync that breaks is
still visible at the default, where previously it was buried under ten lines a
second of SQL.

Also remove the preHandler hook that printed "Incoming request" per request.
Fastify's logger already emits incoming and completed lines with request id,
status and duration, and obeys LOG_LEVEL; the hook was a second, poorer copy no
level could switch off. Boot plus 40 requests goes from 48 log lines to 7.

An unparseable LOG_LEVEL falls back to warn and says so at warn, so a
misspelling is distinguishable from a value that worked.
…RMAT

LOG_LEVEL governed only the two places that called fastify.log. The other
386 console.* calls in the server -- written by fourteen contributors over a
year, none of whom adopted a logger -- wrote straight to stdout and stderr,
and no level could touch them. At the default, a healthy boot still printed
seven lines and every settings fetch printed a hundred.

Rather than rewrite those sites, honour the decision already made at each
one. Every author chose console.error, .warn or .log; that IS a severity.
Patch the global console so each method routes to fastify.log at the level
of the same name, and every one of those calls obeys LOG_LEVEL at once, with
no diff at the call sites. Dependencies' console output comes along too.

Arguments are flattened with util.format before reaching pino. pino treats
trailing arguments as printf interpolation values and drops them when the
message has no placeholders, so a bare logger.info(msg, obj) would silently
lose obj -- and `console.log('Raw settings:', rows)` would log the label and
nothing else. util.format is what console itself does, so output is
byte-identical to before, now with a level attached.

This is an adoption shim, not an architecture. Migration to explicit logger
calls can proceed file by file, or not at all; the shim covers whatever has
not been converted, and comes out in one place when nothing is left.

Add LOG_FORMAT alongside: `pretty` (default) or `json`. pino's own default is
JSON, and the reversal is deliberate. HomeGlow runs on a Pi under journald,
and the usual reader is a person with journalctl open, not a pipeline.
journald already stamps time, host and pid, so those fields are dropped from
pretty output, and singleLine keeps one journal entry per event -- without
it, pino-pretty renders each object field on its own indented line and a
single request log becomes seven rows.

Consequence, accepted on purpose: at the default level a healthy boot prints
nothing. `Server running on port`, `Calendar sync service started` and
Fastify's own `Server listening` are all info. /api/stats is the health
check. Promoting a banner line to warn to buy comfort would be a lie about
severity.

An invalid LOG_FORMAT falls back to pretty and says so at warn, matching
LOG_LEVEL's behaviour.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Backlog

Development

Successfully merging this pull request may close these issues.

1 participant