diff --git a/docs/superpowers/plans/2026-10-29-unified-logging.md b/docs/superpowers/plans/2026-10-29-unified-logging.md new file mode 100644 index 0000000..3490a9a --- /dev/null +++ b/docs/superpowers/plans/2026-10-29-unified-logging.md @@ -0,0 +1,291 @@ +# Unified Logging Implementation Plan (lib) + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Ship one pino-based logger in `@data-fair/lib-node/log.js` (levels, safe error serializer, metrics, implicit context, `debug` module output redirected into it), open the request log context in lib-express `session.middleware()`, and remove `eventsLog` / `internalError` from the lib. + +**Architecture:** A module-level pino instance writes JSON (prod) or pino-pretty (dev) synchronously to stdout. A thin wrapper exposes `log.(msg, fields?)`, increments prom-client counters for warn/alert/error, and merges an `AsyncLocalStorage` context into each line through a pino `mixin`. lib-express fills that context per request inside `session.middleware()`. + +**Tech Stack:** TypeScript (ESM, type stripping), pino 10, pino-pretty 13 (optional peer), debug 4 (kept as the debug API, output redirected), prom-client 15, node:test. + +**Spec:** `docs/superpowers/specs/2026-10-29-unified-logging-design.md` + +**Out of scope of this plan:** data-fair and other services migration (separate plan, other repos); releases (done by the maintainer: lib-node and lib-express become **majors**, so commits removing APIs carry a `BREAKING CHANGE:` footer). + +## Global Constraints + +- One signature: `log.(msg: string, fields?: LogFields)`; reserved field keys `code`, `err`. +- Levels and pino values: `debug` 20, `info` 30, `warn` 40, `alert` 45 (custom), `error` 50. pino `level` is always `'debug'`; debug lines are gated only by `DEBUG` namespaces. +- Output field `level` is the label string; `time` is ISO (`pino.stdTimeFunctions.isoTime`); no `pid`; base fields `hostname` (`os.hostname()`) and `service` (from `log.init({ service })`, else `OTEL_SERVICE_NAME`, omitted if neither). +- Format: JSON when `NODE_ENV === 'production'`, pretty otherwise; `LOG_FORMAT=json|pretty` overrides; pretty = `pino-pretty` built with `{ sync: true, customLevels: 'alert:45' }` as the destination stream; if `pino-pretty` cannot be imported → JSON. +- Everything to stdout (`pino.destination({ dest: 1, sync: true })`). +- Counters (default prom-client register): `df_logs{level, code, host}` on warn/alert/error; deprecated `df_internal_error{errorCode}` on error; deprecated `df_events_log{level, code, host}` on warn/alert lines that have a code. Missing code → `''`; missing host → `'-'`. +- Request context field names: `ip`, `host`, `userId`, `userName`, `accountKey` (`type + '.' + id`), `accountDep`, `accountName`. Host normalization: missing, starting with `localhost` or ending with `:8080` → `'-'`. +- No logging method ever throws. +- Commit messages: conventional commits, ending with `Co-Authored-By: Claude Opus 5.5 `. +- Tests run with `node --experimental-strip-types --test ` from the repo root; full gate is `npm run quality`. + +## Review Focus + +1. **A secret-bearing axios error logged at any level** — raw `AxiosError` with `config.headers.Authorization` must produce no header data (pinned in Task 2). +2. **Error handler lines when the session cookie is invalid** — must still carry `ip`/`host` (pinned in Task 5). +3. **Two concurrent requests interleaving awaits** — each line keeps its own user (pinned in Task 4). +4. **`err` that is not an Error** (string, `null`, plain object, circular `cause`) — logged without throwing (pinned in Task 2). +5. **Per-call `host`/`code` overriding context** — counter label and output use the explicit value (pinned in Task 3). + +--- + +## File Structure + +- Create `packages/node/log.ts` — logger instance, levels, format selection, wrapper API, counters, context, `debug` output redirection, test seam. +- Create `packages/node/log-err.ts` — `serializeErr` whitelist serializer (pure, separately testable). +- Create `packages/node/log.test.ts`, `packages/node/log-err.test.ts`, `packages/node/log-worker.test.ts` (+ fixture `packages/node/test-fixtures/log-worker.ts`). +- Create `packages/express/req-log-context.ts` (+ test) — `reqLogFields`, `sessionLogFields`. +- Modify `packages/express/session.ts` — scope in `middleware()`, remove `reqForLogs` / `onLogsError`. +- Delete `packages/express/events-log.ts`, `packages/express/events-log.test.ts`. +- Modify all lib-internal call sites (Task 6 list), `packages/node/observer.ts`, `packages/express/index.ts`, `packages/node/package.json`, READMEs, `eslint.config.mjs`. + +--- + +### Task 1: Logger core (levels, output, format, test seam) + +**Files:** +- Create: `packages/node/log.ts` +- Test: `packages/node/log.test.ts` +- Modify: `packages/node/package.json` (dependencies `pino@^10`, `debug@^4`; optional peer `pino-pretty@13` in `peerDependencies` + `peerDependenciesMeta`; devDependency `pino-pretty@^13`), root `package-lock.json` via `npm install` + +**Interfaces:** +- Produces: + - `export type LogLevel = 'debug' | 'info' | 'warn' | 'alert' | 'error'` + - `export type LogFields = { code?: string, err?: unknown, [key: string]: unknown }` + - `export interface Logger { info (msg: string, fields?: LogFields): void; warn (...): void; alert (...): void; error (...): void; init (opts: { service?: string }): void }` + - `export default log: Logger` + - `/** @internal test seam */ export function _resetLogger (opts?: { destination?: { write (s: string): unknown }, format?: 'json' | 'pretty' }): void` — rebuilds the pino instance; without opts uses the env-driven defaults. + - internal `write (level: LogLevel, msg: string, fields?: LogFields): void` used by every method (later tasks hook counters and context into it). + +- [ ] **Step 1: Install deps** — `npm install -w packages/node pino@^10 debug@^4 && npm install -w packages/node -D pino-pretty@^13`, then add `pino-pretty` to `peerDependencies` (`"13"`) and `peerDependenciesMeta` (`optional: true`). Expected: `node_modules/pino` exists. + +- [ ] **Step 2: Write failing tests** in `packages/node/log.test.ts` with a capture helper: + +```ts +const capture = () => { const lines: any[] = []; _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }); return lines } + +it('writes one JSON object per line with label level, ISO time, hostname and no pid', () => { + const lines = capture(); log.info('hello', { a: 1 }) + assert.equal(lines[0].level, 'info'); assert.equal(lines[0].msg, 'hello'); assert.equal(lines[0].a, 1) + assert.match(lines[0].time, /^\d{4}-\d{2}-\d{2}T/); assert.equal(lines[0].hostname, hostname()); assert.equal(lines[0].pid, undefined) +}) +it('supports the alert level between warn and error', () => { const lines = capture(); log.alert('x', { code: 'c' }); assert.equal(lines[0].level, 'alert'); assert.equal(lines[0].code, 'c') }) +it('adds service from init', () => { const lines = capture(); log.init({ service: 'svc' }); log.warn('x'); assert.equal(lines[0].service, 'svc') }) +it('pretty format writes human readable non-JSON output', () => { const out: string[] = []; _resetLogger({ format: 'pretty', destination: { write: (s: string) => out.push(s) } }); log.info('pretty hello'); assert.ok(out.join('').includes('pretty hello')); assert.throws(() => JSON.parse(out[0])) }) +it('never throws', () => { capture(); const circular: any = {}; circular.self = circular; assert.doesNotThrow(() => log.info('x', circular)) }) +``` + +(For the pretty test, the destination is passed to pino-pretty as its `destination` option.) + +- [ ] **Step 3: Run** `node --experimental-strip-types --test packages/node/log.test.ts` — Expected: FAIL (module not found). + +- [ ] **Step 4: Implement `packages/node/log.ts`** — pino options: `level: 'debug'`, `customLevels: { alert: 45 }`, `base: { hostname: os.hostname() }`, `timestamp: pino.stdTimeFunctions.isoTime`, `formatters: { level: label => ({ level: label }) }`, `mixin` returning `{ service }` when set. `pino-pretty` loaded once with top-level `await import('pino-pretty').catch(() => null)`. `write` wraps `instance[level](fields ?? {}, msg)` in try/catch. Module calls `_resetLogger()` at load. + +- [ ] **Step 5: Run tests** — Expected: PASS. + +- [ ] **Step 6: Commit** — `git add packages/node/log.ts packages/node/log.test.ts packages/node/package.json package-lock.json && git commit -m "feat(node): pino based logger with alert level and env driven format"` + +--- + +### Task 2: Safe error serializer + +**Files:** +- Create: `packages/node/log-err.ts` +- Test: `packages/node/log-err.test.ts` +- Modify: `packages/node/log.ts` (pino `serializers: { err: serializeErr }`), `packages/node/log.test.ts` + +**Interfaces:** +- Produces: `export interface SerializedErr { type?: string, message: string, stack?: string, code?: string | number, status?: number, method?: string, url?: string, cause?: SerializedErr }` and `export function serializeErr (value: unknown, depth?: number): SerializedErr` (max depth 5, then `cause` omitted). + +- [ ] **Step 1: Write failing tests** in `log-err.test.ts`: + +```ts +it('keeps only whitelisted fields of an Error', () => { + const err = Object.assign(new Error('boom'), { code: 'E1', status: 500, keyValue: { email: 'a@b.c' }, secret: 'x' }) + const s = serializeErr(err) + assert.deepEqual(Object.keys(s).sort(), ['code', 'message', 'stack', 'status', 'type']) + assert.equal(s.type, 'Error'); assert.equal(s.message, 'boom') +}) +it('maps statusCode to status', () => assert.equal(serializeErr(Object.assign(new Error('x'), { statusCode: 404 })).status, 404)) +it('drops non primitive code', () => assert.equal(serializeErr(Object.assign(new Error('x'), { code: { a: 1 } })).code, undefined)) +it('never leaks axios request headers and strips the query string', () => { + const err = Object.assign(new Error('timeout'), { isAxiosError: true, config: { method: 'get', url: 'https://x.org/p?apiKey=s3cret', headers: { Authorization: 'Bearer s3cret' } } }) + const json = JSON.stringify(serializeErr(err)) + assert.ok(!json.includes('s3cret')); assert.ok(json.includes('"url":"https://x.org/p"')); assert.ok(json.includes('"method":"get"')) +}) +it('handles AxiosRequestError shape (name + config from response) without bodies', () => { + const err = Object.assign(new Error('500 - fail'), { name: 'AxiosRequestError', status: 500, config: { method: 'post', url: 'http://a/b?k=v', data: 'body' }, data: { secret: 1 }, headers: { 'set-cookie': 'x' } }) + const s = serializeErr(err); assert.equal(s.url, 'http://a/b'); assert.equal(s.status, 500); assert.ok(!JSON.stringify(s).includes('secret')) +}) +it('serializes cause recursively and stops on cycles', () => { + const a: any = new Error('a'); const b: any = new Error('b', { cause: a }); a.cause = b + const s = serializeErr(b); assert.equal(s.cause?.message, 'a'); assert.doesNotThrow(() => JSON.stringify(s)) +}) +it('accepts non Error values', () => { + assert.equal(serializeErr('plain').message, 'plain'); assert.equal(serializeErr(null).message, 'null') + assert.equal(serializeErr({ message: 'obj', token: 't' }).message, 'obj'); assert.ok(!JSON.stringify(serializeErr({ message: 'obj', token: 't' })).includes('"t"')) +}) +``` + +Plus in `log.test.ts`: `log.warn('x', { err: new Error('e') })` produces `lines[0].err.message === 'e'` and `lines[0].err.stack`. + +- [ ] **Step 2: Run** `node --experimental-strip-types --test packages/node/log-err.test.ts` — Expected: FAIL. +- [ ] **Step 3: Implement** `serializeErr`: Error-like (`instanceof Error` or object with string `message`) → whitelist; axios detection = `isAxiosError === true` or `name === 'AxiosRequestError'`, method/url read from `config`; any other value → `{ message: String(value) }` (`'null'` for null). Wire into pino `serializers`. +- [ ] **Step 4: Run both test files** — Expected: PASS. +- [ ] **Step 5: Commit** — `feat(node): whitelist error serializer for logs` + +--- + +### Task 3: Metrics + +**Files:** +- Modify: `packages/node/log.ts`, `packages/node/log.test.ts` +- Modify (bridge until Task 6): `packages/node/observer.ts` — remove its `df_internal_error` counter; `internalError(code, error, ...rest)` temporarily delegates to `log.error(error?.message ?? String(error), { code, err: error })`. `packages/express/events-log.ts` — remove its `df_events_log` Counter, import `eventsLogCounter` from `@data-fair/lib-node/log.js` and re-export it (avoids double registration). + +**Interfaces:** +- Produces: `export const logsCounter: Counter<'level' | 'code' | 'host'>` (`df_logs`), `export const internalErrorCounter` (`df_internal_error`, help text starts with `DEPRECATED, use df_logs.`), `export const eventsLogCounter` (`df_events_log`, same deprecation note). + +- [ ] **Step 1: Write failing tests** (read values with `register.getSingleMetric(name)?.get()` as in `req-perf.test.ts`; use unique codes per test): + +```ts +it('counts warn/alert/error in df_logs with level, code and host', async () => { + capture(); log.warn('w', { code: 'm-w', host: 'h1' }); log.alert('a', { code: 'm-a' }); log.error('e', { code: 'm-e' }) + const v = (await register.getSingleMetric('df_logs')!.get()).values + assert.ok(v.find(x => x.labels.code === 'm-w' && x.labels.level === 'warn' && x.labels.host === 'h1' && x.value === 1)) + assert.ok(v.find(x => x.labels.code === 'm-a' && x.labels.host === '-')) + assert.ok(v.find(x => x.labels.code === 'm-e' && x.labels.level === 'error')) +}) +it('does not count info and debug', async () => { capture(); log.info('i', { code: 'm-i' }); const v = (await register.getSingleMetric('df_logs')!.get()).values; assert.ok(!v.find(x => x.labels.code === 'm-i')) }) +it('counts uncoded lines with an empty code', ...) // log.warn('x') → labels.code === '' +it('keeps df_internal_error for error lines', ...) // log.error('e', { code: 'm-ie' }) → df_internal_error{errorCode:'m-ie'} === 1 +it('keeps df_events_log only for coded warn/alert', ...) // log.alert coded → present; log.warn uncoded and log.error coded → absent +``` + +- [ ] **Step 2: Run** — Expected: FAIL. +- [ ] **Step 3: Implement** in `write`: for warn/alert/error compute `code = typeof fields?.code === 'string' ? fields.code : ''`, `host = fields?.host ?? contextHost ?? '-'` (context lookup becomes real in Task 4; until then `fields?.host ?? '-'`), increment counters per Global Constraints. Apply the two bridge edits. +- [ ] **Step 4: Run** `node --experimental-strip-types --test packages/node/log.test.ts packages/express/events-log.test.ts` — Expected: PASS. +- [ ] **Step 5: Commit** — `feat(node): df_logs counter, keep deprecated counters` + +--- + +### Task 4: Implicit context and debug output redirection + +**Files:** +- Modify: `packages/node/log.ts`, `packages/node/log.test.ts` +- Create: `packages/node/log-worker.test.ts`, `packages/node/test-fixtures/log-worker.ts`, `packages/node/test-fixtures/early-debug.ts` + +**Interfaces:** +- Produces: + - `export type LogContext = Record` + - `export function withLogContext (fields: LogContext, fn: () => T): T` — runs `fn` in a store = `{ ...parent, ...fields }`. + - `export function getLogContext (): LogContext` — shallow copy, `{}` outside any scope. Worker propagation uses exactly these two (no extra helpers — my call, they already form the pair the spec asks for). + - Side effect at module load: on the shared `debug` module (`import createDebug from 'debug'`), `createDebug.formatArgs = () => {}` and `createDebug.log = function (...args) { write('debug', util.format(...args), { ns: this.namespace }) }`. `debug` reads both at each call, so instances created earlier are redirected too. No `debugNs`, no `DebugFn`: call sites keep `import Debug from 'debug'`. + +- [ ] **Step 1: Write failing tests:** + +```ts +it('merges context into lines, per-call fields win', () => { + const lines = capture() + withLogContext({ datasetId: 'd1', host: 'ctx' }, () => withLogContext({ step: 's' }, () => log.info('x', { host: 'call' }))) + assert.equal(lines[0].datasetId, 'd1'); assert.equal(lines[0].step, 's'); assert.equal(lines[0].host, 'call') +}) +it('isolates concurrent scopes across awaits and timers', async () => { + const lines = capture() + const run = (u: string) => withLogContext({ userId: u }, async () => { await new Promise(r => setTimeout(r, u === 'a' ? 10 : 1)); log.info(u) }) + await Promise.all([run('a'), run('b')]) + for (const l of lines) assert.equal(l.userId, l.msg) +}) +it('uses the context host as counter label', async () => { capture(); withLogContext({ host: 'ctx-host' }, () => log.warn('x', { code: 'm-ctx' })); /* df_logs{code:'m-ctx', host:'ctx-host'} === 1 */ }) +it('getLogContext returns a copy', () => withLogContext({ a: 1 }, () => { const c = getLogContext(); c.a = 2; assert.equal(getLogContext().a, 1) })) +// earlyDebug = createDebug('lt:early') is created at the top of log.test.ts, BEFORE `import log from './log.js'` +// is evaluated (put it in a tiny fixture module imported first: packages/node/test-fixtures/early-debug.ts) +it('redirects debug output, including instances created before the logger loaded', () => { + createDebug.enable('lt:*,-lt:no'); const lines = capture() + earlyDebug('hi %s', 'there'); createDebug('lt:late')('late', { k: 1 }); createDebug('lt:no')('nope'); createDebug('other')('nope') + assert.deepEqual(lines.map(l => [l.ns, l.msg, l.level]), [['lt:early', 'hi there', 'debug'], ['lt:late', 'late { k: 1 }', 'debug']]) +}) +``` + +`log-worker.test.ts`: in a scope `{ datasetId: 'w1' }`, start `new Worker(fixtureUrl, { workerData: { logContext: getLogContext() }, stdout: true })`; the fixture calls `withLogContext(workerData.logContext, () => log.info('in worker'))` with `LOG_FORMAT=json` in the worker `env`; the test reads the worker's stdout, parses the line, asserts `datasetId === 'w1'`. Run the fixture with `execArgv: ['--experimental-strip-types']`. + +- [ ] **Step 2: Run** — Expected: FAIL. +- [ ] **Step 3: Implement** a module-level `AsyncLocalStorage`; mixin returns `{ ...store, service? }` (pino's default mixin merge lets per-call fields win); counter host reads the store; the two `debug` property overrides. +- [ ] **Step 4: Run** `node --experimental-strip-types --test packages/node/log.test.ts packages/node/log-worker.test.ts` — Expected: PASS. +- [ ] **Step 5: Commit** — `feat(node): implicit log context and DEBUG namespaces` + +--- + +### Task 5: Request log context in session.middleware() + +**Files:** +- Create: `packages/express/req-log-context.ts`, `packages/express/req-log-context.test.ts` +- Modify: `packages/express/session.ts` (`middleware()`), `packages/express/session.test.ts` + +**Interfaces:** +- Consumes: `withLogContext`, `log` (Task 4), `reqIp` from `./req-origin.js`. +- Produces: `export function reqLogFields (req: Request | IncomingMessage): { ip?: string, host: string }` and `export function sessionLogFields (state: SessionState): LogContext` (`userId`, `userName`, `accountKey`, `accountDep`, `accountName`; undefined values omitted). + +- [ ] **Step 1: Write failing tests.** In `req-log-context.test.ts`, port the three ip cases of `events-log.test.ts` (X-Forwarded-For used, X-Client-IP ignored; no ip for in-cluster call) onto `reqLogFields`, plus host normalization: `example.com` kept, `data-fair:8080` → `'-'`, `localhost:5600` → `'-'`, missing → `'-'`; and `sessionLogFields` for an org account with department → `accountKey: 'organization.o1', accountDep: 'dep1'`. In `session.test.ts` (`describe('Session.middleware')`): + +```ts +it('opens a log context with request and session fields for later handlers', async () => { + const lines = captureLogs() // same helper as Task 1, via _resetLogger from lib-node/log.js + const session = new Session(); session.readState = async () => ({ lang: 'fr', user: testUser, account: { type: 'organization', id: 'org1', name: 'Test Org' }, accountRole: 'admin' }) + await session.middleware()(mockReq('GET', { host: 'example.com', 'x-forwarded-for': '203.0.113.7' }), mockRes(), () => { log.info('in route') }) + assert.equal(lines[0].userId, 'user1'); assert.equal(lines[0].accountKey, 'organization.org1'); assert.equal(lines[0].ip, '203.0.113.7'); assert.equal(lines[0].host, 'example.com') +}) +it('hands session failures to next(err) inside the request scope', async () => { + const lines = captureLogs() + const session = new Session(); session.readState = async () => { throw Object.assign(new Error('bad'), { status: 401 }) } + await session.middleware()(mockReq('GET', { host: 'example.com' }), mockRes(), (err?: any) => { log.warn(err.message, { code: 'unauthorized-req' }) }) + assert.equal(lines[0].host, 'example.com'); assert.equal(lines[0].code, 'unauthorized-req') +}) +it('logging a scoped session from the middleware does not trigger the scope check', ...) // scoped state, route never marks scope checked, next() called, line has userId +``` + +Update the existing test `sync accessors after a failed middleware do not throw a TypeError`: the middleware now resolves and calls `next(err)`; assert `next` received an error with status 401 instead of `assert.rejects`. + +- [ ] **Step 2: Run** `node --experimental-strip-types --test packages/express/req-log-context.test.ts packages/express/session.test.ts` — Expected: new tests FAIL. +- [ ] **Step 3: Implement.** `middleware()` returns `(req, res, next) => withLogContext(reqLogFields(req), async () => { try { …existing body…; withLogContext(sessionLogFields(sessionState), next) } catch (err) { next(err) } })`. Session state comes from `loadState` (no `assertRouteCheckedScope`). +- [ ] **Step 4: Run** the same command — Expected: PASS. +- [ ] **Step 5: Commit** — `feat(express): session middleware opens the request log context` + +--- + +### Task 6: Remove eventsLog and internalError, port the lib, docs + +**Files:** +- Delete: `packages/express/events-log.ts`, `packages/express/events-log.test.ts` +- Modify: `packages/express/index.ts` (drop the events-log export), `packages/express/session.ts` (remove `reqForLogs`, `onLogsError`, `internalError` import) and its three `reqForLogs` tests, `packages/node/observer.ts` (remove `internalError`; port its `console.*`) +- Port to `log` (`internalError`, `eventsLog`, `console.*` only; `debug` usages stay): `packages/express/error-handler.ts`, `ws-server.ts`, `req-perf.ts`, `req-origin.ts`, `packages/node/locks.ts`, `events-queue.ts`, `mongo.ts`, `http-agents.ts`, `upgrade-scripts.ts`, `test-spies.ts`, `packages/node/session.ts` +- Modify: `eslint.config.mjs`, `packages/node/README.md`, `packages/express/README.md` + +**Interfaces:** +- Consumes: `log` (Tasks 1–4). + +Porting rules (apply mechanically): +- `internalError(code, err)` → `log.error(, { code, err })`; when the second arg is a string message → `log.error(message, { code })`. +- error-handler: `status >= 500` → `log.error('failure while serving http request', { code: 'http', err })`; 403 → `log.warn(err.message, { code: 'forbidden-req' })`; 401 → `log.warn(err.message, { code: 'unauthorized-req' })`; its `debugModule('http-errors')` stays. +- `console.log` → `log.info`, `console.warn` → `log.warn`, `console.error` → `log.error` with a code (`observer` metrics failure: `code: 'observer-metrics'`), `console.debug` (test-spies) → the module's existing `debug` instance. +- `packages/utils/json-schema.ts` stays as is (utils is dependency-free and runs in browsers). + +- [ ] **Step 1: Delete, port, and remove** per the lists above. Then `grep -rn "internalError\|eventsLog\|events-log\|console\.\(log\|warn\|error\|info\|debug\)" packages/node packages/express --include=*.ts | grep -v '\.d\.ts' | grep -v '\.test\.ts'` — Expected: empty. +- [ ] **Step 2: eslint** — add a block `{ files: ['packages/node/**/*.ts', 'packages/express/**/*.ts'], ignores: ['**/*.test.ts', '**/test-fixtures/**'], rules: { 'no-console': 'error' } }`. Run `npm run lint` — Expected: no errors. +- [ ] **Step 3: READMEs** — lib-node: replace the `internalError` paragraph with a "Logging" section (usage, levels table, fields table, `debug` stays the debug API (output redirected, limitation with bundled copies), `code` must be static, context rules from the spec's Implicit context section, worker propagation with `getLogContext`/`withLogContext`, OTel notes incl. `OTEL_LOGS_EXPORTER=none`, migration table from the spec's Rollout step 1); add `pino-pretty` to the optional peers table. lib-express: remove the events-log row, mention that `session.middleware()` opens the log context. +- [ ] **Step 4: Full gate** — `npm run quality` — Expected: build, lint and all tests pass. +- [ ] **Step 5: Commit** + +```bash +git add -A packages eslint.config.mjs +git commit -m "feat!: unified logger replaces eventsLog and internalError + +BREAKING CHANGE: eventsLog (lib-express) and internalError (lib-node/observer) are removed, use log from @data-fair/lib-node/log.js. Log output is now JSON lines on stdout (pretty in dev), EVENTS_LOG_LEVEL is removed. + +Co-Authored-By: Claude Opus 5.5 " +``` diff --git a/docs/superpowers/specs/2026-10-29-unified-logging-design.md b/docs/superpowers/specs/2026-10-29-unified-logging-design.md new file mode 100644 index 0000000..1fe8012 --- /dev/null +++ b/docs/superpowers/specs/2026-10-29-unified-logging-design.md @@ -0,0 +1,319 @@ +# Unified logging for the data-fair stack — design + +Date: 2026-10-29 +Scope: `@data-fair/lib-node`, `@data-fair/lib-express`, then each service (data-fair first). + +## Why + +Today a service writes three unrelated formats: + +- `eventsLog` (lib-express `events-log.ts`): `console.log('df-event:', JSON.stringify(event))` on stdout. +- `internalError` (lib-node `observer.ts`): plain text `[code] message` + stack on stderr. +- `debug` (npm package, ~46 imports in data-fair api) and ~94 raw `console.*` calls: free-form text. + +Logs are collected by fluent-bit into rotated files per host/tenant; that system is under review and +the likely destination is Loki or VictoriaLogs, both of which index structured JSON fields. We want +every line to be one JSON object with the same field names, so that a filter like +`accountKey=organization.xyz`, `code=…` or `trace_id=…` works on everything, and so that +everything one request did (possibly across services) can be grouped. + +## Goals + +- **One logger, one signature, one output shape** for everything: `log.(msg, fields?)`. +- No distinction between "audit logs" and other logs. Clients' admins will receive custom filtered + outputs (by host, account, level, code…) depending on the situation. +- Almost standard levels, plus one custom level `alert` for events (mostly security) that are not + failures but deserve the same scrutiny as errors. +- Simple metrics: every `warn`, `alert` and `error` line increments a counter labeled by its code. +- JSON lines in production, human-readable output in dev; chosen from `NODE_ENV`. +- Keep `DEBUG=ns1,ns2*` targeted activation with the exact same syntax as the `debug` package. + Debug output stays off unless explicitly enabled per namespace. All other levels are always emitted. +- stdout only, no files, no transports, no shipping from the app. +- Trace ids on log lines, from OpenTelemetry, activated entirely on the Kubernetes side. +- An implicit, globally available log context (user, account, ip, host — what `EventLogContext` + carries by hand today) attached to every line logged during a request, plus the ability for any + code (including worker threads) to add small resource references (e.g. `datasetId`) to a scope. +- Usage is a plain import; no logger instance passed around; no new setup in services beyond what + they already do (`session.middleware()`). +- **Converge quickly on the convention rather than maintain compatibility**: `eventsLog` and + `internalError` are removed, not aliased. + +## Non-goals (for now) + +- Any OpenTelemetry code or dependency in the lib. +- Exporting traces or logs over OTLP. +- Trace ids in dev environments and inside worker threads. +- Logging in the browser / vue packages. +- Context for websocket connections (`ws-server.ts`) — later. +- Intercepting `console.*`: existing calls are ported by hand, not patched. +- Compatibility shims for the old APIs or the old output format. + +## Anti-goals (failure even if it technically works) + +- All debug logs enabled in production, flooding the log system. +- Secrets or document content leaking into logs through serialized error objects. +- A log line attributed to the wrong user/account (context captured by a long-lived resource). +- Big objects (`req`, full documents) retained in memory through the context. +- Unbounded metrics cardinality (dynamic values used as codes). +- Logging that breaks or throws in any environment (tests, scripts, no OTel operator). +- Passing logger instances through function signatures. + +## Constraints + +- Node 24 in service images; `AsyncLocalStorage` is backed by `AsyncContextFrame` there and is cheap. + The lib itself tests on Node 22 (`.nvmrc`), where ALS is slower but correct — acceptable. +- ESM everywhere; services run `.ts` via type stripping. +- `prom-client` is already an optional peer of lib-node; services all use it. +- Existing alert rules and dashboards query `df_internal_error{errorCode}` and + `df_events_log{level,code,host}`: these keep being emitted during the transition. + +## Decided with the user + +1. **pino** is the logger, `pino-pretty` for dev output. +2. **Levels**: `debug` (gated by `DEBUG` namespaces), `info`, `warn`, `alert`, `error`. Everything + except debug is always emitted; `EVENTS_LOG_LEVEL` is removed. `alert` is a custom pino level. + `error` is for internal failures only; client errors are `warn` at most. +3. **One signature**: `log.(msg, fields?)`. Errors go in the fields under `err`. +4. **Optional `code` field on any line.** On `warn`, `alert` and `error` lines it is used as a + metrics label. +5. **Metrics**: no metrics for `debug` and `info`; `warn`, `alert`, `error` increment counters + labeled `{level, code, host}`. The `host` label is kept. Old counters keep being emitted during + the transition (see Metrics). +6. **Errors use pino's `err` key convention** with a whitelisting serializer of our own (see Errors), + for any level. +7. **`eventsLog` and `internalError` are removed**; call sites are migrated. The resulting releases + are majors for lib-node and lib-express. +8. **`console.*` calls are ported**; an eslint `no-console` rule on server code guards against + regressions. +9. **OpenTelemetry is activated on the k8s side only** (OpenTelemetry Operator auto-instrumentation). + Its pino instrumentation adds `trace_id`, `span_id`, `trace_flags` to pino log lines; already + verified in the staging environment. No Dockerfile or start command change. +10. **Implicit context through our own `AsyncLocalStorage`**, opened by `session.middleware()` for + requests; resource references in scopes, propagated into data-fair's piscina worker threads. +11. **The output format change is coordinated with the collector**: fluent-bit routes are adapted on + the staging environment when the branch is deployed, before releasing. + +## Design + +### Module layout + +- `packages/node/log.ts` → `@data-fair/lib-node/log.js` + - default export `log`: `info`, `warn`, `alert`, `error`, `init`. + - at load, redirects the output of the `debug` module into the logger (see Debug output). + - `withLogContext(fields, fn)`, `getLogContext()`, worker helpers. + - owns the counters. +- `packages/node/observer.ts`: `internalError` and its counter removed (counter moves to `log.ts`); + its own `console.*` usage ported. +- `packages/express/events-log.ts` (+ `.d.ts`, test): removed. `EventLog`/`EventLogContext` types + removed. `session.reqForLogs`/`onLogsError` removed if nothing else uses them (builder checks). +- `packages/express/session.ts`: `middleware()` opens the request log context. +- `packages/express/error-handler.ts` and other lib-internal `console`/`internalError`/ + `eventsLog` usage: ported. + +### Logger API + +```ts +import log, { withLogContext } from '@data-fair/lib-node/log.js' + +log.info('dataset finalized', { datasetId }) +log.info('memory deleted', { code: 'agents.memory.delete' }) // audit-style line, just a code +log.warn('forbidden request', { code: 'forbidden-req', err }) +log.alert('admin api key created', { code: 'df.apikeys.createadmin' }) +log.error('failed to create mongo index', { code: 'mongo-index-fail', err, collection }) + + +await withLogContext({ datasetId }, async () => { … }) // every line inside carries datasetId +``` + +- Message first, fields second (maps to pino's `(obj, msg)` internally). Keep the wrapper thin. +- `fields` is a plain object; reserved keys: `code`, `err`. Explicit fields override context fields. +- `code` is a **static string** (e.g. `mongo-index-fail`, `df.apikeys.createadmin`) — never contains + ids, hosts or other dynamic values, which go in other fields. Stated in README and JSDoc. +- No method ever throws; a failure inside logging must not become a new error. +- Typing: `error` and `alert` without a `code` are allowed (counted with an empty code) — my call, + to keep one signature; the README recommends always giving one on these levels. +- `log.init({ service })` optional, sets the `service` field (falls back to `OTEL_SERVICE_NAME`). + +### Debug output + +Debug logs keep going through the `debug` module: `import debugModule from 'debug'` call sites stay +unchanged (decided with the user). Only the output is redirected. When `log.ts` loads, it replaces +two properties of the shared `debug` module (the copy lib-node resolves, normally deduped with the +services'): +- `createDebug.formatArgs` → no-op (no color, no namespace prefix, no diff timing); +- `createDebug.log` → writes a pino `debug` line `{ ns: this.namespace, msg: util.format(...args) }`. + +`debug` reads both properties at each call, so instances created before the logger loaded are +redirected too and import order does not matter (verified in a scratch test). Namespace gating stays +entirely `debug`'s (`DEBUG` syntax unchanged); pino's own level is always `debug`. + +Not used: `pino-debug`. It patches the CommonJS module wrapper, must load before anything requires +`debug` (first import or preload) and throws for instances created earlier. Limitation of our +approach: a third-party library bundling its own separate copy of `debug` is not redirected; its +output only appears when its namespace is enabled, as raw text. Acceptable. + +`debug` becomes a declared dependency of lib-node (it is used today without being declared). + +### Levels + +| level | pino value | emitted | metrics | +|---|---|---|---| +| debug | 20 | only matching `DEBUG` namespaces | no | +| info | 30 | always | no | +| warn | 40 | always | yes | +| alert | 45 (custom) | always | yes | +| error | 50 | always | yes | + +The alert value between warn and error is my call (purely ordering; every level is emitted anyway). +pino's `trace`/`fatal` are not exposed. + +### Errors + +Pino's convention is to log errors under the `err` key. We keep that key and that general shape, but +**replace pino's standard `err` serializer**, because it copies every enumerable property of the +error, which for us means: +- raw axios errors (no response: network failure, timeout) carry the full request `config`, including + `Authorization` / `x-apiKey` headers; +- `AxiosRequestError` (lib-node `axios.ts`) carries request body, response body and response headers; +- mongo errors carry document content (`keyValue` on duplicate keys). + +Our serializer is a whitelist: +- `type` (constructor name / `name`), `message`, `stack`; +- `code` and `status`/`statusCode` when they are primitives; +- `cause`, recursively with the same rules (bounded depth); +- for axios errors (raw or `AxiosRequestError`): `method` and `url` with the query string stripped. + +Nothing else. Non-Error values given as `err` (string, plain object, null) are serialized safely +(e.g. `{ message: String(value) }`) without throwing. + +### Metrics + +New counter `df_logs{level, code, host}` (name is my call; follows existing `df_` prefix), +incremented on every `warn`, `alert` and `error` line. `code` is `''` when absent; `host` is the line's +`host` field (explicit or from context), `'-'` when absent. + +During the transition the old counters keep being emitted, from the same place: +- `df_internal_error{errorCode}` on every `error` line; +- `df_events_log{level, code, host}` on every `warn` and `alert` line that has a code. Note: `info` + lines no longer increment it (they did when they were `eventsLog.info`); dashboards relying on + info counts change. + +Both old counters are marked deprecated in their help text, to be removed once alert rules and +dashboards use `df_logs`. + +### Output + +One JSON object per line, written synchronously to **stdout** for every level (my call). + +| field | source | +|---|---| +| `time` | ISO string | +| `level` | label string (`debug`, `info`, `warn`, `alert`, `error`), not pino's number | +| `msg` | message | +| `code` | optional, from fields | +| `err` | serialized error, from fields | +| `service` | `log.init` or `OTEL_SERVICE_NAME`; omitted if unknown | +| `hostname` | `os.hostname()` (pod name) | +| `trace_id`, `span_id`, `trace_flags` | added by the OTel pino instrumentation when present | +| `ip`, `host`, `userId`, `userName`, `accountKey`, `accountDep`, `accountName` | request context (names as in the current `EventLog`) | +| `ns` | debug lines | +| any other fields | from `withLogContext` scopes and per-call fields | + +No `pid`. `accountKey` keeps the current format `type + '.' + id`. + +**Format selection** (my call): JSON when `NODE_ENV === 'production'`, pretty otherwise; +`LOG_FORMAT=json|pretty` overrides. Pretty mode uses `pino-pretty` as a synchronous stream in the main +thread (not a worker transport). `pino-pretty` is an optional peer dependency loaded dynamically; if +missing, fall back to JSON without failing. Pretty lines show level, code/ns and short context +(account, user) inline, the stack below. + +### Implicit context + +A single module-level `AsyncLocalStorage` in lib-node `log.ts`; a pino `mixin` merges the +current store into each line. + +- `withLogContext(fields, fn)`: runs `fn` in a new store = parent store + `fields` (copy, never + mutate the parent). Returns `fn`'s result (sync or promise). +- `getLogContext()`: current fields, read-only copy. + +Rules, stated in the README and in the JSDoc of `withLogContext`: +- only small immutable values (ids, keys, short names) — never `req`, documents, buffers; +- long-lived resources (pools, intervals, caches, queues) are created at startup, outside any scope, + otherwise they capture a scope and attribute later lines to the wrong user; +- event listeners run in the emitter's context, not the subscriber's. + +### Request context (in `session.middleware()`) + +Every service already mounts `session.middleware()`, which already reads the session eagerly +(`loadState`). It becomes the place where the request scope opens, so services need no new setup: + +1. open a scope with `ip` (`reqIp(req, { optional: true })`) and `host` (same normalization as today's + events log: missing, `localhost*` or `*:8080` → `'-'`); +2. inside it, load the session as today, add `userId`, `userName`, `accountKey`, `accountDep`, + `accountName` (from `sessionState.user` / `sessionState.account`), and call `next()` inside the + scope; +3. if loading the session fails, hand the error to `next(err)` from inside the scope so the error + handler's lines (e.g. `unauthorized-req`) keep ip/host — a promise rejection caught by express + outside the scope would lose it. + +Reading the session for log fields must not go through `assertRouteCheckedScope`: log fields are not +an authorization use of the session. + +Lines logged by middleware mounted before `session.middleware()` have no request context. Acceptable. + +### Worker threads (data-fair piscina workers) + +- The logger works in a worker thread by plain import (each thread has its own pino instance and ALS). +- lib-node exposes a pair of helpers (names are the builder's call): one on the calling side that + captures the current log context as a plain serializable object to put in the task payload, one on + the worker side that runs the task inside `withLogContext(payloadContext, …)`. +- Known limitations, documented: in a worker, `process.stdout` is relayed asynchronously through the + main thread, so the last lines before a hard worker crash can be lost; counters incremented in a + worker are not served by the main thread's `/metrics` (unchanged from today). + +### OpenTelemetry + +Nothing to build in the lib. Notes for deployments, in the README: +- the operator's auto-instrumentation includes the pino instrumentation, which adds + `trace_id`/`span_id`/`trace_flags`; keep `OTEL_LOGS_EXPORTER=none` so it does not also try to ship + logs over OTLP; +- `traceparent` is propagated on all outgoing HTTP calls, including to third parties (my call: + acceptable, the ids are random and carry no information); +- without the operator (dev, tests, scripts) lines simply have no trace fields. + +## Rollout + +1. lib: implement `log.js` (levels, serializer, counters, context, worker helpers, debug redirection), + request scope in `session.middleware()`, remove `eventsLog` and `internalError`, port all + lib-internal usage. Release **lib-node and lib-express as majors**. README section in lib-node: + usage, levels, fields, code rules, context rules, OTel notes, migration table + (`eventsLog.info(code, msg, ctx)` → `log.info(msg, { code })`, `eventsLog.alert` → `log.alert`, + `internalError(code, err)` → `log.error(msg, { code, err })`; `debug` call sites unchanged). +2. data-fair: bump libs, port `console.*`, `eventsLog`, `internalError` call sites, add the + worker context helpers around piscina tasks, add eslint `no-console` for server code. Deploy the + branch on staging, adapt fluent-bit routes, then release. +3. Other services, same steps when they bump to the new majors. + +## Testing + +`node:test`, like existing lib tests. Capture output by injecting a destination stream (the logger +must allow this for tests — builder's call how). + +- JSON shape: fields, label levels, ISO time, no pid; pretty fallback to JSON without `pino-pretty`. +- levels: `alert` custom level present with its label. +- debug: an instance created before the logger loaded and one created after both produce pino + debug lines with `ns` and the `util.format`ted message; disabled namespaces emit nothing. +- metrics: `df_logs` incremented for warn/alert/error with `{level, code, host}`, not for + info/debug; `df_internal_error` on error; `df_events_log` on coded warn/alert. +- errors: whitelist only (an axios-like error with `config.headers.Authorization` and a mongo-like + error with `keyValue` produce no such data), `cause` chain, URL query stripped, odd inputs (string, + null, plain object) never throw. +- context: `withLogContext` nesting, isolation between concurrent scopes, survives awaits and timers. +- session middleware: ip/host and user/account present in lines logged by later handlers; ip/host + present in error-handler lines when session loading fails; no scope-check error triggered by logging. +- worker helpers: context captured, serialized, restored in a real `worker_threads` worker. + +## Left to the builder + +Exact names of helpers and of the new counter if a better one fits conventions, package versions, +how to inject the test destination, pretty-output layout, max `cause` depth. diff --git a/eslint.config.mjs b/eslint.config.mjs index e1a79e7..4a94fb8 100644 --- a/eslint.config.mjs +++ b/eslint.config.mjs @@ -7,5 +7,13 @@ export default [ rules: { 'no-undef': 'off' // taken care of by typescript } + }, + { + // server side code logs through @data-fair/lib-node/log.js + files: ['packages/node/**/*.ts', 'packages/express/**/*.ts'], + ignores: ['**/*.test.ts', '**/test-fixtures/**'], + rules: { + 'no-console': 'error' + } } ] diff --git a/package-lock.json b/package-lock.json index 3e168b2..5d0cb88 100644 --- a/package-lock.json +++ b/package-lock.json @@ -883,6 +883,12 @@ "node": ">=8.0.0" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@stylistic/eslint-plugin": { "version": "2.13.0", "resolved": "https://registry.npmjs.org/@stylistic/eslint-plugin/-/eslint-plugin-2.13.0.tgz", @@ -2093,6 +2099,15 @@ "integrity": "sha512-Oei9OH4tRh0YqU3GxhX79dM/mwVgvbZJaSNaRk+bshkj0S5cfHcgYakreBjrHwatXKbz+IoIdYLxrKim2MjW0Q==", "license": "MIT" }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/available-typed-arrays": { "version": "1.0.7", "resolved": "https://registry.npmjs.org/available-typed-arrays/-/available-typed-arrays-1.0.7.tgz", @@ -2381,6 +2396,13 @@ "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==", + "dev": true, + "license": "MIT" + }, "node_modules/combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -2646,6 +2668,16 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "dev": true, + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/dayjs": { "version": "1.11.19", "resolved": "https://registry.npmjs.org/dayjs/-/dayjs-1.11.19.tgz", @@ -2946,6 +2978,16 @@ "node": ">= 0.8" } }, + "node_modules/end-of-stream": { + "version": "1.4.5", + "resolved": "https://registry.npmjs.org/end-of-stream/-/end-of-stream-1.4.5.tgz", + "integrity": "sha512-ooEGc6HP26xXq/N+GCGOT0JKCLDGrq2bQUZrQ7gyrJiZANJ/8YDTxTpQBXGMn+WbIQXNVpyWymm7KYVICQnyOg==", + "dev": true, + "license": "MIT", + "dependencies": { + "once": "^1.4.0" + } + }, "node_modules/enhanced-resolve": { "version": "5.20.0", "resolved": "https://registry.npmjs.org/enhanced-resolve/-/enhanced-resolve-5.20.0.tgz", @@ -3608,6 +3650,13 @@ "dev": true, "license": "MIT" }, + "node_modules/fast-copy": { + "version": "4.3.1", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.3.1.tgz", + "integrity": "sha512-CRzQaTFOFUs6PuhsAq7lk9Zqr995soJBcFNZlfJS/5keTSl1awREV9dZW4xS2nX4pWbhIIR0xp4h+J8PQxCkvg==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", @@ -3628,6 +3677,13 @@ "dev": true, "license": "MIT" }, + "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==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-uri": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.0.tgz", @@ -4261,6 +4317,13 @@ "he": "bin/he" } }, + "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==", + "dev": true, + "license": "MIT" + }, "node_modules/hookable": { "version": "5.5.3", "resolved": "https://registry.npmjs.org/hookable/-/hookable-5.5.3.tgz", @@ -5009,6 +5072,16 @@ "url": "https://github.com/sponsors/panva" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -6015,6 +6088,15 @@ "ufo": "^1.6.1" } }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -6033,7 +6115,6 @@ "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz", "integrity": "sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w==", "license": "ISC", - "peer": true, "dependencies": { "wrappy": "1" } @@ -6279,6 +6360,91 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.4.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.4.0.tgz", + "integrity": "sha512-bk1ZMTwG/Vymx+zPoa28MhNzucFvXJWp3csrSuxuHPSMeUettaCoQ5Jvg07mtC4JGNpcfTwz41oVCnNgBK9+vA==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^1.0.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-pretty": { + "version": "13.2.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.2.0.tgz", + "integrity": "sha512-jjghD1ML+Di/WxjJDz6j6Y4FT7hIXOlb8h27AyJ+ohtAXJXH4PS/xkv7si+RCCIW59HMgZsMKTDgzdr0RhuRrg==", + "dev": true, + "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.2", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.3", + "secure-json-parse": "^4.1.0", + "sonic-boom": "^5.0.0", + "strip-json-comments": "^5.0.3" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/sonic-boom": { + "version": "5.0.2", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-5.0.2.tgz", + "integrity": "sha512-/JEruzo6yhNVhsLblTRchgTQHIt7SsdJP0YyrfWaNKjIOQDfrdZv9gwYraYCAsmKV39/LAdV31FLL5NCDpoL/A==", + "dev": true, + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "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==", + "dev": true, + "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", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/pkg-types": { "version": "2.3.0", "resolved": "https://registry.npmjs.org/pkg-types/-/pkg-types-2.3.0.tgz", @@ -6354,6 +6520,22 @@ "url": "https://github.com/prettier/prettier?sponsor=1" } }, + "node_modules/process-warning": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.1.tgz", + "integrity": "sha512-oCkNVj4OKnKEcocVBcDfiIugN1/cE6rgfT3nCtzeqZPA8+rIxMaQ0xXzIkGP8Gj2qUaP1UR7uhJ1VD8lUCpzCg==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/prom-client": { "version": "15.1.3", "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-15.1.3.tgz", @@ -6400,6 +6582,17 @@ "integrity": "sha512-D+zkORCbA9f1tdWRK0RaCR3GPv50cMxcrz4X8k5LTSUD1Dkw47mKJEZQNunItRTkWwgtaUSo1RVFRIG9ZXiFYg==", "license": "MIT" }, + "node_modules/pump": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.4.tgz", + "integrity": "sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==", + "dev": true, + "license": "MIT", + "dependencies": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "node_modules/punycode": { "version": "2.3.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.3.1.tgz", @@ -6443,6 +6636,12 @@ ], "license": "MIT" }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/quick-lru": { "version": "4.0.1", "resolved": "https://registry.npmjs.org/quick-lru/-/quick-lru-4.0.1.tgz", @@ -6676,6 +6875,12 @@ "url": "https://paulmillr.com/funding/" } }, + "node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/reconnecting-websocket": { "version": "4.4.0", "resolved": "https://registry.npmjs.org/reconnecting-websocket/-/reconnecting-websocket-4.4.0.tgz", @@ -6909,6 +7114,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -6938,6 +7152,23 @@ "dev": true, "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.1", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.1.tgz", + "integrity": "sha512-lnd81MQEZKjhW/Gd2TQqdd4XP6QYNdDW/EP+I7nTrFHP9y2LmaGPIHk9xsnzcOiEr1c39c/e84xFgGviQKBTRw==", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/semver": { "version": "7.6.0", "resolved": "https://registry.npmjs.org/semver/-/semver-7.6.0.tgz", @@ -7167,6 +7398,15 @@ "dev": true, "license": "ISC" }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map-js": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/source-map-js/-/source-map-js-1.2.1.tgz", @@ -7226,7 +7466,6 @@ "version": "4.2.0", "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", - "dev": true, "license": "ISC", "engines": { "node": ">= 10.x" @@ -7491,6 +7730,18 @@ "url": "https://github.com/sponsors/sindresorhus" } }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, "node_modules/through": { "version": "2.3.8", "resolved": "https://registry.npmjs.org/through/-/through-2.3.8.tgz", @@ -8223,8 +8474,7 @@ "version": "1.0.2", "resolved": "https://registry.npmjs.org/wrappy/-/wrappy-1.0.2.tgz", "integrity": "sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==", - "license": "ISC", - "peer": true + "license": "ISC" }, "node_modules/ws": { "version": "8.19.0", @@ -8409,13 +8659,16 @@ "axios": "^1.7.7", "cacheable-lookup": "^7.0.0", "cookie": "^0.7.2", + "debug": "^4.4.3", "ipaddr.js": "^2.5.0", "jsonwebtoken": "^9.0.2", "jwks-rsa": "^3.1.0", + "pino": "^10.4.0", "semver": "^7.6.3" }, "devDependencies": { "mongodb": "^6.9.0", + "pino-pretty": "^13.2.0", "prom-client": "^15.1.3", "tough-cookie": "^5.0.0", "ws": "^8.18.0" diff --git a/packages/express/README.md b/packages/express/README.md index 2e0867d..b298992 100644 --- a/packages/express/README.md +++ b/packages/express/README.md @@ -14,10 +14,9 @@ Peer dependencies: `@data-fair/lib-node@^2.15.0`, `express@5`, and `ws@8` (optio | Import path | Description | | --- | --- | -| `@data-fair/lib-express` | Re-exports the small common pieces: `session.js`, `errorHandler`, events log, find utils, `httpError`, `req-origin.js`, `site.js`, `serve-spa.js`. | -| `@data-fair/lib-express/session.js` | `session` singleton: verifies the simple-directory session cookies, `session.middleware()`, `reqSession()` / `reqSessionAuthenticated()` / `reqAdminMode()` accessors. | -| `@data-fair/lib-express/error-handler.js` | Express error handler: maps errors to status codes, counts 5xx with `internalError`, hides 5xx details when `NODE_ENV=production`. | -| `@data-fair/lib-express/events-log.js` | `info` / `warn` / `alert` logs of sensitive events (audit, security), filtered by `EVENTS_LOG_LEVEL`. | +| `@data-fair/lib-express` | Re-exports the small common pieces: `session.js`, `errorHandler`, find utils, `httpError`, `req-origin.js`, `site.js`, `serve-spa.js`. | +| `@data-fair/lib-express/session.js` | `session` singleton: verifies the simple-directory session cookies, `session.middleware()` (also opens the request log context, see `@data-fair/lib-node/log.js`), `reqSession()` / `reqSessionAuthenticated()` / `reqAdminMode()` accessors. | +| `@data-fair/lib-express/error-handler.js` | Express error handler: maps errors to status codes, logs 5xx as errors and 401/403 as warnings, hides 5xx details when `NODE_ENV=production`. | | `@data-fair/lib-express/req-origin.js` | Reverse-proxy aware request info: `reqOrigin()`, `reqHost()`, `reqIp()`, `reqIsInternal()`, `assertReqInternalSecret()`, `secretKeyMatches()`… | | `@data-fair/lib-express/site.js` | `createSiteMiddleware(servicePathPart)`: extracts the site path prefix of the request, `reqSitePath()`, `reqSiteUrl()`. | | `@data-fair/lib-express/serve-spa.js` | `createSpaMiddleware()`: serves a built SPA with UI config injection, cache headers and CSP. | diff --git a/packages/express/error-handler.ts b/packages/express/error-handler.ts index ef902c5..2255d7d 100644 --- a/packages/express/error-handler.ts +++ b/packages/express/error-handler.ts @@ -1,6 +1,5 @@ import type { ErrorRequestHandler } from 'express' -import { internalError } from '@data-fair/lib-node/observer.js' -import eventsLog from './events-log.js' +import log from '@data-fair/lib-node/log.js' import debugModule from 'debug' const debug = debugModule('http-errors') @@ -19,13 +18,13 @@ const errorHandler: ErrorRequestHandler = (err, req, res, next) => { if (err.name === 'MongoServerError' && err.code === 11000) status = 409 if (status >= 500) { - internalError('http', 'failure while serving http request', err) + log.error('failure while serving http request', { code: 'http', err }) } if (status === 403) { - eventsLog.warn('forbidden-req', err.message, { req }) + log.warn(err.message, { code: 'forbidden-req' }) } if (status === 401) { - eventsLog.warn('unauthorized-req', err.message, { req }) + log.warn(err.message, { code: 'unauthorized-req' }) } res.set('Cache-Control', 'no-cache') res.set('Expires', '-1') diff --git a/packages/express/events-log.test.ts b/packages/express/events-log.test.ts deleted file mode 100644 index 2a8fb21..0000000 --- a/packages/express/events-log.test.ts +++ /dev/null @@ -1,38 +0,0 @@ -import { describe, it, beforeEach, afterEach } from 'node:test' -import { strict as assert } from 'assert' -import type { Request } from 'express' -import eventsLog from './events-log.js' - -const user = { id: 'u1', name: 'User 1' } -const mockReq = (headers: Record) => ({ headers, get: (name: string) => headers[name.toLowerCase()] }) as unknown as Request - -// info() is fire-and-forget: collect the df-event lines it prints -let lines: string[] = [] -const originalLog = console.log -const settle = () => new Promise(resolve => setImmediate(resolve)) - -describe('events-log ip', () => { - beforeEach(() => { - lines = [] - console.log = (...args: unknown[]) => { if (args[0] === 'df-event:') lines.push(args[1] as string) } - }) - afterEach(() => { console.log = originalLog }) - - it('logs the client IP from X-Forwarded-For, not X-Client-IP', async () => { - eventsLog.info('test', 'msg', { user, req: mockReq({ 'x-forwarded-for': '203.0.113.7', 'x-client-ip': '10.0.0.9', host: 'example.com' }) }) - await settle() - assert.equal(JSON.parse(lines[0]).ip, '203.0.113.7') - }) - - it('logs no IP for a request without one (an in-cluster call)', async () => { - eventsLog.info('test', 'msg', { user, req: mockReq({ host: 'data-fair:8080' }) }) - await settle() - assert.equal(JSON.parse(lines[0]).ip, undefined) - }) - - it('keeps an explicit ip from the context', async () => { - eventsLog.info('test', 'msg', { user, ip: '198.51.100.1', req: mockReq({ 'x-forwarded-for': '203.0.113.7' }) }) - await settle() - assert.equal(JSON.parse(lines[0]).ip, '198.51.100.1') - }) -}) diff --git a/packages/express/events-log.ts b/packages/express/events-log.ts deleted file mode 100644 index cba2e19..0000000 --- a/packages/express/events-log.ts +++ /dev/null @@ -1,117 +0,0 @@ -// log sensitive events, for security ,traceability and audit purposes -// this info is not going to be exposed on any web service, public file, etc -// it is for admins only and can contain sensitive information if useful -// but, of course, not ultra sensitive like clear-text passwords for example - -// account events might be sent to a an organization's security officer -// global events are only for hosting superadmins - -import { type Account, type UserRef } from '@data-fair/lib-common-types/session/index.js' -import { type Request } from 'express' -import { hostname as getHostname } from 'os' -import { Counter } from 'prom-client' -import session from './session.js' -import { reqIp } from './req-origin.js' -import { internalError } from '@data-fair/lib-node/observer.js' - -export type EventLogLevel = 'info' | 'warn' | 'alert' - -export interface EventLog { - time: string - code: string - message: string - level: EventLogLevel - hostname: string - accountKey?: string - accountDep?: string - accountName?: string - userId?: string - userName?: string - ip?: string - host: string -} - -export interface EventLogContext { - req?: Request - account?: Account - user?: UserRef - ip?: string - host?: string -} - -const level = process.env.EVENTS_LOG_LEVEL || 'info' -const levels = ['silent', 'alert', 'warn', 'info'] -const activeLevels = levels.slice(0, levels.indexOf(level) + 1) - -const hostname = getHostname() - -export const eventsLogCounter = new Counter({ - name: 'df_events_log', - help: 'A counter of sensitive events logged by the service. Each increment should be accompanied by a log of the event in stdout.', - labelNames: ['level', 'code', 'host'] -}) - -const globalInfo: { service?: string } = {} - -export function init (service: string) { - globalInfo.service = service -} - -export function logEvent (event: EventLog) { - event.hostname = hostname - eventsLogCounter.inc({ level: event.level, code: event.code, host: event.host }) - if (activeLevels.includes(event.level)) { - console.log('df-event:', JSON.stringify(event)) - } -} - -async function log (level: EventLogLevel, code: string, message: string, context: EventLogContext = {}) { - // looking into req.user and req.user.activeAccount for retro-compatibility with older session management - let user: UserRef | undefined = context.user ?? (context.req as unknown as any)?.user - let account: Account | undefined = context.account ?? (user as unknown as any)?.activeAccount - - // new session management - if (!user && context.req) { - const sessionState = await session.reqForLogs(context.req) - if (sessionState) { - user = sessionState.user - account = sessionState.account - } - } - - let host = context.host ?? context.req?.get('Host') - if (!host || host.startsWith('localhost') || host.endsWith(':8080')) host = '-' - - const event: EventLog = { - time: new Date().toISOString(), - level, - code, - message, - hostname, - ip: context.ip ?? (context.req && reqIp(context.req, { optional: true })), - host, - accountKey: account && (account.type + '.' + account.id), - accountDep: account?.department, - accountName: account?.name, - userId: user?.id, - userName: user?.name - } - logEvent(event) -} - -function info (code: string, message: string, context: EventLogContext) { - log('info', code, message, context) - .catch(err => internalError('event-log-fail', err)) -} - -function warn (code: string, message: string, context: EventLogContext) { - log('warn', code, message, context) - .catch(err => internalError('event-log-fail', err)) -} - -function alert (code: string, message: string, context: EventLogContext) { - log('alert', code, message, context) - .catch(err => internalError('event-log-fail', err)) -} - -export default { info, warn, alert } diff --git a/packages/express/index.ts b/packages/express/index.ts index 1f5f83b..b21fb76 100644 --- a/packages/express/index.ts +++ b/packages/express/index.ts @@ -3,7 +3,6 @@ export * from './session.js' export { default as errorHandler } from './error-handler.js' -export * from './events-log.js' export * from './find-utils.js' export * from '@data-fair/lib-utils/http-errors.js' export * from './req-origin.js' diff --git a/packages/express/req-log-context.test.ts b/packages/express/req-log-context.test.ts new file mode 100644 index 0000000..b5df5cc --- /dev/null +++ b/packages/express/req-log-context.test.ts @@ -0,0 +1,39 @@ +import { describe, it } from 'node:test' +import { strict as assert } from 'assert' +import type { Request } from 'express' +import { reqLogFields, sessionLogFields } from './req-log-context.js' + +const mockReq = (headers: Record) => ({ headers, get: (name: string) => headers[name.toLowerCase()] }) as unknown as Request + +describe('reqLogFields', () => { + it('reads the client IP from X-Forwarded-For, not X-Client-IP', () => { + assert.equal(reqLogFields(mockReq({ 'x-forwarded-for': '203.0.113.7', 'x-client-ip': '10.0.0.9', host: 'example.com' })).ip, '203.0.113.7') + }) + + it('has no IP for a request without one (an in-cluster call)', () => { + assert.equal(reqLogFields(mockReq({ host: 'data-fair:8080' })).ip, undefined) + }) + + it('never throws on a malformed X-Forwarded-For', () => { + assert.doesNotThrow(() => reqLogFields(mockReq({ 'x-forwarded-for': 'unknown', host: 'example.com' }))) + assert.equal(reqLogFields(mockReq({ 'x-forwarded-for': 'garbage, 1.2.3.4', host: 'example.com' })).ip, undefined) + }) + + it('normalizes internal hosts', () => { + assert.equal(reqLogFields(mockReq({ host: 'example.com' })).host, 'example.com') + assert.equal(reqLogFields(mockReq({ host: 'data-fair:8080' })).host, '-') + assert.equal(reqLogFields(mockReq({ host: 'localhost:5600' })).host, '-') + assert.equal(reqLogFields(mockReq({})).host, '-') + }) +}) + +describe('sessionLogFields', () => { + it('describes the user and the active account', () => { + const fields = sessionLogFields({ lang: 'fr', user: { id: 'u1', name: 'User 1', email: 'u@x.org', organizations: [] }, account: { type: 'organization', id: 'o1', name: 'Org 1', department: 'dep1' }, accountRole: 'admin' }) + assert.deepEqual(fields, { userId: 'u1', userName: 'User 1', accountKey: 'organization.o1', accountDep: 'dep1', accountName: 'Org 1' }) + }) + + it('omits missing values', () => { + assert.deepEqual(sessionLogFields({ lang: 'fr' }), {}) + }) +}) diff --git a/packages/express/req-log-context.ts b/packages/express/req-log-context.ts new file mode 100644 index 0000000..0aa8bee --- /dev/null +++ b/packages/express/req-log-context.ts @@ -0,0 +1,31 @@ +// fields of the implicit log context of a request, see withLogContext in lib-node/log.js + +import type { IncomingMessage } from 'node:http' +import type { Request } from 'express' +import type { SessionState } from '@data-fair/lib-common-types/session/index.js' +import type { LogContext } from '@data-fair/lib-node/log.js' +import { reqIp } from './req-origin.js' + +export function reqLogFields (req: Request | IncomingMessage): { ip?: string, host: string } { + let host = req.headers.host + // internal calls are not attributed to a site + if (!host || host.startsWith('localhost') || host.endsWith(':8080')) host = '-' + const fields: { ip?: string, host: string } = { host } + const ip = reqIp(req, { optional: true }) + if (ip) fields.ip = ip + return fields +} + +export function sessionLogFields (state: SessionState): LogContext { + const fields: LogContext = {} + if (state.user) { + fields.userId = state.user.id + fields.userName = state.user.name + } + if (state.account) { + fields.accountKey = state.account.type + '.' + state.account.id + if (state.account.department) fields.accountDep = state.account.department + fields.accountName = state.account.name + } + return fields +} diff --git a/packages/express/req-origin.test.ts b/packages/express/req-origin.test.ts index 8fe2bf5..84ff69f 100644 --- a/packages/express/req-origin.test.ts +++ b/packages/express/req-origin.test.ts @@ -1,6 +1,7 @@ import { describe, it } from 'node:test' import { strict as assert } from 'assert' import { reqOrigin, reqHost, reqIp, ipRateLimitKey, reqIsInternal, assertReqInternal, assertReqInternalSecret, secretKeyMatches } from './req-origin.js' +import { _resetLogger } from '@data-fair/lib-node/log.js' import type { Request } from 'express' import type { IncomingMessage } from 'node:http' @@ -87,16 +88,15 @@ describe('reqIp', () => { // appended to it, so the first one may be what the client chose. Still the origin, so it is used, // but the environment is flagged (once, then at most hourly) instead of failing every request. it('should take the first of several IPs, and flag the environment once', () => { - const errors: string[] = [] - const originalError = console.error - console.error = (...args: unknown[]) => { errors.push(String(args[0])) } + const lines: any[] = [] + _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }) try { assert.equal(reqIp(mockReq({ 'x-forwarded-for': '10.0.0.1, 192.168.1.1' })), '10.0.0.1') assert.equal(reqIp(mockReq({ 'x-forwarded-for': '10.0.0.2, 192.168.1.1' })), '10.0.0.2') } finally { - console.error = originalError + _resetLogger() } - const flags = errors.filter(e => e.startsWith('[x-forwarded-for-several]')) + const flags = lines.filter(l => l.code === 'x-forwarded-for-several').map(l => l.msg) assert.equal(flags.length, 1) assert.match(flags[0], /must overwrite it/) }) @@ -137,8 +137,18 @@ describe('reqIp', () => { assert.equal(reqIp(mockReq({ 'x-forwarded-for': '10.0.0.1, 192.168.1.1' }), { optional: true }), '10.0.0.1') }) - it('still throws on a value that is not an IP', () => { - assert.throws(() => reqIp(mockReq({ 'x-forwarded-for': 'not-an-ip' }), { optional: true }), /not valid/) + it('returns undefined and flags the environment on a value that is not an IP', () => { + const lines: any[] = [] + _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }) + try { + assert.equal(reqIp(mockReq({ 'x-forwarded-for': 'not-an-ip' }), { optional: true }), undefined) + assert.equal(reqIp(mockReq({ 'x-forwarded-for': 'still-not-an-ip' }), { optional: true }), undefined) + } finally { + _resetLogger() + } + const flags = lines.filter(l => l.code === 'x-forwarded-for-invalid') + assert.equal(flags.length, 1) + assert.equal(flags[0].level, 'error') }) it('works on a plain IncomingMessage (websocket upgrade)', () => { diff --git a/packages/express/req-origin.ts b/packages/express/req-origin.ts index 1f221a1..feb3b3c 100644 --- a/packages/express/req-origin.ts +++ b/packages/express/req-origin.ts @@ -3,7 +3,7 @@ import type { IncomingMessage } from 'node:http' import { isIP } from 'node:net' import { createHash, timingSafeEqual } from 'node:crypto' import { httpError } from '@data-fair/lib-utils/http-errors.js' -import { internalError } from '@data-fair/lib-node/observer.js' +import log from '@data-fair/lib-node/log.js' export const reqHost = (req: Request) => { const forwardedHost = req.get('x-forwarded-host') @@ -42,12 +42,12 @@ export const reqOrigin = (req: Request) => { // first occurrence in the process, then at most hourly: an appending environment would otherwise // log an error per request and bury the cause in its own noise const FLAG_INTERVAL_MS = 60 * 60 * 1000 -let lastFlagged: number | undefined -const flagAppendedForwardedFor = (value: string) => { +const lastFlagged: Record = {} +const flagForwardedFor = (code: string, message: string) => { const now = Date.now() - if (lastFlagged !== undefined && now - lastFlagged < FLAG_INTERVAL_MS) return - lastFlagged = now - internalError('x-forwarded-for-several', `X-Forwarded-For holds several IPs ("${value}"): a layer appends to it, so its first entry can be chosen by the client. The edge proxy must overwrite it with the client address.`) + if (lastFlagged[code] !== undefined && now - lastFlagged[code] < FLAG_INTERVAL_MS) return + lastFlagged[code] = now + log.error(message, { code }) } // read from req.headers and not req.get: this is also used on the plain IncomingMessage @@ -55,7 +55,8 @@ const flagAppendedForwardedFor = (value: string) => { // // Strict by default: a request is limited by its user or by this IP, and one with neither is a // misconfiguration. `optional` is for the places where no client IP is legitimate (audit logs, a -// relay deciding what to forward): undefined without the header, still an error on a non-IP value. +// relay deciding what to forward): undefined without the header, and undefined on a non-IP value +// (the environment is flagged, a misconfigured proxy must not fail every request of these places). export function reqIp (req: Request | IncomingMessage): string export function reqIp (req: Request | IncomingMessage, options: { optional: true }): string | undefined export function reqIp (req: Request | IncomingMessage, options?: { optional?: boolean }): string | undefined { @@ -70,11 +71,18 @@ export function reqIp (req: Request | IncomingMessage, options?: { optional?: bo // appended to it, so the first one may be what the client chose: it is still the origin and is // used, but the environment is flagged rather than failing every request of a live deployment. if (ip.includes(',')) { - flagAppendedForwardedFor(ip) + flagForwardedFor('x-forwarded-for-several', `X-Forwarded-For holds several IPs ("${ip}"): a layer appends to it, so its first entry can be chosen by the client. The edge proxy must overwrite it with the client address.`) ip = ip.split(',')[0] } ip = ip.trim() - if (!isIP(ip)) throw new Error(`The "X-Forwarded-For" header should contain an IP. "${ip}" is not valid.`) + if (!isIP(ip)) { + const message = `The "X-Forwarded-For" header should contain an IP. "${ip}" is not valid.` + if (options?.optional) { + flagForwardedFor('x-forwarded-for-invalid', message) + return undefined + } + throw new Error(message) + } return ip } @@ -126,7 +134,7 @@ export const assertReqInternalSecret = (req: Request, expectedSecretKey: string) assertReqInternal(req) let secretKey = req.get('x-secret-key') if (!secretKey && typeof req.query.key === 'string') { - console.warn('passing internal secret key through query parameter is not recommended, use x-secret-key header') + log.warn('passing internal secret key through query parameter is not recommended, use x-secret-key header') secretKey = req.query.key } if (!secretKeyMatches(secretKey, expectedSecretKey)) throw httpError(401, 'Bad secret key') diff --git a/packages/express/req-perf.ts b/packages/express/req-perf.ts index 70c59ea..7a93575 100644 --- a/packages/express/req-perf.ts +++ b/packages/express/req-perf.ts @@ -1,6 +1,7 @@ import type { Request, Response, NextFunction } from 'express' import { Histogram } from 'prom-client' import Debug from 'debug' +import log from '@data-fair/lib-node/log.js' const debugReq = Debug('df:observe:req') @@ -36,7 +37,7 @@ export const reqPerfStep = (req: Request, stepName: string) => { const reqObserve: { start: number, step: number, routeName?: string } = (req as unknown as any)[reqObserveKey] if (!reqObserve) { - console.warn('reqStep was called on a request that was not initialized for observation') + log.warn('reqStep was called on a request that was not initialized for observation') return } @@ -44,7 +45,7 @@ export const reqPerfStep = (req: Request, stepName: string) => { reqObserve.routeName = req.route?.path } if (!reqObserve.routeName) { - console.warn('reqStep was called on a request without a route name') + log.warn('reqStep was called on a request without a route name') return } @@ -53,7 +54,7 @@ export const reqPerfStep = (req: Request, stepName: string) => { reqStepHistogram.labels(reqObserve.routeName, stepName).observe(duration / 1000) debugReq('request', req.method, req.url, stepName, duration, 'ms') if (duration > 1000 && stepName !== 'total' && stepName !== 'finish') { - console.log('request', req.method, req.url, stepName, duration, 'ms') + log.info('slow request step', { method: req.method, url: req.url, routeName: reqObserve.routeName, step: stepName, duration }) } reqObserve.step = now } diff --git a/packages/express/session.test.ts b/packages/express/session.test.ts index 354c4e5..c8ec955 100644 --- a/packages/express/session.test.ts +++ b/packages/express/session.test.ts @@ -1,8 +1,9 @@ -import { describe, it } from 'node:test' +import { describe, it, after } from 'node:test' import { strict as assert } from 'assert' import { Session, session as defaultSession, requireScope, assertReqScope, allowAnyScope, markScopeChecked, reqSession, reqSessionAuthenticated, reqAdminMode, reqUser, reqUserAuthenticated, setReqUser, setReqSession } from './session.js' import type { Request, Response } from 'express' import type { SessionState, User } from '@data-fair/lib-common-types/session/index.js' +import log, { _resetLogger } from '@data-fair/lib-node/log.js' const testUser: User = { email: 'test@example.com', @@ -197,6 +198,48 @@ describe('Session.middleware', () => { }) }) +describe('Session.middleware log context', () => { + const captureLogs = () => { + const lines: any[] = [] + _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }) + return lines + } + after(() => _resetLogger()) + + it('opens a log context with request and session fields for later handlers', async () => { + const lines = captureLogs() + const session = new Session() + session.readState = async () => ({ lang: 'fr', user: testUser, account: { type: 'organization', id: 'org1', name: 'Test Org' }, accountRole: 'admin' }) + await session.middleware()(mockReq('GET', { host: 'example.com', 'x-forwarded-for': '203.0.113.7' }), mockRes(), () => { log.info('in route') }) + assert.equal(lines[0].userId, 'user1') + assert.equal(lines[0].userName, 'Test User') + assert.equal(lines[0].accountKey, 'organization.org1') + assert.equal(lines[0].ip, '203.0.113.7') + assert.equal(lines[0].host, 'example.com') + }) + + it('hands session failures to next(err) inside the request scope', async () => { + const lines = captureLogs() + const session = new Session() + session.readState = async () => { throw Object.assign(new Error('bad'), { status: 401 }) } + await session.middleware()(mockReq('GET', { host: 'example.com' }), mockRes(), (err?: any) => { log.warn(err.message, { code: 'unauthorized-req' }) }) + assert.equal(lines[0].host, 'example.com') + assert.equal(lines[0].code, 'unauthorized-req') + assert.equal(lines[0].msg, 'bad') + }) + + it('logging a scoped session does not trigger the scope check', async () => { + const lines = captureLogs() + const session = new Session() + session.scopeAware = true + session.readState = async () => ({ lang: 'fr', user: { ...testUser, scope: 'datasets:read' }, account: { type: 'user', id: 'user1', name: 'Test User' }, accountRole: 'admin', scopes: ['datasets:read'] }) + let error: any + await session.middleware()(mockReq(), mockRes(), (err?: any) => { error = err; log.info('in route') }) + assert.equal(error, undefined) + assert.equal(lines[0].userId, 'user1') + }) +}) + describe('Session.req IP binding', () => { const boundAdminUser: User = { ...adminUser, boundIp: '1.2.3.4' } const boundAdminState: SessionState = { @@ -534,51 +577,24 @@ describe('scope checks are required per route', () => { session.readState = async () => raw() const req = mockReq() await assert.rejects(session.req(req), (err: any) => err.status === 401 && /invalid scope claim/.test(err.message)) - await assert.rejects(Promise.resolve(session.middleware()(mockReq(), mockRes(), () => {})), (err: any) => err.status === 401) + let error: any + await session.middleware()(mockReq(), mockRes(), (err?: any) => { error = err }) + assert.equal(error?.status, 401) }) it('sync accessors after a failed middleware do not throw a TypeError', async () => { const session = new Session() session.readState = async () => { throw Object.assign(new Error('x'), { status: 401 }) } const req = mockReq() - await assert.rejects(Promise.resolve(session.middleware()(req, mockRes(), () => {}))) + let error: any + await session.middleware()(req, mockRes(), (err?: any) => { error = err }) + assert.equal(error?.status, 401) assert.equal(reqSession(req), undefined) assert.equal(reqUser(req), undefined) assert.throws(() => reqSessionAuthenticated(req), (err: any) => err.status === 401) assert.throws(() => reqUserAuthenticated(req), (err: any) => err.status === 401) assert.throws(() => reqAdminMode(req), (err: any) => err.status === 401) }) - - it('reqForLogs reports infrastructure errors but stays silent on 401/403', async () => { - const calls: any[] = [] - const failing = new Session() - failing.onLogsError = (err: any) => calls.push(err) - failing.readState = async () => { throw new Error('mongo down') } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - failing.readState = async () => { throw Object.assign(new Error('boom'), { status: 503 }) } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - failing.readState = async () => { throw Object.assign(new Error('nope'), { status: 401 }) } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - failing.readState = async () => { throw Object.assign(new Error('nope'), { status: 403 }) } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - assert.equal(calls.length, 2) - }) - - it('reqForLogs never throws even when reporting throws', async () => { - const failing = new Session() - failing.onLogsError = () => { throw new Error('reporter broke') } - failing.readState = async () => { throw new Error('mongo down') } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - }) - - it('reqForLogs never throws', async () => { - const { session, req } = await setup(scopedState) - const state = await session.reqForLogs(req) - assert.deepEqual(state?.scopes, ['datasets:read']) - const failing = new Session() - failing.readState = async () => { throw Object.assign(new Error('nope'), { status: 401 }) } - assert.equal(await failing.reqForLogs(mockReq()), undefined) - }) }) describe('requireScope without the session middleware', () => { diff --git a/packages/express/session.ts b/packages/express/session.ts index ccdcbe6..504b143 100644 --- a/packages/express/session.ts +++ b/packages/express/session.ts @@ -6,7 +6,8 @@ import { assertAdminMode, assertAuthenticated, assertScope } from '@data-fair/li import { httpError } from '@data-fair/lib-utils/http-errors.js' import { reqSitePathSafe, reqIp, reqOrigin } from '@data-fair/lib-express' import { SessionHandler } from '@data-fair/lib-node/session.js' -import { internalError } from '@data-fair/lib-node/observer.js' +import { withLogContext } from '@data-fair/lib-node/log.js' +import { reqLogFields, sessionLogFields } from './req-log-context.js' export * from '@data-fair/lib-common-types/session/index.js' @@ -76,25 +77,6 @@ export class Session extends SessionHandler { return sessionState } - /** @internal logging only, never for authorization */ - // reads the session for logging only: never throws, ignores the scope check requirement - async reqForLogs (req: Request | IncomingMessage): Promise { - try { - return await this.loadState(req) - } catch (err: any) { - // 401/403 are expected refusals; anything else (jwks fetch, infrastructure) must not vanish - if (!err?.status || err.status >= 500) { - try { this.onLogsError(err) } catch { /* reporting must never throw either */ } - } - return undefined - } - } - - /** @internal test seam, not API */ - onLogsError (err: unknown) { - internalError('event-log-session', err) - } - private async loadState (req: Request | IncomingMessage, res?: Response | ServerResponse): Promise { // @ts-ignore if (req[sessionKey]) return req[sessionKey] @@ -205,11 +187,19 @@ export class Session extends SessionHandler { } } + // also opens the implicit log context of the request (ip, host, user, account) middleware (options: { required?: boolean, adminOnly?: boolean } = {}): RequestHandler { - return async (req, res, next) => { - // @ts-ignore - req[sessionMiddlewareKey] = true - const sessionState = await this.loadState(req, res) + return (req, res, next) => withLogContext(reqLogFields(req), async () => { + // errors are handed to next() from inside the scope, so that the error handler's lines keep the context + let sessionState: SessionState + try { + // @ts-ignore + req[sessionMiddlewareKey] = true + sessionState = await this.loadState(req, res) + } catch (err) { + next(err) + return + } if (sessionState.user?.pseudoSession && req.method !== 'GET') { res.status(403).send('pseudo session only allows GET requests') return @@ -226,8 +216,9 @@ export class Session extends SessionHandler { } } } - next() - } + // not an authorization use of the session, the scope check does not apply + withLogContext(sessionLogFields(sessionState), next) + }) } } diff --git a/packages/express/ws-server.ts b/packages/express/ws-server.ts index 0521229..547ae3c 100644 --- a/packages/express/ws-server.ts +++ b/packages/express/ws-server.ts @@ -22,7 +22,7 @@ import { nanoid } from 'nanoid' import { WebSocketServer } from 'ws' import { assertScope } from '@data-fair/lib-common-types/session/index.js' import { session, markScopeChecked } from '@data-fair/lib-express' -import { internalError } from '@data-fair/lib-node/observer.js' +import log from '@data-fair/lib-node/log.js' import { initMessagesCollection } from '@data-fair/lib-node/ws-emitter.js' let cursor: any @@ -138,7 +138,7 @@ export const start = async ( } catch (err: any) { const status = err.status ?? err.statusCode ?? 500 const errorMessage: Message = { type: 'error', status, data: err.message ?? err, channel: message?.channel } - if (status >= 500) internalError('ws-error', err) + if (status >= 500) log.error('failure while handling a websocket message', { code: 'ws-error', err }) return ws.send(JSON.stringify(errorMessage)) } }) @@ -204,7 +204,7 @@ const initCursor = async (db: Db, messagesCollection: Collection) => { } } catch (err: any) { if (stopped) break - console.log('WS tailable cursor was interrupted, reinit it', err && err.message) + log.info('WS tailable cursor was interrupted, reinit it', { err }) } } } diff --git a/packages/node/README.md b/packages/node/README.md index 5f7a2e8..0334d71 100644 --- a/packages/node/README.md +++ b/packages/node/README.md @@ -12,7 +12,8 @@ Peer dependencies, all declared optional: install the ones required by the modul | Peer dependency | Needed by | | --- | --- | -| `prom-client@15` | `observer.js`, `http-agents.js` and everything built on them (`axios.js`, `events-queue.js`…) | +| `prom-client@15` | `observer.js`, `http-agents.js` and everything built on them (`axios.js`, `events-queue.js`…); without it `log.js` does not count log lines | +| `pino-pretty@13` | pretty output of `log.js` in dev (falls back to JSON without it) | | `mongodb@6` | `mongo.js`, `locks.js`, `upgrade-scripts.js` | | `ws@8` | `ws-client.js` | | `tough-cookie@5` | `axios-with-cookies.js`, `axios-auth.js` | @@ -28,7 +29,8 @@ There is no root entry point: import each module by its path. | `@data-fair/lib-node/ssrf.js` | SSRF checks for clients that don't use the agents above: `resolvePublicAddress()`, `publicLookup`, `SsrfError`. | | `@data-fair/lib-node/axios-with-cookies.js` | Axios instance with a `tough-cookie` cookie jar. | | `@data-fair/lib-node/axios-auth.js` | Axios instance logged into simple-directory with email/password. Integration tests only. | -| `@data-fair/lib-node/observer.js` | Mini web server exposing Prometheus metrics and CPU/heap profiles, plus the shared `internalError()` counter. | +| `@data-fair/lib-node/log.js` | The logger of the stack: JSON lines on stdout (pretty in dev), implicit context, metrics, `debug` output redirected. | +| `@data-fair/lib-node/observer.js` | Mini web server exposing Prometheus metrics and CPU/heap profiles. | | `@data-fair/lib-node/mongo.js` | `Mongo` connection wrapper (default export: a singleton) with declarative named index management (`configure()`). | | `@data-fair/lib-node/locks.js` | Distributed locks stored in a MongoDB `locks` collection with a TTL (default export: a singleton). | | `@data-fair/lib-node/upgrade-scripts.js` | Runner for the database migration scripts of a service. | @@ -64,6 +66,78 @@ For clients that don't use these agents (ftp, sftp, raw sockets, SDKs…), `@dat See the [`data-fair-security` skill](https://github.com/data-fair/lib/tree/main/skills/data-fair-security) for the stack-wide rules. +## Logging + +One logger for everything, imported where needed, never passed around: + +```ts +import log, { withLogContext } from '@data-fair/lib-node/log.js' + +log.info('dataset finalized', { datasetId }) +log.info('memory deleted', { code: 'agents.memory.delete' }) +log.warn('forbidden request', { code: 'forbidden-req', err }) +log.alert('admin api key created', { code: 'df.apikeys.createadmin' }) +log.error('failed to create mongo index', { code: 'mongo-index-fail', err, collection }) + +log.init({ service: 'data-fair' }) // optional, defaults to OTEL_SERVICE_NAME +``` + +Every method has the same signature `(msg, fields?)` and never throws. Do not use the keys written by pino (`level`, `time`, `msg`, `hostname`) as field names, they would be duplicated in the JSON line. + +| Level | Use | Emitted | Counted | +| --- | --- | --- | --- | +| `debug` | through the `debug` module (see below) | only namespaces enabled by `DEBUG` | no | +| `info` | normal operations, audit trail | always | no | +| `warn` | client errors, suspicious but expected situations | always | yes | +| `alert` | events that are not failures but deserve the same scrutiny as errors (mostly security) | always | yes | +| `error` | internal failures only, never client errors | always | yes | + +**Output**: one JSON object per line on stdout when `NODE_ENV=production`, pretty output otherwise (`LOG_FORMAT=json|pretty` overrides). Fields: `time`, `level` (label), `msg`, `hostname`, `service`, `code`, `err`, the context fields, the per-call fields, and `trace_id` / `span_id` / `trace_flags` when OpenTelemetry is active. + +**Codes**: `code` is optional on every line. It must be a **static string** (`mongo-index-fail`, `df.apikeys.createadmin`): never put ids, hosts or other dynamic values in it, they go in other fields. It labels the counters. + +**Errors**: pass them as the `err` field. They are serialized with a whitelist (`type`, `message`, `stack`, primitive `code`, `status`, `cause`, and `method` / `url` without query string for axios errors), so headers, request config and document content carried by errors never reach the logs. Messages are truncated to 1000 characters (the message of an `AxiosRequestError` starts with the response body). + +**Metrics**: `warn`, `alert` and `error` lines increment `df_logs{level, code, host}`. Deprecated, kept during the transition: `df_internal_error{errorCode}` (error lines) and `df_events_log{level, code, host}` (coded warn and alert lines). + +**Debug**: keep using the `debug` module (`import Debug from 'debug'`), `DEBUG=ns1,ns2*` works as before. When `log.js` is loaded, the output of the shared `debug` module is redirected into the logger as `debug` lines with a `ns` field. A third-party library bundling its own copy of `debug` is not redirected. + +### Implicit context + +The fields of the current context are added to every line. `session.middleware()` of `@data-fair/lib-express` opens a context per request with `ip`, `host`, `userId`, `userName`, `accountKey`, `accountDep`, `accountName`. Any code can add fields for a scope: + +```ts +await withLogContext({ datasetId }, async () => { + // every line logged in here, even deep in the call stack, carries datasetId +}) +``` + +Rules: + +- only small immutable values (ids, keys, short names), never `req`, documents or buffers: they stay in memory as long as the scope is alive, +- create long-lived resources (pools, intervals, caches, queues) at startup, outside any scope, or they capture it and attribute their later lines to the wrong user, +- event listeners run in the context of the code that emits, not of the code that subscribed. + +Worker threads have their own context: pass `getLogContext()` in the task payload and wrap the task with `withLogContext(payload.logContext, ...)` in the worker. + +### OpenTelemetry + +Nothing to do in the code. Activate the OpenTelemetry Operator auto-instrumentation on the Kubernetes side: its pino instrumentation adds `trace_id`, `span_id` and `trace_flags` to the lines, and the `traceparent` header is propagated on outgoing HTTP calls (third parties included). Set `OTEL_LOGS_EXPORTER=none` so that logs are not also shipped over OTLP. Without the operator (dev, tests, scripts) lines have no trace fields. + +### Migration + +| Before | After | +| --- | --- | +| `eventsLog.info(code, msg, ctx)` | `log.info(msg, { code })` | +| `eventsLog.warn(code, msg, ctx)` | `log.warn(msg, { code })` | +| `eventsLog.alert(code, msg, ctx)` | `log.alert(msg, { code })` | +| `internalError(code, err)` | `log.error(msg, { code, err })` | +| `console.log` / `console.warn` / `console.error` | `log.info` / `log.warn` / `log.error` with a code | +| `EVENTS_LOG_LEVEL` | removed, every level but debug is emitted | +| `import Debug from 'debug'` | unchanged | + +User, account, ip and host of `eventsLog`'s context argument now come from the implicit context. + ## Observer A very light web server for observability, on port 9090 by default: @@ -74,19 +148,13 @@ A very light web server for observability, on port 9090 by default: - `GET /heap-snapshot`: full retained heap snapshot (blocks the event loop while V8 walks the heap). ```ts -import { startObserver, stopObserver, internalError } from '@data-fair/lib-node/observer.js' +import { startObserver, stopObserver } from '@data-fair/lib-node/observer.js' await startObserver() // or startObserver(port) // ... await stopObserver() ``` -`internalError(errorCode, error, ...optionalParams)` increments the shared `df_internal_error` counter and logs the error. Use it for anomalies that should trigger alerts, not for client errors: - -```ts -internalError('http', 'failure while serving http request', err) -``` - Process metrics are plain `prom-client` metrics. A service-level metric (its value depends on a shared state, like the database, not on the activity of the current process) is registered in `servicePromRegistry`: ```ts diff --git a/packages/node/events-queue.ts b/packages/node/events-queue.ts index 44bac59..14aacce 100644 --- a/packages/node/events-queue.ts +++ b/packages/node/events-queue.ts @@ -1,6 +1,6 @@ import { type Event } from '@data-fair/lib-common-types/event/index.js' import { type Notification } from '@data-fair/lib-common-types/notification/index.js' -import { internalError } from '@data-fair/lib-node/observer.js' +import log from './log.js' // the events service is part of our own infrastructure (configuration, not user input) import { privateAxiosInstance as axios } from './axios.js' import Debug from 'debug' @@ -34,7 +34,7 @@ export class EventsQueue { // events is an optional service: without its url it is not deployed and events are dropped let inactive = !!options.inactive || !options.eventsUrl if (!inactive && !options.eventsSecret) { - internalError('events-queue', 'the events service url is set but its secret is missing, events are dropped') + log.error('the events service url is set but its secret is missing, events are dropped', { code: 'events-queue' }) inactive = true } this._options = { ...options, inactive } @@ -64,7 +64,7 @@ export class EventsQueue { try { await axios.post(this.options().eventsUrl + '/api/events', events, { headers: { 'x-secret-key': this.options().eventsSecret } }) } catch (err: any) { - internalError('events-queue-push-event', err) + log.error('failure to push events', { code: 'events-queue-push-event', err }) // retry later if (err.status >= 500 && events.length < 1000) this.eventsQueue = events.concat(this.eventsQueue) } @@ -77,7 +77,7 @@ export class EventsQueue { try { await axios.post(this.options().eventsUrl + '/api/notifications', notification, { headers: { 'x-secret-key': this.options().eventsSecret } }) } catch (err: any) { - internalError('events-queue-push-notif', err) + log.error('failure to push a notification', { code: 'events-queue-push-notif', err }) // retry later if (err.status >= 500 && (notifications.length + this.notificationsQueue.length) < 1000) { this.notificationsQueue.unshift(notification) diff --git a/packages/node/http-agents.ts b/packages/node/http-agents.ts index 4dbbddc..eebbc21 100644 --- a/packages/node/http-agents.ts +++ b/packages/node/http-agents.ts @@ -13,6 +13,7 @@ import CacheableLookup from 'cacheable-lookup' import HttpAgent, { HttpsAgent } from 'agentkeepalive' import { Counter, Gauge } from 'prom-client' import { SsrfHttpAgent, SsrfHttpsAgent, getSsrfRules, getProxyEnvName } from './ssrf.js' +import log from './log.js' // not very high number of sockets but we don't want to saturate our reverse proxies // if a higher number is needed the service should probably be scaled anyway @@ -29,7 +30,7 @@ export const privateHttpsAgent = new HttpsAgent(keepaliveOpts) const createPublicAgents = () => { const proxyEnvName = getProxyEnvName() if (proxyEnvName) { - console.warn(`WARNING: ${proxyEnvName} is defined, the protection against server side request forgery (SSRF) is disabled, outgoing requests are not checked against non public addresses`) + log.warn(`${proxyEnvName} is defined, the protection against server side request forgery (SSRF) is disabled, outgoing requests are not checked against non public addresses`) return { httpAgent: new HttpAgent(keepaliveOpts), httpsAgent: new HttpsAgent(keepaliveOpts) } } const rules = getSsrfRules() diff --git a/packages/node/locks.ts b/packages/node/locks.ts index ffaab20..e199a2f 100644 --- a/packages/node/locks.ts +++ b/packages/node/locks.ts @@ -2,7 +2,7 @@ import type { Db } from 'mongodb' import { hostname } from 'node:os' import { randomBytes } from 'node:crypto' import Debug from 'debug' -import { internalError } from './observer.js' +import log from './log.js' const debug = Debug('locks') @@ -31,7 +31,7 @@ export class Locks { try { await this.collection.createIndex({ updatedAt: 1 }, { expireAfterSeconds: ttl }) } catch (err) { - console.log('Failure to create TTL index. Probably because the value changed. Try to update it.') + log.info('Failure to create TTL index. Probably because the value changed. Try to update it.') db.command({ collMod: 'locks', index: { keyPattern: { updatedAt: 1 }, expireAfterSeconds: ttl } }) } @@ -39,7 +39,7 @@ export class Locks { // a mongo error here must not become an unhandled rejection (it would crash the process on any failover) this.interval = setInterval(() => { this.collection.updateMany({ pid: this.pid }, { $currentDate: { updatedAt: true } }) - .catch(err => internalError('locks-heartbeat', err)) + .catch(err => log.error('failure to prolongate locks', { code: 'locks-heartbeat', err })) }, (ttl / 2) * 1000) } diff --git a/packages/node/log-err.test.ts b/packages/node/log-err.test.ts new file mode 100644 index 0000000..3337cfa --- /dev/null +++ b/packages/node/log-err.test.ts @@ -0,0 +1,70 @@ +import { describe, it } from 'node:test' +import { strict as assert } from 'assert' +import { serializeErr } from './log-err.js' + +describe('serializeErr', () => { + it('keeps only whitelisted fields of an Error', () => { + const err = Object.assign(new Error('boom'), { code: 'E1', status: 500, keyValue: { email: 'a@b.c' }, secret: 'x' }) + const s = serializeErr(err) + assert.deepEqual(Object.keys(s).sort(), ['code', 'message', 'stack', 'status', 'type']) + assert.equal(s.type, 'Error') + assert.equal(s.message, 'boom') + }) + + it('uses the error name as type', () => { + class MongoServerError extends Error { constructor (m: string) { super(m); this.name = 'MongoServerError' } } + assert.equal(serializeErr(new MongoServerError('dup')).type, 'MongoServerError') + }) + + it('maps statusCode to status', () => { + assert.equal(serializeErr(Object.assign(new Error('x'), { statusCode: 404 })).status, 404) + }) + + it('drops non primitive code', () => { + assert.equal(serializeErr(Object.assign(new Error('x'), { code: { a: 1 } })).code, undefined) + }) + + it('never leaks axios request headers and strips the query string', () => { + const err = Object.assign(new Error('timeout'), { isAxiosError: true, config: { method: 'get', url: 'https://x.org/p?apiKey=s3cret', headers: { Authorization: 'Bearer s3cret' } } }) + const json = JSON.stringify(serializeErr(err)) + assert.ok(!json.includes('s3cret')) + assert.ok(json.includes('"url":"https://x.org/p"')) + assert.ok(json.includes('"method":"get"')) + }) + + it('handles AxiosRequestError shape without bodies', () => { + const err = Object.assign(new Error('500 - fail'), { name: 'AxiosRequestError', status: 500, config: { method: 'post', url: 'http://a/b?k=v', data: 'body' }, data: { secret: 1 }, headers: { 'set-cookie': 'x' } }) + const s = serializeErr(err) + assert.equal(s.url, 'http://a/b') + assert.equal(s.status, 500) + assert.ok(!JSON.stringify(s).includes('secret')) + assert.ok(!JSON.stringify(s).includes('body')) + }) + + it('truncates long messages and the message line of stacks', () => { + const body = JSON.stringify({ echoed: 'Bearer SECRET', doc: 'x'.repeat(5000) }) + const err = Object.assign(new Error(`500 - ${body}`), { name: 'AxiosRequestError', status: 500 }) + const s = serializeErr(err) + assert.ok(s.message.length <= 1001, `message length ${s.message.length}`) + assert.ok((s.stack ?? '').length < 2000, `stack length ${s.stack?.length}`) + assert.ok(s.stack?.includes('at ')) + }) + + it('serializes cause recursively and stops on cycles', () => { + const a: any = new Error('a') + const b: any = new Error('b', { cause: a }) + a.cause = b + const s = serializeErr(b) + assert.equal(s.cause?.message, 'a') + assert.doesNotThrow(() => JSON.stringify(s)) + }) + + it('accepts non Error values', () => { + assert.equal(serializeErr('plain').message, 'plain') + assert.equal(serializeErr(null).message, 'null') + assert.equal(serializeErr(undefined).message, 'undefined') + const s = serializeErr({ message: 'obj', token: 'tok' }) + assert.equal(s.message, 'obj') + assert.ok(!JSON.stringify(s).includes('tok')) + }) +}) diff --git a/packages/node/log-err.ts b/packages/node/log-err.ts new file mode 100644 index 0000000..193ff98 --- /dev/null +++ b/packages/node/log-err.ts @@ -0,0 +1,48 @@ +// whitelist serializer for errors in logs +// pino's standard serializer copies all enumerable properties, which leaks secrets for us +// (axios config headers, request and response bodies, mongo document content, etc.) + +export interface SerializedErr { + type?: string + message: string + stack?: string + code?: string | number + status?: number + method?: string + url?: string + cause?: SerializedErr +} + +const maxDepth = 5 +// messages can embed response bodies (AxiosRequestError) and the stack repeats the message +const maxMessageLength = 1000 + +const truncate = (text: string) => text.length > maxMessageLength ? text.slice(0, maxMessageLength) + '…' : text + +const truncateStackHeader = (stack: string) => { + const framesIndex = stack.indexOf('\n at ') + if (framesIndex === -1) return truncate(stack) + return truncate(stack.slice(0, framesIndex)) + stack.slice(framesIndex) +} + +const isPrimitiveCode = (value: unknown): value is string | number => typeof value === 'string' || typeof value === 'number' + +export function serializeErr (value: unknown, depth = 0): SerializedErr { + if (value === null || typeof value !== 'object') return { message: truncate(String(value)) } + const err = value as Record + const s: SerializedErr = { message: truncate(typeof err.message === 'string' ? err.message : String(value)) } + if (value instanceof Error) s.type = err.name && err.name !== 'Error' ? err.name : err.constructor?.name ?? 'Error' + if (typeof err.stack === 'string') s.stack = truncateStackHeader(err.stack) + if (isPrimitiveCode(err.code)) s.code = err.code + const status = err.status ?? err.statusCode + if (typeof status === 'number') s.status = status + if (err.isAxiosError === true || err.name === 'AxiosRequestError') { + if (typeof err.config?.method === 'string') s.method = err.config.method + if (typeof err.config?.url === 'string') s.url = err.config.url.split('?')[0] + } + // the depth limit also stops circular causes + if (err.cause !== undefined && depth < maxDepth) { + s.cause = serializeErr(err.cause, depth + 1) + } + return s +} diff --git a/packages/node/log-worker.test.ts b/packages/node/log-worker.test.ts new file mode 100644 index 0000000..99416ec --- /dev/null +++ b/packages/node/log-worker.test.ts @@ -0,0 +1,16 @@ +import { describe, it } from 'node:test' +import { strict as assert } from 'assert' +import { Worker } from 'node:worker_threads' +import { getLogContext, withLogContext } from './log.js' + +describe('log context in worker threads', () => { + it('is propagated through the task payload', async () => { + const line = await withLogContext({ datasetId: 'w1' }, () => new Promise((resolve, reject) => { + const worker = new Worker(new URL('./test-fixtures/log-worker.js', import.meta.url), { workerData: { logContext: getLogContext() } }) + worker.once('message', resolve) + worker.once('error', reject) + })) + assert.equal(JSON.parse(line).datasetId, 'w1') + assert.equal(JSON.parse(line).msg, 'in worker') + }) +}) diff --git a/packages/node/log.test.ts b/packages/node/log.test.ts new file mode 100644 index 0000000..d5d8a86 --- /dev/null +++ b/packages/node/log.test.ts @@ -0,0 +1,177 @@ +import { describe, it, after } from 'node:test' +import { strict as assert } from 'assert' +import { hostname } from 'node:os' +import { Writable } from 'node:stream' +import { register } from 'prom-client' +import createDebug from 'debug' +// must be imported before log.js, to check that instances created earlier are redirected too +import { earlyDebug } from './test-fixtures/early-debug.js' +import log, { _resetLogger, withLogContext, getLogContext } from './log.js' + +// collect the JSON lines written by the logger +const capture = () => { + const lines: any[] = [] + _resetLogger({ format: 'json', destination: { write: (s: string) => { for (const l of s.split('\n')) if (l) lines.push(JSON.parse(l)) } } }) + return lines +} + +describe('log output', () => { + after(() => _resetLogger()) + + it('writes one JSON object per line with label level, ISO time, hostname and no pid', () => { + const lines = capture() + log.info('hello', { a: 1 }) + assert.equal(lines.length, 1) + assert.equal(lines[0].level, 'info') + assert.equal(lines[0].msg, 'hello') + assert.equal(lines[0].a, 1) + assert.match(lines[0].time, /^\d{4}-\d{2}-\d{2}T/) + assert.equal(lines[0].hostname, hostname()) + assert.equal(lines[0].pid, undefined) + }) + + it('supports the alert level between warn and error', () => { + const lines = capture() + log.alert('x', { code: 'c' }) + assert.equal(lines[0].level, 'alert') + assert.equal(lines[0].code, 'c') + }) + + it('adds service from init', () => { + const lines = capture() + log.init({ service: 'svc' }) + log.warn('x') + assert.equal(lines[0].service, 'svc') + }) + + it('pretty format writes human readable non-JSON output', () => { + const out: string[] = [] + // pino-pretty needs a real stream as destination + _resetLogger({ format: 'pretty', destination: new Writable({ write (chunk, _enc, cb) { out.push(chunk.toString()); cb() } }) }) + log.info('pretty hello') + assert.ok(out.join('').includes('pretty hello')) + assert.throws(() => JSON.parse(out[0])) + }) + + it('serializes err with the safe serializer', () => { + const lines = capture() + log.warn('x', { err: Object.assign(new Error('e'), { config: { headers: { Authorization: 'secret' } } }) }) + assert.equal(lines[0].err.message, 'e') + assert.ok(lines[0].err.stack) + assert.equal(lines[0].err.config, undefined) + }) + + it('never throws', () => { + capture() + const circular: any = {} + circular.self = circular + assert.doesNotThrow(() => log.info('x', circular)) + assert.doesNotThrow(() => log.error('x', { get boom () { throw new Error('getter') } })) + }) +}) + +const metricValues = async (name: string) => (await register.getSingleMetric(name)!.get()).values + +describe('log metrics', () => { + after(() => _resetLogger()) + + it('counts warn/alert/error in df_logs with level, code and host', async () => { + capture() + log.warn('w', { code: 'm-w', host: 'h1' }) + log.alert('a', { code: 'm-a' }) + log.error('e', { code: 'm-e' }) + const v = await metricValues('df_logs') + assert.ok(v.find(x => x.labels.code === 'm-w' && x.labels.level === 'warn' && x.labels.host === 'h1' && x.value === 1)) + assert.ok(v.find(x => x.labels.code === 'm-a' && x.labels.level === 'alert' && x.labels.host === '-' && x.value === 1)) + assert.ok(v.find(x => x.labels.code === 'm-e' && x.labels.level === 'error' && x.value === 1)) + }) + + it('does not count info lines', async () => { + capture() + log.info('i', { code: 'm-i' }) + assert.ok(!(await metricValues('df_logs')).find(x => x.labels.code === 'm-i')) + }) + + it('counts uncoded lines with an empty code', async () => { + capture() + log.warn('x', { host: 'm-uncoded' }) + assert.ok((await metricValues('df_logs')).find(x => x.labels.code === '' && x.labels.host === 'm-uncoded')) + }) + + it('keeps df_internal_error for error lines', async () => { + capture() + log.error('e', { code: 'm-ie' }) + assert.ok((await metricValues('df_internal_error')).find(x => x.labels.errorCode === 'm-ie' && x.value === 1)) + }) + + it('keeps df_events_log only for coded warn/alert', async () => { + capture() + log.alert('a', { code: 'm-ev-a' }) + log.warn('w', { host: 'm-ev-uncoded' }) + log.error('e', { code: 'm-ev-e' }) + const v = await metricValues('df_events_log') + assert.ok(v.find(x => x.labels.code === 'm-ev-a' && x.labels.level === 'alert' && x.value === 1)) + assert.ok(!v.find(x => x.labels.host === 'm-ev-uncoded')) + assert.ok(!v.find(x => x.labels.code === 'm-ev-e')) + }) +}) + +describe('log context', () => { + after(() => _resetLogger()) + + it('merges context into lines, per-call fields win', () => { + const lines = capture() + withLogContext({ datasetId: 'd1', host: 'ctx' }, () => withLogContext({ step: 's' }, () => log.info('x', { host: 'call' }))) + assert.equal(lines[0].datasetId, 'd1') + assert.equal(lines[0].step, 's') + assert.equal(lines[0].host, 'call') + }) + + it('isolates concurrent scopes across awaits and timers', async () => { + const lines = capture() + const run = (u: string) => withLogContext({ userId: u }, async () => { + await new Promise(resolve => setTimeout(resolve, u === 'a' ? 10 : 1)) + log.info(u) + await Promise.resolve() + log.info(u) + }) + await Promise.all([run('a'), run('b')]) + assert.equal(lines.length, 4) + for (const l of lines) assert.equal(l.userId, l.msg) + }) + + it('has no context outside scopes', () => { + const lines = capture() + log.info('x') + assert.equal(lines[0].userId, undefined) + assert.deepEqual(getLogContext(), {}) + }) + + it('uses the context host as counter label', async () => { + capture() + withLogContext({ host: 'ctx-host' }, () => log.warn('x', { code: 'm-ctx' })) + assert.ok((await metricValues('df_logs')).find(x => x.labels.code === 'm-ctx' && x.labels.host === 'ctx-host' && x.value === 1)) + }) + + it('getLogContext returns a copy', () => { + withLogContext({ a: 1 }, () => { + const c = getLogContext() + c.a = 2 + assert.equal(getLogContext().a, 1) + }) + }) +}) + +describe('debug output', () => { + after(() => _resetLogger()) + + it('redirects debug output, including instances created before the logger loaded', () => { + createDebug.enable('lt:*,-lt:no') + const lines = capture() + earlyDebug('hi %s', 'there') + createDebug('lt:late')('late', { k: 1 }) + createDebug('lt:no')('nope') + createDebug('other')('nope') + assert.deepEqual(lines.map(l => [l.ns, l.msg, l.level]), [['lt:early', 'hi there', 'debug'], ['lt:late', 'late { k: 1 }', 'debug']]) + }) +}) diff --git a/packages/node/log.ts b/packages/node/log.ts new file mode 100644 index 0000000..6437929 --- /dev/null +++ b/packages/node/log.ts @@ -0,0 +1,144 @@ +// the logger shared by all the services of the data-fair stack +// JSON lines on stdout in production, pretty output in dev, see README for the conventions + +import { hostname } from 'node:os' +import { format } from 'node:util' +import { AsyncLocalStorage } from 'node:async_hooks' +import createDebug from 'debug' +import { pino, type Logger as PinoLogger, type DestinationStream } from 'pino' +import type { Counter } from 'prom-client' +import { serializeErr } from './log-err.js' + +export type LogLevel = 'debug' | 'info' | 'warn' | 'alert' | 'error' + +export type LogFields = { code?: string, err?: unknown, [key: string]: unknown } + +export interface Logger { + info (msg: string, fields?: LogFields): void + warn (msg: string, fields?: LogFields): void + alert (msg: string, fields?: LogFields): void + error (msg: string, fields?: LogFields): void + init (opts: { service?: string }): void +} + +type LogFormat = 'json' | 'pretty' + +export type LogContext = Record + +// implicit context merged into every log line +// only small immutable values (ids, keys, short names), never req, documents, buffers, etc +// long-lived resources (pools, intervals, caches) must be created outside any scope +// or they would capture it and attribute later lines to the wrong user +const contextStorage = new AsyncLocalStorage() + +/** run fn in a scope where every log line carries the fields of the parent scope plus these */ +export function withLogContext (fields: LogContext, fn: () => T): T { + return contextStorage.run({ ...contextStorage.getStore(), ...fields }, fn) +} + +/** a copy of the current context, for example to pass it to a worker thread in a task payload */ +export function getLogContext (): LogContext { + return { ...contextStorage.getStore() } +} + +// optional peer dependency, absent in production images +let prettyFactory: ((opts: Record) => DestinationStream) | null = null +try { + // @ts-ignore optional peer dependency + prettyFactory = (await import('pino-pretty')).default +} catch { + prettyFactory = null +} + +let service: string | undefined = process.env.OTEL_SERVICE_NAME + +let instance: PinoLogger<'alert'> + +const defaultFormat = (): LogFormat => { + if (process.env.LOG_FORMAT === 'json' || process.env.LOG_FORMAT === 'pretty') return process.env.LOG_FORMAT + return process.env.NODE_ENV === 'production' ? 'json' : 'pretty' +} + +/** @internal test seam, not API */ +export function _resetLogger (opts: { destination?: { write (s: string): unknown }, format?: LogFormat } = {}) { + const format = opts.format ?? defaultFormat() + let destination: DestinationStream + if (format === 'pretty' && prettyFactory) { + destination = prettyFactory({ sync: true, customLevels: 'alert:45', destination: opts.destination ?? 1 }) + } else { + destination = (opts.destination as DestinationStream) ?? pino.destination({ dest: 1, sync: true }) + } + instance = pino({ + level: 'debug', + customLevels: { alert: 45 }, + base: { hostname: hostname() }, + timestamp: pino.stdTimeFunctions.isoTime, + formatters: { level: (label) => ({ level: label }) }, + serializers: { err: serializeErr }, + // per-call fields win over the mixin (pino's default merge strategy) + mixin: () => service ? { service, ...contextStorage.getStore() } : { ...contextStorage.getStore() } + }, destination) +} +_resetLogger() + +// prom-client is an optional peer dependency, without it log lines are simply not counted +let promClient: typeof import('prom-client') | null = null +try { + promClient = await import('prom-client') +} catch { + promClient = null +} + +export const logsCounter: Counter<'level' | 'code' | 'host'> | null = promClient && new promClient.Counter({ + name: 'df_logs', + help: 'A counter of warn, alert and error log lines. The code label comes from the code field of the line, it must be a static string.', + labelNames: ['level', 'code', 'host'] +}) + +export const internalErrorCounter: Counter<'errorCode'> | null = promClient && new promClient.Counter({ + name: 'df_internal_error', + help: 'DEPRECATED, use df_logs. A counter of error log lines.', + labelNames: ['errorCode'] +}) + +export const eventsLogCounter: Counter<'level' | 'code' | 'host'> | null = promClient && new promClient.Counter({ + name: 'df_events_log', + help: 'DEPRECATED, use df_logs. A counter of warn and alert log lines that have a code.', + labelNames: ['level', 'code', 'host'] +}) + +const count = (level: LogLevel, fields?: LogFields) => { + if (level !== 'warn' && level !== 'alert' && level !== 'error') return + const code = typeof fields?.code === 'string' ? fields.code : '' + const host = fields?.host ?? contextStorage.getStore()?.host + const hostLabel = typeof host === 'string' && host ? host : '-' + logsCounter?.inc({ level, code, host: hostLabel }) + if (level === 'error') internalErrorCounter?.inc({ errorCode: code }) + else if (code) eventsLogCounter?.inc({ level, code, host: hostLabel }) +} + +const write = (level: LogLevel, msg: string, fields?: LogFields) => { + try { + count(level, fields) + instance[level](fields ?? {}, msg) + } catch { + // logging must never become a new error + } +} + +// the debug module stays the API for debug logs, only its output is redirected here +// debug reads these properties at each call so instances created earlier are redirected too +createDebug.formatArgs = function () {} +createDebug.log = function (this: { namespace: string }, ...args: unknown[]) { + write('debug', format(...args), { ns: this.namespace }) +} + +const log: Logger = { + info: (msg, fields) => write('info', msg, fields), + warn: (msg, fields) => write('warn', msg, fields), + alert: (msg, fields) => write('alert', msg, fields), + error: (msg, fields) => write('error', msg, fields), + init: (opts) => { if (opts.service) service = opts.service } +} + +export default log diff --git a/packages/node/mongo.ts b/packages/node/mongo.ts index d01bc25..f2f30da 100644 --- a/packages/node/mongo.ts +++ b/packages/node/mongo.ts @@ -1,5 +1,6 @@ import type { IndexSpecification, CreateIndexesOptions, MongoClientOptions, IndexDirection, Db } from 'mongodb' import { MongoClient, MongoError } from 'mongodb' +import log from './log.js' type IndexDirections = Record @@ -21,13 +22,13 @@ export class Mongo { connect = async (mongoUrl: string, options: MongoClientOptions = {}) => { if (this._client) { - console.warn('db already connected') + log.warn('db already connected') return } - console.log('connecting to mongodb...') + log.info('connecting to mongodb...') this._client = await MongoClient.connect(mongoUrl, { maxPoolSize: 5, ignoreUndefined: true, ...options }) this._db = this._client.db() - console.log('...ok') + log.info('connected to mongodb') } // Create an index if it does not exist and manage overwriting existing and conflicting index definitions @@ -38,7 +39,7 @@ export class Mongo { if (options.name && err instanceof MongoError && (err.code === 85 || err.code === 86)) { // if the error is a conflict on keys or params of the index we automatically // delete then recreate the index - console.log(`drop then recreate index ${collection}/${options.name}`) + log.info('drop then recreate index', { collection, index: options.name }) await this.db.collection(collection).dropIndex(options.name) await this.db.collection(collection).createIndex(key, options) } else { diff --git a/packages/node/observer.ts b/packages/node/observer.ts index e7eddad..c3dbd99 100644 --- a/packages/node/observer.ts +++ b/packages/node/observer.ts @@ -9,7 +9,8 @@ import { hostname } from 'node:os' import { createServer } from 'node:http' import { getHeapSnapshot } from 'node:v8' import { pipeline } from 'node:stream/promises' -import { Registry, Counter, register, collectDefaultMetrics } from 'prom-client' +import { Registry, register, collectDefaultMetrics } from 'prom-client' +import log from './log.js' import eventPromise from '@data-fair/lib-utils/event-promise.js' // a special registry for metrics that are global @@ -18,26 +19,12 @@ export const servicePromRegistry = new Registry() collectDefaultMetrics() -// local metrics incremented throughout the code -const internalErrorCounter = new Counter({ - name: 'df_internal_error', - help: 'A counter of errors from any service, worker, etc. Do not use for client errors, only for anomalies that should trigger alerts. Each increment should be accompanied by an error log with matching code.', - labelNames: ['errorCode'] -}) - -export const internalError = (errorCode: string, error: any, ...optionalParams: any) => { - internalErrorCounter.inc({ errorCode }) - const message = error.message || error - console.error(`[${errorCode}] ${message}`, ...optionalParams) - if (error.stack) console.error(error.stack) -} - /** * @param {import('node:http').ServerResponse} res * @param {any} err */ const httpErrorHandler = (res: ServerResponse, err: any) => { - console.error('failed to server prometheus /metrics', err) + log.error('failed to serve prometheus metrics', { code: 'observer-metrics', err }) res.writeHead(500) res.end() } @@ -74,9 +61,9 @@ const serveRetainedHeapSnapshot = async (res: ServerResponse) => { res.setHeader('Content-Disposition', `attachment; filename="data-fair-${hostname()}-${new Date().toISOString()}.heapsnapshot"`) res.setHeader('Content-Type', 'application/octet-stream') const start = Date.now() - console.log('observer: starting full heap snapshot — event loop will be blocked') + log.info('observer: starting full heap snapshot — event loop will be blocked') await pipeline(getHeapSnapshot(), res) - console.log(`observer: full heap snapshot done in ${Date.now() - start}ms`) + log.info('observer: full heap snapshot done', { duration: Date.now() - start }) } // live heap allocation sampler @@ -123,14 +110,7 @@ export const startObserver = async (port = 9090) => { }) server.listen(port) await eventPromise(server, 'listening') - console.log(`Observer server available on http://localhost:${port} - GET /metrics -> get prometheus metrics for this instance - GET /service-metrics -> get prometheus metrics shared accross all instances - GET /cpu-profile -> generate and fetch a CPU profile - GET /heap-profile -> generate and fetch a sampled heap allocation snapshot - GET /heap-profile-all -> generate and fetch a sampled heap allocation snapshot including objects collected by GC - GET /heap-snapshot -> dump a full retained heap snapshot (blocks the event loop while V8 walks the heap) -`) + log.info(`Observer server available on http://localhost:${port}`, { routes: ['/metrics', '/service-metrics', '/cpu-profile', '/heap-profile', '/heap-profile-all', '/heap-snapshot'] }) } export const stopObserver = async () => { diff --git a/packages/node/package.json b/packages/node/package.json index 1145185..6377db5 100644 --- a/packages/node/package.json +++ b/packages/node/package.json @@ -21,16 +21,19 @@ "axios": "^1.7.7", "cacheable-lookup": "^7.0.0", "cookie": "^0.7.2", + "debug": "^4.4.3", "ipaddr.js": "^2.5.0", "jsonwebtoken": "^9.0.2", "jwks-rsa": "^3.1.0", + "pino": "^10.4.0", "semver": "^7.6.3" }, "peerDependencies": { "mongodb": "6", "prom-client": "15", "tough-cookie": "5", - "ws": "8" + "ws": "8", + "pino-pretty": "13" }, "peerDependenciesMeta": { "mongodb": { @@ -44,11 +47,15 @@ }, "tough-cookie": { "optional": true + }, + "pino-pretty": { + "optional": true } }, "type": "module", "devDependencies": { "mongodb": "^6.9.0", + "pino-pretty": "^13.2.0", "prom-client": "^15.1.3", "tough-cookie": "^5.0.0", "ws": "^8.18.0" diff --git a/packages/node/session.ts b/packages/node/session.ts index 4d4a689..41559a7 100644 --- a/packages/node/session.ts +++ b/packages/node/session.ts @@ -6,6 +6,7 @@ import jwt from 'jsonwebtoken' import JwksClient from 'jwks-rsa' import cookie from 'cookie' import { httpError } from '@data-fair/lib-utils/http-errors.js' +import log from './log.js' export type KeySet = 'session' | 'scoped' // simple-directory names the keys of its scoped key set scoped-; the signature still has to @@ -208,7 +209,7 @@ export class SessionHandler { user = verified.payload as User this.assertTokenKind('cookie', verified.header, verified.payload, verified.keySet) } catch (err: any) { - console.warn(err) + log.warn('failure to verify a session token', { code: 'session-token', err }) if (!isTokenFailure(err)) { // happens in case of temporary unavailability of SD // better not to disconnect user in this case diff --git a/packages/node/ssrf.test.ts b/packages/node/ssrf.test.ts index 652821a..9acd844 100644 --- a/packages/node/ssrf.test.ts +++ b/packages/node/ssrf.test.ts @@ -126,8 +126,10 @@ describe('ssrf agents', () => { it('should disable the protection with a warning behind a proxy', async () => { const script = `import ${JSON.stringify(fileURLToPath(new URL('./http-agents.ts', import.meta.url)))}` const env = { ...process.env, HTTPS_PROXY: 'http://proxy.example.com:3128' } - const { stderr } = await execFileAsync(process.execPath, ['--experimental-strip-types', '--input-type=module', '--eval', script], { env, timeout: 10000 }) - assert.match(stderr, /WARNING: HTTPS_PROXY is defined, the protection against server side request forgery \(SSRF\) is disabled/) + const { stdout } = await execFileAsync(process.execPath, ['--experimental-strip-types', '--input-type=module', '--eval', script], { env: { ...env, LOG_FORMAT: 'json' }, timeout: 10000 }) + const line = JSON.parse(stdout.split('\n').find(l => l.includes('HTTPS_PROXY')) as string) + assert.equal(line.level, 'warn') + assert.match(line.msg, /HTTPS_PROXY is defined, the protection against server side request forgery \(SSRF\) is disabled/) }) }) diff --git a/packages/node/test-fixtures/early-debug.ts b/packages/node/test-fixtures/early-debug.ts new file mode 100644 index 0000000..24f8b7c --- /dev/null +++ b/packages/node/test-fixtures/early-debug.ts @@ -0,0 +1,4 @@ +// a debug instance created before the logger module is loaded +import createDebug from 'debug' + +export const earlyDebug = createDebug('lt:early') diff --git a/packages/node/test-fixtures/log-worker.ts b/packages/node/test-fixtures/log-worker.ts new file mode 100644 index 0000000..159547b --- /dev/null +++ b/packages/node/test-fixtures/log-worker.ts @@ -0,0 +1,6 @@ +// worker thread that restores the log context received from its parent and logs inside it +import { parentPort, workerData } from 'node:worker_threads' +import log, { _resetLogger, withLogContext } from '../log.js' + +_resetLogger({ format: 'json', destination: { write: (s: string) => { parentPort?.postMessage(s) } } }) +withLogContext(workerData.logContext, () => log.info('in worker')) diff --git a/packages/node/test-spies.ts b/packages/node/test-spies.ts index 0b23d99..43f2467 100644 --- a/packages/node/test-spies.ts +++ b/packages/node/test-spies.ts @@ -41,7 +41,7 @@ export function waitFor (eventName: string, timeout = 2000) { export function emit (eventName: string, data: any) { debug(`Emitting test spy ${eventName} (${pendingPromises[eventName]?.length} listeners)`) if (!pendingPromises[eventName]?.length) { - console.debug(`No listener for test spy ${eventName}`) + debug(`No listener for test spy ${eventName}`) return } for (const p of pendingPromises[eventName]) { diff --git a/packages/node/upgrade-scripts.ts b/packages/node/upgrade-scripts.ts index ab67947..b11f814 100644 --- a/packages/node/upgrade-scripts.ts +++ b/packages/node/upgrade-scripts.ts @@ -5,6 +5,7 @@ import path from 'path' import { readdirSync, readFileSync, statSync } from 'fs' import Debug from 'debug' import type { Locks } from './locks.js' +import log from './log.js' const debug = Debug('upgrade') @@ -51,7 +52,7 @@ export interface UpgradeScript { export default async function (db: Db, locks: Locks, basePath = './', isFresh?: () => Promise) { const ack = await locks.acquire('upgrade') if (!ack) { - console.warn('upgrade scripts lock is already acquired, skip them') + log.warn('upgrade scripts lock is already acquired, skip them') // IMPORTANT: this behaviour of running the process when the upgrade scripts are still running on another one // implies that they cannot be considered a pre-requisite.. // if we want to consider the upgrade scripts as a pre-requisite we should implement a wait on all