diff --git a/README.md b/README.md index b608367..32748bd 100644 --- a/README.md +++ b/README.md @@ -31,7 +31,7 @@ and keep a running balance of extra/minus hours. | `DATA_DIR` | `./data` | `users.json` + `users/.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). diff --git a/backend/app.ts b/backend/app.ts index 71d9606..58ae4e8 100644 --- a/backend/app.ts +++ b/backend/app.ts @@ -157,9 +157,9 @@ export function createApp(overrides: Partial = {}) { } 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 = {}) { 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 = {}) { 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 = {}) { 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 = {}) { 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 }); }); diff --git a/backend/log.ts b/backend/log.ts index 867e6fc..92e3f40 100644 --- a/backend/log.ts +++ b/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; /** 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), }; diff --git a/backend/server.ts b/backend/server.ts index 9e6f231..136ec0a 100644 --- a/backend/server.ts +++ b/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. diff --git a/backend/store.ts b/backend/store.ts index 444b303..b7d042f 100644 --- a/backend/store.ts +++ b/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) }; } }