[Log] Add better logging and a logger

README.md

@@ -31,6 +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                  |
 
 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

@@ -3,6 +3,7 @@ import fs from 'node:fs';
 import { isData, type Data } from '../shared/types';
 import { createSessionToken, hashPassword, verifyPassword, verifySessionToken } from './auth';
 import * as config from './config';
+import { log } from './log';
 import { UserStore, type User } from './store';
 
 const COOKIE = 'workh_session';
@@ -156,8 +157,9 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
     }
     if (legacy) {
       fs.renameSync(o.legacyDataFile, `${o.legacyDataFile}.migrated`);
-      console.log(`WorkH: moved ${o.legacyDataFile} into the new account "${user.username}"`);
+      log.info(`moved ${o.legacyDataFile} into the new account "${user.username}"`);
     }
+    log.info(`account created: ${user.username}`);
     startSession(res, user);
     res.status(201).json({ username: user.username });
   });
@@ -173,9 +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}`);
       res.status(401).json({ error: 'Wrong username or password' });
       return;
     }
+    log.info(`login: ${user.username}`);
     startSession(res, user);
     res.json({ username: user.username });
   });
@@ -208,7 +212,7 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
       return;
     }
     store.delete(user.id);
-    console.log(`WorkH: deleted account "${user.username}"`);
+    log.info(`account deleted: ${user.username}`);
     res.clearCookie(COOKIE, cookieOptions);
     res.status(204).end();
   });
@@ -223,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) {
-      console.error('Could not read data file:', err);
+      log.error('could not read data file', err);
       res.status(500).json({ error: 'Could not read data file' });
     }
   });
@@ -238,11 +242,31 @@ export function createApp(overrides: Partial<AppOptions> = {}) {
       res.status(400).json({ error: 'Invalid data shape' });
       return;
     }
-    const result = store.writeData((req as AuthedRequest).user.id, req.body, ifMatch);
+    const { user } = req as AuthedRequest;
+    const before = store.readData(user.id).data;
+    const result = store.writeData(user.id, req.body, ifMatch);
     if (!result.ok) {
       res.status(412).set('ETag', `"${result.current.rev}"`).json(result.current.data);
       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(', ')}`);
+    const deleted = Object.keys(before.entries).filter((date) => !(date in req.body.entries));
+    if (deleted.length) log.info(`${user.username} deleted ${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)}`);
+      }
+    }
+    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)}`);
+      }
+    }
+    if (changed(before.workloadPeriods, req.body.workloadPeriods)) {
+      log.info(`${user.username} changed working hours to ${JSON.stringify(req.body.workloadPeriods)}`);
+    }
     res.set('ETag', `"${result.rev}"`).json({ ok: true });
   });
 

backend/log.ts

@@ -0,0 +1,20 @@
+const LEVELS = { debug: 0, info: 1, warn: 2, error: 3 };
+type Level = keyof typeof LEVELS;
+
+/** 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) {
+  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);
+}
+
+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),
+};

backend/server.ts

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

backend/store.ts

@@ -2,6 +2,7 @@ import { createHash, randomUUID } from 'node:crypto';
 import fs from 'node:fs';
 import path from 'node:path';
 import { defaultData, type Data } from '../shared/types';
+import { log } from './log';
 
 export interface User {
   id: string;
@@ -113,6 +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}`);
     return { ok: true, rev: revOf(content) };
   }
 }