diff --git a/docs/reference/configuration.md b/docs/reference/configuration.md index 9839c8f..b00726c 100644 --- a/docs/reference/configuration.md +++ b/docs/reference/configuration.md @@ -14,6 +14,8 @@ database). This page covers both. | `DB_PATH` | `server/data/tasks.db` | Override the SQLite file location. | | `ENCRYPTION_KEY` | _auto-generated_ | **Optional.** Key used to encrypt stored third-party credentials. If unset, one is generated on first start — see below. Set it only to supply your own key or share one across instances; must decode to 32 bytes (`openssl rand -base64 32`). Changing it after credentials are stored invalidates them. | | `NODE_ENV` | — | `production` / `development`. | +| `LOG_LEVEL` | `warn` | Logging verbosity, using pino's standard levels: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, `silent`. Governs **all** console output from the server — every `console.log`/`warn`/`error` in the code and its dependencies is routed through the logger at the matching level. At the default, a healthy boot prints nothing and only warnings and errors appear; `info` adds startup lines, a line per HTTP request and a per-source calendar sync summary. **`debug` and `trace` additionally echo every SQL statement**, with bound values expanded — high volume, and calendar titles, locations and raw event payloads end up in the log. Use them for local debugging, not on a family display. | +| `LOG_FORMAT` | `pretty` | `pretty` for human-readable lines (`[2026-09-15 20:29:56] WARN: …`), `json` for one pino JSON object per line. Default is `pretty` because the usual reader is a person with `journalctl` open, and journald already stamps time, host and pid. Use `json` when feeding a log pipeline. | | `HOMEGLOW_DISABLE_BACKGROUND_JOBS` | `0` | Set to `1` to disable the nightly chore-pruning cron (useful in tests). | | `HOMEGLOW_DISABLE_CALENDAR_SYNC` | `0` | Set to `1` to disable the calendar sync service. | | `DEMO_MODE` | `false` | Set to `true` to run a **public demo instance**: in-memory DB (wiped on stop), admin PIN disabled, sample data seeded and reset every 6h (incl. live demo calendar feeds and a static weather snapshot), and abuse-prone routes (uploads, CORS proxy, OAuth, calendar source management) return 403 — calendar sync only ever fetches the seeded demo feeds. See the [Demo Mode](../guides/demo-mode.md) guide. | diff --git a/server/index.js b/server/index.js index 3bfbd05..a4c89de 100644 --- a/server/index.js +++ b/server/index.js @@ -20,7 +20,41 @@ const demoBlocked = (reply) => { }; process.env.TZ = APP_TIMEZONE; -const fastify = require('fastify')({ logger: true }); +const { resolveLogLevel, isSqlTraceEnabled } = require('./utils/logLevel'); +const { resolveLogFormat, transportFor } = require('./utils/logFormat'); +const { installConsoleShim } = require('./utils/consoleShim'); + +// Both resolved before the logger exists, so a rejected value can be reported +// through the logger once it is up rather than vanishing. +const LOG_LEVEL_RESULT = resolveLogLevel(process.env.LOG_LEVEL); +const LOG_LEVEL = LOG_LEVEL_RESULT.level; +const LOG_FORMAT_RESULT = resolveLogFormat(process.env.LOG_FORMAT); +const LOG_FORMAT = LOG_FORMAT_RESULT.format; + +const fastify = require('fastify')({ + logger: { level: LOG_LEVEL, transport: transportFor(LOG_FORMAT) }, +}); + +// From here on, every console.* call in this process -- this file, the +// services, and dependencies -- goes through fastify.log at the level matching +// the method that was called, and therefore obeys LOG_LEVEL. See the note in +// utils/consoleShim.js for what that means when reading console.error below. +installConsoleShim(fastify.log); + +// Deliberately at warn: it survives the default level. An operator who +// mistyped one of these is precisely the person who will not see an info line. +if (LOG_LEVEL_RESULT.source === 'invalid') { + fastify.log.warn( + `LOG_LEVEL="${LOG_LEVEL_RESULT.rejected}" is not a log level; using "${LOG_LEVEL}". ` + + 'Valid: trace, debug, info, warn, error, fatal, silent.' + ); +} +if (LOG_FORMAT_RESULT.source === 'invalid') { + fastify.log.warn( + `LOG_FORMAT="${LOG_FORMAT_RESULT.rejected}" is not a log format; using "${LOG_FORMAT}". ` + + 'Valid: pretty, json.' + ); +} const Database = require('better-sqlite3'); const ical = require('ical-generator'); const node_ical = require('node-ical'); @@ -504,11 +538,13 @@ fastify.register(multipart, { }, }); -// Add a preHandler hook to log all incoming requests -fastify.addHook('preHandler', (request, reply, done) => { - console.log(`Incoming request: ${request.method} ${request.url}`); - done(); -}); +// Request logging is Fastify's own, not a hook of ours. Its logger already +// emits an "incoming request" and a "request completed" line per request, with +// the request id, status and duration attached -- and, unlike a console.log in +// a preHandler, it obeys LOG_LEVEL. The hook that used to live here printed a +// second, poorer copy that no level could switch off, which on a wall display +// polling continuously is a steady leak into the journal for no added +// information. Set LOG_LEVEL=info to see requests. // Serve static files for uploads. // @@ -1832,7 +1868,14 @@ async function ConnectOrCreateDb() { await fs.chmod(path.dirname(dbPath), 0o777); } - const newDb = new Database(dbPath, { verbose: console.log }); + // Statement tracing is attached only when the level would emit it. Passing + // `verbose` at all makes better-sqlite3 expand every statement's bound + // parameters into a string, so leaving it on and filtering downstream would + // still pay the cost -- and still put calendar titles, locations and the + // whole raw upstream payload into the log on the way past. + const newDb = isSqlTraceEnabled(LOG_LEVEL) + ? new Database(dbPath, { verbose: (sql) => fastify.log.debug({ sql }, 'sqlite statement') }) + : new Database(dbPath); newDb.pragma('foreign_keys = ON'); // WAL lets readers proceed while a writer is active (better-sqlite3 is still // single-threaded, but this avoids POSIX lock stalls across connections). @@ -6242,7 +6285,7 @@ const start = async () => { // fetched (SSRF guard). The seeded "Family Calendar" placeholder // (.invalid host) is skipped by the service itself. if (DEMO_MODE) { - calendarSyncService = new CalendarSyncService(db, decryptPassword); + calendarSyncService = new CalendarSyncService(db, decryptPassword, fastify.log); if (process.env.HOMEGLOW_DISABLE_CALENDAR_SYNC !== '1') { calendarSyncService.initialize(); console.log('Calendar sync enabled in demo mode (seeded demo feeds only; source management is demo-blocked)'); @@ -6250,7 +6293,7 @@ const start = async () => { console.log('Calendar sync jobs disabled in demo mode by HOMEGLOW_DISABLE_CALENDAR_SYNC=1 (cached events only)'); } } else if (process.env.HOMEGLOW_DISABLE_CALENDAR_SYNC !== '1') { - calendarSyncService = new CalendarSyncService(db, decryptPassword); + calendarSyncService = new CalendarSyncService(db, decryptPassword, fastify.log); calendarSyncService.initialize(); console.log('Calendar sync service started'); } else { diff --git a/server/package-lock.json b/server/package-lock.json index 588672e..2129ab6 100644 --- a/server/package-lock.json +++ b/server/package-lock.json @@ -20,7 +20,8 @@ "ical-generator": "^10.2.0", "ical.js": "^2.2.1", "node-cron": "^4.6.0", - "node-ical": "^0.26.0" + "node-ical": "^0.26.0", + "pino-pretty": "13.1.3" }, "devDependencies": { "c8": "^11.0.0" @@ -699,6 +700,12 @@ "dev": true, "license": "MIT" }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "license": "MIT" + }, "node_modules/combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -771,6 +778,15 @@ "node": ">= 8" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/debug": { "version": "4.4.3", "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", @@ -960,6 +976,12 @@ "node": ">=6" } }, + "node_modules/fast-copy": { + "version": "4.1.1", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.1.1.tgz", + "integrity": "sha512-A4QTJmuiztpGtr6AMeJts9R4hbj2ZBUwtOaKrG6rw2y7t6+IaJKjz5M3XDs8BUznxDH43FVc6A0y/gWlMl4UtA==", + "license": "MIT" + }, "node_modules/fast-decode-uri-component": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/fast-decode-uri-component/-/fast-decode-uri-component-1.0.1.tgz", @@ -1005,6 +1027,12 @@ "fast-decode-uri-component": "^1.0.1" } }, + "node_modules/fast-safe-stringify": { + "version": "2.1.1", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.1.1.tgz", + "integrity": "sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==", + "license": "MIT" + }, "node_modules/fast-uri": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.3.tgz", @@ -1378,6 +1406,12 @@ "node": ">= 0.4" } }, + "node_modules/help-me": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", + "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==", + "license": "MIT" + }, "node_modules/html-escaper": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/html-escaper/-/html-escaper-2.0.2.tgz", @@ -1581,6 +1615,15 @@ "node": ">=8" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/jsbi": { "version": "4.3.2", "resolved": "https://registry.npmjs.org/jsbi/-/jsbi-4.3.2.tgz", @@ -1970,6 +2013,42 @@ "split2": "^4.0.0" } }, + "node_modules/pino-pretty": { + "version": "13.1.3", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.1.3.tgz", + "integrity": "sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg==", + "license": "MIT", + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^4.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^5.0.0", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.0", + "secure-json-parse": "^4.0.0", + "sonic-boom": "^4.0.1", + "strip-json-comments": "^5.0.2" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/strip-json-comments": { + "version": "5.0.3", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-5.0.3.tgz", + "integrity": "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==", + "license": "MIT", + "engines": { + "node": ">=14.16" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, "node_modules/pino-std-serializers": { "version": "7.1.0", "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", diff --git a/server/package.json b/server/package.json index 6ffc2ac..799557f 100644 --- a/server/package.json +++ b/server/package.json @@ -25,6 +25,7 @@ "ical-generator": "^10.2.0", "ical.js": "^2.2.1", "node-cron": "^4.6.0", - "node-ical": "^0.26.0" + "node-ical": "^0.26.0", + "pino-pretty": "13.1.3" } } diff --git a/server/services/calendarSync.js b/server/services/calendarSync.js index e6adb85..fda53d4 100644 --- a/server/services/calendarSync.js +++ b/server/services/calendarSync.js @@ -6,17 +6,29 @@ const googleCalendar = require('./googleCalendar'); const appleCalDAV = require('./appleCalDAV'); const { dedupeCalendarEvents } = require('../utils/calendarDedup'); +// Falls back to console when no logger is supplied, so the service stays usable +// standalone (tests construct it directly). `debug` maps to nothing in the +// fallback: without a level there is no way to honour one, and per-cycle chatter +// is exactly what must not be printed unconditionally. +const CONSOLE_LOGGER = { + debug: () => { }, + info: (...args) => console.log(...args), + warn: (...args) => console.warn(...args), + error: (...args) => console.error(...args), +}; + class CalendarSyncService { - constructor(db, decryptPassword) { + constructor(db, decryptPassword, logger = CONSOLE_LOGGER) { this.db = db; this.decryptPassword = decryptPassword; + this.log = logger; this.syncIntervals = new Map(); this.isSyncing = new Map(); } initialize() { this.startAllSyncJobs(); - console.log('Calendar sync service initialized'); + this.log.info('Calendar sync service initialized'); } normalizeAllDayEnd(end) { @@ -44,7 +56,7 @@ class CalendarSyncService { async syncSource(sourceId) { if (this.isSyncing.get(sourceId)) { - console.log(`Sync already in progress for source ${sourceId}, skipping`); + this.log.debug(`Sync already in progress for source ${sourceId}, skipping`); return { skipped: true }; } @@ -53,7 +65,7 @@ class CalendarSyncService { try { const source = this.db.prepare('SELECT * FROM calendar_sources WHERE id = ? AND enabled = 1').get(sourceId); if (!source) { - console.log(`Source ${sourceId} not found or disabled`); + this.log.warn(`Source ${sourceId} not found or disabled`); return { success: false, error: 'Source not found or disabled' }; } @@ -65,7 +77,7 @@ class CalendarSyncService { return { skipped: true }; } - console.log(`Starting sync for calendar source: ${source.name} (${source.type})`); + this.log.debug(`Starting sync for calendar source: ${source.name} (${source.type})`); const startTime = Date.now(); let events = []; @@ -113,11 +125,11 @@ class CalendarSyncService { VALUES (?, datetime('now'), 'success', ?, ?) `).run(sourceId, `Synced ${events.length} events in ${duration}ms`, events.length); - console.log(`Synced ${events.length} events for ${source.name} in ${duration}ms`); + this.log.info(`Synced ${events.length} events for ${source.name} in ${duration}ms`); return { success: true, eventCount: events.length, duration }; } catch (error) { - console.error(`Error syncing calendar source ${sourceId}:`, error.message); + this.log.error(`Error syncing calendar source ${sourceId}: ${error.message}`); this.db.prepare(` INSERT OR REPLACE INTO calendar_sync_status (source_id, last_sync_at, last_sync_status, last_sync_message) @@ -408,7 +420,7 @@ class CalendarSyncService { } if (interval <= 0) { - console.log(`Sync disabled for source ${sourceId}`); + this.log.info(`Sync disabled for source ${sourceId}`); return; } @@ -416,12 +428,12 @@ class CalendarSyncService { const intervalId = setInterval(() => { this.syncSource(sourceId).catch(err => { - console.error(`Scheduled sync failed for source ${sourceId}:`, err.message); + this.log.error(`Scheduled sync failed for source ${sourceId}: ${err.message}`); }); }, intervalMs); this.syncIntervals.set(sourceId, intervalId); - console.log(`Started sync job for source ${sourceId} every ${interval} minutes`); + this.log.info(`Started sync job for source ${sourceId} every ${interval} minutes`); } restartSyncJob(sourceId) { @@ -441,7 +453,7 @@ class CalendarSyncService { setTimeout(() => { this.syncAllSources().catch(err => { - console.error('Initial sync failed:', err.message); + this.log.error(`Initial sync failed: ${err.message}`); }); }, 5000); } @@ -449,7 +461,7 @@ class CalendarSyncService { stopAllSyncJobs() { for (const [sourceId, intervalId] of this.syncIntervals) { clearInterval(intervalId); - console.log(`Stopped sync job for source ${sourceId}`); + this.log.info(`Stopped sync job for source ${sourceId}`); } this.syncIntervals.clear(); } diff --git a/server/tests/consoleShim.test.js b/server/tests/consoleShim.test.js new file mode 100644 index 0000000..eff4aaf --- /dev/null +++ b/server/tests/consoleShim.test.js @@ -0,0 +1,105 @@ +const test = require('node:test'); +const assert = require('node:assert'); +const pino = require('pino'); + +const { MAPPING, installConsoleShim } = require('../utils/consoleShim'); + +// A pino instance that writes into an array instead of stdout, so assertions +// can read what would have been logged. +function capturingLogger(level) { + const lines = []; + const logger = pino({ level }, { write: (s) => lines.push(JSON.parse(s)) }); + return { logger, lines }; +} + +// Patch a private object rather than the real global console, so a failing +// assertion in here can still print itself. +function fakeConsole() { + return { log() { }, info() { }, debug() { }, warn() { }, error() { } }; +} + +test('every console method maps to the pino level of the same intent', () => { + assert.deepStrictEqual(MAPPING, { log: 'info', info: 'info', debug: 'debug', warn: 'warn', error: 'error' }); +}); + +test('the severity the author chose at the call site is what the logger records', () => { + const { logger, lines } = capturingLogger('trace'); + const c = fakeConsole(); + installConsoleShim(logger, c); + + c.log('a'); c.warn('b'); c.error('c'); c.debug('d'); c.info('e'); + + const byMsg = Object.fromEntries(lines.map((l) => [l.msg, l.level])); + assert.strictEqual(byMsg.a, 30, 'console.log -> info'); + assert.strictEqual(byMsg.b, 40, 'console.warn -> warn'); + assert.strictEqual(byMsg.c, 50, 'console.error -> error'); + assert.strictEqual(byMsg.d, 20, 'console.debug -> debug'); + assert.strictEqual(byMsg.e, 30, 'console.info -> info'); +}); + +test('trailing arguments survive: the case a naive logger.info(msg, obj) would drop', () => { + const { logger, lines } = capturingLogger('info'); + const c = fakeConsole(); + installConsoleShim(logger, c); + + // The exact shape of the settings dump and the DB error in index.js. + c.log('Raw settings from database:', [{ key: 'TZ', value: 'America/Los_Angeles' }]); + c.error('Failed to connect or create database:', new Error('SQLITE_CANTOPEN')); + + assert.ok(lines[0].msg.includes('America/Los_Angeles'), 'array argument was formatted in, not dropped'); + assert.ok(lines[1].msg.includes('SQLITE_CANTOPEN'), 'error message present'); + assert.ok(lines[1].msg.includes(' at '), 'error stack present, as console would print it'); +}); + +test('output is byte-identical to what console would have printed', () => { + // util.format is what console uses, so anything console could render, the + // shim renders the same way -- including %s placeholders and objects. + const util = require('util'); + const { logger, lines } = capturingLogger('info'); + const c = fakeConsole(); + installConsoleShim(logger, c); + + const args = ['user %s has %d chores', 'zev', 3, { extra: true }]; + c.log(...args); + assert.strictEqual(lines[0].msg, util.format(...args)); +}); + +test('at the shipped default, console.log is silent and warn/error are not', () => { + const { logger, lines } = capturingLogger('warn'); + const c = fakeConsole(); + installConsoleShim(logger, c); + + c.log('startup chatter'); + c.info('more chatter'); + c.warn('something off'); + c.error('something broken'); + + assert.deepStrictEqual(lines.map((l) => l.msg), ['something off', 'something broken']); +}); + +test('uninstall restores the original methods exactly', () => { + const { logger } = capturingLogger('info'); + const c = fakeConsole(); + const before = { ...c }; + const uninstall = installConsoleShim(logger, c); + + assert.notStrictEqual(c.log, before.log, 'shim installed'); + uninstall(); + for (const m of Object.keys(MAPPING)) { + assert.strictEqual(c[m], before[m], `console.${m} restored`); + } +}); + +test('the shim does not recurse if the logger itself writes via console', () => { + // Guard against the one way a global patch can wedge the process: a + // destination that calls console.*. pino writes to a stream and never + // does, but assert it rather than assume it. + let depth = 0; + const guard = { + info: (m) => { depth++; assert.ok(depth < 2, 'recursion'); depth--; }, + warn() { }, error() { }, debug() { }, + }; + const c = fakeConsole(); + installConsoleShim(guard, c); + assert.doesNotThrow(() => c.log('x')); +}); diff --git a/server/tests/logFormat.test.js b/server/tests/logFormat.test.js new file mode 100644 index 0000000..9def138 --- /dev/null +++ b/server/tests/logFormat.test.js @@ -0,0 +1,46 @@ +const test = require('node:test'); +const assert = require('node:assert'); + +const { FORMATS, DEFAULT_FORMAT, resolveLogFormat, transportFor } = require('../utils/logFormat'); + +test('pretty is the default, because the reader is usually a person with journalctl open', () => { + assert.strictEqual(DEFAULT_FORMAT, 'pretty'); + for (const unset of [undefined, null, '', ' ']) { + assert.deepStrictEqual(resolveLogFormat(unset), { format: 'pretty', source: 'default' }); + } +}); + +test('both formats are accepted, case and whitespace insensitively', () => { + assert.deepStrictEqual(FORMATS, ['pretty', 'json']); + for (const f of FORMATS) { + assert.strictEqual(resolveLogFormat(f).format, f); + assert.strictEqual(resolveLogFormat(` ${f.toUpperCase()} `).format, f); + assert.strictEqual(resolveLogFormat(f).source, 'env'); + } +}); + +test('an unknown format falls back and names what it rejected', () => { + const r = resolveLogFormat('yaml'); + assert.strictEqual(r.format, 'pretty'); + assert.strictEqual(r.source, 'invalid'); + assert.strictEqual(r.rejected, 'yaml'); +}); + +test('json means pino native output: no transport at all', () => { + assert.strictEqual(transportFor('json'), undefined); +}); + +test('pretty configures pino-pretty and drops the fields journald already supplies', () => { + const t = transportFor('pretty'); + assert.strictEqual(t.target, 'pino-pretty'); + assert.strictEqual(t.options.ignore, 'pid,hostname'); + assert.ok(t.options.translateTime, 'a human-readable timestamp, not epoch ms'); + assert.strictEqual(t.options.colorize, false, 'no ANSI escapes into journald'); + assert.strictEqual(t.options.singleLine, true, 'one journal entry per event'); +}); + +test('the pretty transport target is actually installed', () => { + // A transport that names a missing module fails at logger construction, + // i.e. at server boot, which is the worst place to find out. + assert.doesNotThrow(() => require.resolve(transportFor('pretty').target)); +}); diff --git a/server/tests/logLevel.test.js b/server/tests/logLevel.test.js new file mode 100644 index 0000000..927af5c --- /dev/null +++ b/server/tests/logLevel.test.js @@ -0,0 +1,107 @@ +const test = require('node:test'); +const assert = require('node:assert'); + +const { + LEVELS, + DEFAULT_LEVEL, + resolveLogLevel, + isSqlTraceEnabled, +} = require('../utils/logLevel'); + +test('the default is warn, so an unattended install is quiet without configuration', () => { + assert.strictEqual(DEFAULT_LEVEL, 'warn'); + + for (const unset of [undefined, null, '', ' ']) { + const { level, source } = resolveLogLevel(unset); + assert.strictEqual(level, 'warn'); + assert.strictEqual(source, 'default'); + } +}); + +test('every pino level is accepted, case and whitespace insensitively', () => { + for (const name of LEVELS) { + assert.strictEqual(resolveLogLevel(name).level, name); + assert.strictEqual(resolveLogLevel(name.toUpperCase()).level, name); + assert.strictEqual(resolveLogLevel(` ${name} `).level, name); + assert.strictEqual(resolveLogLevel(name).source, 'env'); + } +}); + +test('the vocabulary is pino\'s, not one invented here', () => { + assert.deepStrictEqual(LEVELS, ['trace', 'debug', 'info', 'warn', 'error', 'fatal', 'silent']); +}); + +test('a value that names no level falls back, and says which value it rejected', () => { + // The reason matters more than the fallback: a misspelling that silently + // becomes the default looks identical to one that worked. + const { level, source, rejected } = resolveLogLevel('verbose'); + assert.strictEqual(level, 'warn'); + assert.strictEqual(source, 'invalid'); + assert.strictEqual(rejected, 'verbose'); + + for (const bad of ['DEBUGGING', '1', 'true', 'off', 'none']) { + assert.strictEqual(resolveLogLevel(bad).source, 'invalid', `${bad} should not be a level`); + } +}); + +test('an invalid value is distinguishable from an absent one', () => { + // Both land on warn. Only `source` tells the operator whether their + // LOG_LEVEL did anything, which is the whole point of reporting it. + assert.strictEqual(resolveLogLevel(undefined).level, resolveLogLevel('nonsense').level); + assert.notStrictEqual(resolveLogLevel(undefined).source, resolveLogLevel('nonsense').source); +}); + +test('SQL tracing is enabled only at debug and trace', () => { + assert.strictEqual(isSqlTraceEnabled('debug'), true); + assert.strictEqual(isSqlTraceEnabled('trace'), true); + + for (const quiet of ['info', 'warn', 'error', 'fatal', 'silent']) { + assert.strictEqual(isSqlTraceEnabled(quiet), false, `${quiet} must not trace SQL`); + } +}); + +test('the shipped default does not trace SQL', () => { + // The regression this whole change exists to prevent: an install that sets + // nothing must not echo statements. 32MB per 12h on a Pi, with calendar + // contents inlined, came from this being unconditional. + assert.strictEqual(isSqlTraceEnabled(resolveLogLevel(undefined).level), false); +}); + +// --- the behaviour the level controls, exercised against the real driver --- + +const Database = require('better-sqlite3'); + +function captureStatements(level) { + const seen = []; + const db = isSqlTraceEnabled(level) + ? new Database(':memory:', { verbose: (sql) => seen.push(sql) }) + : new Database(':memory:'); + + db.exec('CREATE TABLE calendar_events_cache (id TEXT PRIMARY KEY, title TEXT, location TEXT)'); + db.prepare('INSERT OR REPLACE INTO calendar_events_cache (id, title, location) VALUES (?, ?, ?)') + .run('evt1', "Dentist - Emma's cleaning", '123 Elm St, Springfield'); + db.close(); + return seen; +} + +test('at debug, the driver echoes statements with bound values expanded', () => { + // This is the positive control. Without it, the assertions below pass + // against a probe that never captured anything, which is not evidence. + const seen = captureStatements('debug'); + assert.ok(seen.length > 0, 'debug must capture statements'); + assert.ok( + seen.some((sql) => sql.includes('Emma') && sql.includes('Elm St')), + 'better-sqlite3 inlines bound parameters, so the trace carries event contents' + ); +}); + +test('at the shipped default, no statement reaches the log at all', () => { + const seen = captureStatements(resolveLogLevel(undefined).level); + assert.deepStrictEqual(seen, [], 'default level must attach no verbose hook'); +}); + +test('no quiet level leaks calendar contents', () => { + for (const quiet of ['info', 'warn', 'error', 'fatal', 'silent']) { + assert.deepStrictEqual(captureStatements(quiet), [], `${quiet} must not trace`); + } +}); diff --git a/server/utils/consoleShim.js b/server/utils/consoleShim.js new file mode 100644 index 0000000..ded47bf --- /dev/null +++ b/server/utils/consoleShim.js @@ -0,0 +1,60 @@ +// Route the global console through a leveled logger. +// +// This is an adoption shim, not an architecture. The server has several hundred +// console.* calls written by many hands over a year, and at every one of them +// the author already chose a severity by picking .error, .warn or .log. That +// decision is honoured here rather than re-made: each console method maps to +// the logger level of the same name, so LOG_LEVEL governs all of it at once +// and no call site has to change. +// +// Two details matter: +// +// 1. Arguments are flattened with util.format BEFORE reaching the logger. +// 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`. util.format is exactly +// what console itself does, so output is byte-identical to what console +// would have printed, only now with a level attached. +// +// 2. It patches the global. Anything that logs through console after this +// runs -- dependencies included -- goes through the logger and obeys the +// level. That is mostly the point. It also means a reader who sees +// `console.error` in this codebase should know it is not writing to stderr. +// +// Migration to explicit logger calls can happen file by file, or never; the +// shim covers whatever has not been converted. + +const util = require('util'); + +const MAPPING = Object.freeze({ + log: 'info', + info: 'info', + debug: 'debug', + warn: 'warn', + error: 'error', +}); + +/** + * Redirect console.{log,info,debug,warn,error} into `logger`. + * + * Returns a function that restores the original methods, so tests can install + * and remove the shim without leaking it into other tests. + */ +function installConsoleShim(logger, target = console) { + const originals = {}; + + for (const [method, level] of Object.entries(MAPPING)) { + originals[method] = target[method]; + target[method] = (...args) => { + logger[level](util.format(...args)); + }; + } + + return function uninstallConsoleShim() { + for (const method of Object.keys(originals)) { + target[method] = originals[method]; + } + }; +} + +module.exports = { MAPPING, installConsoleShim }; diff --git a/server/utils/logFormat.js b/server/utils/logFormat.js new file mode 100644 index 0000000..9bdfb31 --- /dev/null +++ b/server/utils/logFormat.js @@ -0,0 +1,54 @@ +// Log output format, resolved once from the environment. +// +// `pretty` is the default, which is the opposite of pino's own default and is +// deliberate. HomeGlow runs on a Pi under journald, and the person reading its +// log is usually an operator with `journalctl` open, not a pipeline. journald +// already stamps every line with time, host and pid, so pino's JSON fields are +// redundant there; what is wanted is a level and a message a human can scan. +// +// `json` is for anyone who does feed a pipeline (Loki, Datadog, `journalctl -o +// json`), where each field being machine-parseable is the whole point. + +const FORMATS = ['pretty', 'json']; + +const DEFAULT_FORMAT = 'pretty'; + +/** The format named by `raw`, or the default, with the reason alongside. */ +function resolveLogFormat(raw) { + if (raw === undefined || raw === null || String(raw).trim() === '') { + return { format: DEFAULT_FORMAT, source: 'default' }; + } + + const normalized = String(raw).trim().toLowerCase(); + + if (FORMATS.includes(normalized)) { + return { format: normalized, source: 'env' }; + } + + return { format: DEFAULT_FORMAT, source: 'invalid', rejected: String(raw).trim() }; +} + +/** + * pino transport options for a format, or undefined for pino's native JSON. + * + * `ignore: 'pid,hostname'` because journald supplies both; `translateTime` + * because an epoch-millisecond integer is not something a person reads. + */ +function transportFor(format) { + if (format !== 'pretty') return undefined; + + return { + target: 'pino-pretty', + options: { + translateTime: 'SYS:yyyy-mm-dd HH:MM:ss', + ignore: 'pid,hostname', + colorize: false, + // One journal entry per event. Without this, pino-pretty renders + // each object field on its own indented line, and a single request + // log becomes seven journal rows. + singleLine: true, + }, + }; +} + +module.exports = { FORMATS, DEFAULT_FORMAT, resolveLogFormat, transportFor }; diff --git a/server/utils/logLevel.js b/server/utils/logLevel.js new file mode 100644 index 0000000..189645e --- /dev/null +++ b/server/utils/logLevel.js @@ -0,0 +1,54 @@ +// Log level, resolved once from the environment. +// +// Fastify's logger is pino, so the level vocabulary is already standard and is +// reused verbatim rather than invented here. `silent` is pino's own name for +// "log nothing"; it is accepted so an operator can turn the logger off without +// reaching for a sentinel value. +// +// The default is `warn`, not pino's `info`. HomeGlow runs unattended on a wall +// display whose kiosk polls continuously, and `info` means every HTTP request +// is journaled forever. `warn` keeps the log to things that describe a problem, +// which is what a log nobody reads daily is actually for. Turning it up is one +// environment variable. + +const LEVELS = ['trace', 'debug', 'info', 'warn', 'error', 'fatal', 'silent']; + +const DEFAULT_LEVEL = 'warn'; + +/** + * The pino level named by `raw`, or the default when it names nothing valid. + * + * Returns the reason alongside the level so the caller can say out loud that a + * value was ignored. A misspelled LOG_LEVEL that silently becomes the default + * is indistinguishable from one that worked, which is how someone ends up + * debugging production with the logging they thought they had turned on. + */ +function resolveLogLevel(raw) { + if (raw === undefined || raw === null || String(raw).trim() === '') { + return { level: DEFAULT_LEVEL, source: 'default' }; + } + + const normalized = String(raw).trim().toLowerCase(); + + if (LEVELS.includes(normalized)) { + return { level: normalized, source: 'env' }; + } + + return { level: DEFAULT_LEVEL, source: 'invalid', rejected: String(raw).trim() }; +} + +/** + * Whether SQL statement tracing should be wired up at this level. + * + * Deliberately a separate decision from "would pino print a debug line". The + * trace is better-sqlite3's `verbose` hook, and passing that hook at all makes + * the driver expand every statement's bound parameters into a string — + * unconditionally, before any level check could discard it. So the hook is + * attached only when the level would actually emit it; at `warn` the work is + * never done rather than done and thrown away. + */ +function isSqlTraceEnabled(level) { + return level === 'trace' || level === 'debug'; +} + +module.exports = { LEVELS, DEFAULT_LEVEL, resolveLogLevel, isSqlTraceEnabled };