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

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. |

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,15 +6285,15 @@ 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)');
       } else {
         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 {

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"
   }
 }

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,20 +420,20 @@ class CalendarSyncService {
     }
 
     if (interval <= 0) {
-      console.log(`Sync disabled for source ${sourceId}`);
+      this.log.info(`Sync disabled for source ${sourceId}`);
       return;
     }
 
     const intervalMs = interval * 60 * 1000;
 
     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,15 +453,15 @@ class CalendarSyncService {
 
     setTimeout(() => {
       this.syncAllSources().catch(err => {
-        console.error('Initial sync failed:', err.message);
+        this.log.error(`Initial sync failed: ${err.message}`);
       });
     }, 5000);
   }
 
   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();
   }