[Log] Change to use logfmt that loki can read

README.md

@@ -31,7 +31,7 @@ and keep a running balance of extra/minus hours.
 | `DATA_DIR`          | `./data` | `users.json` + `users/<id>.json`                                                           |
 | `SESSION_SECRET`    | random   | Signs login cookies; without it everyone is logged out on restart. `npm run -s gen-secret` |
 | `REGISTRATION_CODE` | —        | If set, sign-up requires this invite code                                                  |
-| `LOG_LEVEL`         | `info`   | `debug`, `info`, `warn` or `error`; lines below this level are not logged                  |
+| `LOG_LEVEL`         | `info`   | `debug`, `info`, `warn` or `error`; lines below this level are not logged. Format: logfmt  |
 
 Everything else is fixed in `backend/config.ts`: at most 100 accounts, 30-day sessions.
 The app does no rate limiting of its own; that is left to the ingress (Traefik).

backend/app.ts

@@ -157,9 +157,9 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
     }
     if (legacy) {
       fs.renameSync(o.legacyDataFile, `${o.legacyDataFile}.migrated`);
-      log.info(`moved ${o.legacyDataFile} into the new account "${user.username}"`);
+      log.info('legacy data moved into account', { user: user.username, file: o.legacyDataFile });
     }
-    log.info(`account created: ${user.username}`);
+    log.info('account created', { user: user.username });
     startSession(res, user);
     res.status(201).json({ username: user.username });
   });
@@ -175,11 +175,11 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
     const user = store.findByName(creds.username);
     const ok = await verifyPassword(creds.password, user?.passwordHash ?? (await dummyHash));
     if (!user || !ok) {
-      log.warn(`login failed: ${creds.username}`);
+      log.warn('login failed', { user: creds.username });
       res.status(401).json({ error: 'Wrong username or password' });
       return;
     }
-    log.info(`login: ${user.username}`);
+    log.info('login', { user: user.username });
     startSession(res, user);
     res.json({ username: user.username });
   });
@@ -212,7 +212,7 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
       return;
     }
     store.delete(user.id);
-    log.info(`account deleted: ${user.username}`);
+    log.info('account deleted', { user: user.username });
     res.clearCookie(COOKIE, cookieOptions);
     res.status(204).end();
   });
@@ -227,7 +227,7 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
       const { data, rev } = store.readData((req as AuthedRequest).user.id);
       res.set('ETag', `"${rev}"`).json(data);
     } catch (err) {
-      log.error('could not read data file', err);
+      log.error('could not read data file', { user: (req as AuthedRequest).user.username, error: err });
       res.status(500).json({ error: 'Could not read data file' });
     }
   });
@@ -250,22 +250,22 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
       return;
     }
     const added = Object.keys(req.body.entries).filter((date) => !(date in before.entries));
-    if (added.length) log.info(`${user.username} added time for ${added.join(', ')}`);
+    if (added.length) log.info('time added', { user: user.username, dates: added.join(',') });
     const deleted = Object.keys(before.entries).filter((date) => !(date in req.body.entries));
-    if (deleted.length) log.info(`${user.username} deleted ${deleted.join(', ')}`);
+    if (deleted.length) log.info('days deleted', { user: user.username, dates: deleted.join(',') });
     const changed = (a: unknown, b: unknown) => JSON.stringify(a) !== JSON.stringify(b);
     for (const [date, entry] of Object.entries(req.body.entries)) {
       if (date in before.entries && changed(before.entries[date], entry)) {
-        log.info(`${user.username} changed ${date} to ${JSON.stringify(entry)}`);
+        log.info('day changed', { user: user.username, date, to: entry });
       }
     }
     for (const [key, value] of Object.entries(req.body.settings)) {
       if (changed(before.settings[key as keyof Data['settings']], value)) {
-        log.info(`${user.username} changed ${key} to ${JSON.stringify(value)}`);
+        log.info('setting changed', { user: user.username, setting: key, to: value });
       }
     }
     if (changed(before.workloadPeriods, req.body.workloadPeriods)) {
-      log.info(`${user.username} changed working hours to ${JSON.stringify(req.body.workloadPeriods)}`);
+      log.info('working hours changed', { user: user.username, to: req.body.workloadPeriods });
     }
     res.set('ETag', `"${result.rev}"`).json({ ok: true });
   });

backend/log.ts

@@ -1,20 +1,31 @@
+// Lines are logfmt: `time=… level=info msg="login" user=aaro`. Loki parses them with `| logfmt`.
+
 const LEVELS = { debug: 0, info: 1, warn: 2, error: 3 };
 type Level = keyof typeof LEVELS;
+type Fields = Record<string, unknown>;
 
 /** Lines below LOG_LEVEL (default info) are skipped. Quiet during tests. */
 const minLevel: Level = (process.env.LOG_LEVEL as Level) in LEVELS ? (process.env.LOG_LEVEL as Level) : 'info';
 
-function write(level: Level, message: string, err?: unknown) {
+/** Quotes values with spaces, quotes or `=`; newlines are escaped so each entry stays one line. */
+function value(v: unknown): string {
+  const s = v instanceof Error ? (v.stack ?? v.message) : typeof v === 'string' ? v : JSON.stringify(v);
+  return s === '' || /[\s"=\\]/.test(s) ? JSON.stringify(s) : s;
+}
+
+function write(level: Level, msg: string, fields: Fields = {}) {
   if (process.env.VITEST || LEVELS[level] < LEVELS[minLevel]) return;
-  const line = `${new Date().toISOString()} ${level.toUpperCase()} ${message}`;
-  const out = level === 'warn' || level === 'error' ? console.error : console.log;
-  if (err === undefined) out(line);
-  else out(line, err);
+  const all: Fields = { time: new Date().toISOString(), level, msg, ...fields };
+  const line = Object.entries(all)
+    .filter(([, v]) => v !== undefined)
+    .map(([k, v]) => `${k}=${value(v)}`)
+    .join(' ');
+  (level === 'warn' || level === 'error' ? console.error : console.log)(line);
 }
 
 export const log = {
-  debug: (message: string) => write('debug', message),
-  info: (message: string) => write('info', message),
-  warn: (message: string) => write('warn', message),
-  error: (message: string, err?: unknown) => write('error', message, err),
+  debug: (msg: string, fields?: Fields) => write('debug', msg, fields),
+  info: (msg: string, fields?: Fields) => write('info', msg, fields),
+  warn: (msg: string, fields?: Fields) => write('warn', msg, fields),
+  error: (msg: string, fields?: Fields) => write('error', msg, fields),
 };

backend/server.ts

@@ -3,7 +3,7 @@ import { DATA_DIR, PORT } from './config';
 import { log } from './log';
 
 const server = createApp().listen(PORT, () => {
-  log.info(`WorkH listening on http://localhost:${PORT} (data: ${DATA_DIR})`);
+  log.info('WorkH listening', { port: PORT, dataDir: DATA_DIR });
 });
 
 // Exit promptly when Kubernetes / Docker stops the container.

backend/store.ts

@@ -114,7 +114,7 @@ export class UserStore {
     const content = JSON.stringify(data, null, 2) + '\n';
     if (fs.existsSync(file)) fs.copyFileSync(file, `${file}.bak`);
     writeAtomic(file, content);
-    log.debug(`wrote ${file}`);
+    log.debug('wrote data file', { file });
     return { ok: true, rev: revOf(content) };
   }
 }