diff --git a/README.md b/README.md index 78455a8..2a7f210 100644 --- a/README.md +++ b/README.md @@ -264,15 +264,15 @@ The format rewrites the triple-beam `LEVEL` symbol from `audit` to `info` (so OT Every format used by `createLogger` is also exported for direct use with your own winston setup. -| Format | Purpose | -| --------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `serializeErrorFormat` | Walks the log info (including nested objects and arrays) and replaces `Error` instances with plain objects that include the normally non-enumerable `message`/`stack`. | -| `omitFormat` | Removes fields by dot-notation path via [es-toolkit's compat `omit`](https://es-toolkit.dev/reference/compat/object/omit.html) (lodash-compatible). | -| `omitNilFormat` | Removes top-level `null` or `undefined` values. | -| `redactFormat` | Recursively replaces values at the given paths with `redactedValue` (default `''`). | -| `jsonStringifyValuesFormat` | Serialises every top-level value to a JSON string, producing a flat `{ key: string }` shape. Accepts an optional `replacer`. | -| `prettyConsoleFormat` | Applies `colorize` and `timestamp`, then renders logs as coloured YAML using [`yamlify-object`](https://www.npmjs.com/package/yamlify-object). | -| `mapAuditLevelForOtel` | Rewrites the triple-beam `LEVEL` symbol from `audit` to `info` and copies the original onto `logLevel` so custom levels survive OTEL's severity enumeration. | +| Format | Purpose | +| --------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `serializeErrorFormat` | Walks the log info (including nested objects and arrays) and replaces `Error` instances with plain objects that include the normally non-enumerable `message`/`stack`. A record that is itself an error, or holds one under `message`, is nested under `error`. | +| `omitFormat` | Removes fields by dot-notation path via [es-toolkit's compat `omit`](https://es-toolkit.dev/reference/compat/object/omit.html) (lodash-compatible). | +| `omitNilFormat` | Removes top-level `null` or `undefined` values. | +| `redactFormat` | Recursively replaces values at the given paths with `redactedValue` (default `''`). | +| `jsonStringifyValuesFormat` | Serialises every top-level value to a JSON string, producing a flat `{ key: string }` shape. Accepts an optional `replacer`. | +| `prettyConsoleFormat` | Applies `colorize` and `timestamp`, then renders logs as coloured YAML using [`yamlify-object`](https://www.npmjs.com/package/yamlify-object). | +| `mapAuditLevelForOtel` | Rewrites the triple-beam `LEVEL` symbol from `audit` to `info` and copies the original onto `logLevel` so custom levels survive OTEL's severity enumeration. | `redactFormat` paths accept plain keys (`email`, matched at every level), dot-notation paths (`user.email`), and `[*]` array wildcards to iterate every element of an array segment — for example `files[*].name`, `users[*].addresses[*].zip`, or `tags[*]` to redact each element of a primitive array. @@ -283,10 +283,7 @@ import { format, createLogger, transports } from 'winston' import { redactFormat, serializeErrorFormat } from '@makerx/node-winston' const logger = createLogger({ - format: format.combine( - serializeErrorFormat(), - redactFormat({ paths: ['user.email', 'files[*].name'] }), - ), + format: format.combine(serializeErrorFormat(), redactFormat({ paths: ['user.email', 'files[*].name'] })), transports: [new transports.Console({ format: format.json() })], }) ``` @@ -295,40 +292,50 @@ const logger = createLogger({ The `Error` class's `message` and `stack` properties [are not enumerable](https://stackoverflow.com/questions/18391212/is-it-not-possible-to-stringify-an-error-using-json-stringify), so `JSON.stringify(new Error('message'))` returns `'{}'`. -Winston lifts `message`, `stack` and `cause` onto the record when an `Error` is the **second** argument to a log call: +Worse, winston treats an `Error` differently depending on where in the call it appears, and none of the four results resemble each other: ```ts -logger.log('message', new Error('cause')) // { message: 'message cause', stack: ... } +logger.error(new Error('cause')) // the record IS the error — { ...info } yields no message, no stack +logger.error(new Error('')) // { message: } — the branch turns on a truthy message +logger.error('failed', new Error('cause')) // { message: 'failed cause', stack: '…' } — messages concatenated +logger.error('failed', { error: new Error('cause') }) // { message: 'failed', error: } — no message, no stack ``` -It does nothing of the kind for the other two shapes. +`createLogger` solves all of it with three complementary mechanisms: -An `Error` passed **alone** becomes the record itself, and since `message`, `stack` and `name` are not own enumerable properties, any transport that spreads or enumerates it receives none of them: +- The logger's own level methods (and `log`) normalise their arguments, so an `Error` reaches winston as `{ error }` metadata rather than as the record or the message. This is what makes the four calls above agree; the rest is winston's ordinary metadata handling. Interpolation is the one exception — see below. +- `serializeErrorFormat` runs at the logger level and walks the log info, replacing any `Error` instance (at any depth, the record itself included) with a plain, JSON-serializable object via the library's `serializeError`. This applies to every transport, and still covers the record shapes directly — for `logger.write`, winston's exception handlers, or the format used on its own outside `createLogger`. +- `serializableErrorReplacer` is passed to the Console transport's final `format.json()` as a safety net — [logform](https://github.com/winstonjs/logform) uses [safe-stable-stringify](https://www.npmjs.com/package/safe-stable-stringify), which accepts a replacer, so any `Error` that slips through is still serialised correctly. ```ts -logger.error(new Error('cause')) // { ...info } was { level: 'error' } — no message, no stack +format.json({ replacer: serializableErrorReplacer }) ``` -An `Error` **nested** in structured log data loses `message` and `stack` for the same reason: +#### One shape, however the error was logged + +Error detail is always at `error`, and `message` is always the line you wrote: ```ts -try { - /* ... */ -} catch (error) { - logger.log('message', { info, error }) // { message: 'message', error: {} } -} +logger.error(new Error('boom')) // { level, message: 'boom', error: { name, message, stack } } +logger.error('failed', new Error('boom')) // { level, message: 'failed', error: { name, message, stack } } +logger.error('failed', { error: new Error('boom') }) // { level, message: 'failed', error: { name, message, stack } } +logger.error(new Error('')) // { level, message: '', error: { name, message, stack } } +logger.error(new AggregateError([inner])) // { level, message: '', error: { name, stack, errors: [ … ] } } ``` -`createLogger` solves both with two complementary mechanisms: +An error given as the whole call keeps its own message on the line, so nothing is lost; anything else you pass alongside it is kept as metadata, and a child logger behaves the same way. -- `serializeErrorFormat` runs at the logger level and walks the log info, replacing any `Error` instance (at any depth, the record itself included) with a plain, JSON-serializable object via the library's `serializeError`. This applies to every transport. When the record is the error, `level` and winston's routing symbols are re-applied to the serialized object so routing still works. -- `serializableErrorReplacer` is passed to the Console transport's final `format.json()` as a safety net — [logform](https://github.com/winstonjs/logform) uses [safe-stable-stringify](https://www.npmjs.com/package/safe-stable-stringify), which accepts a replacer, so any `Error` that slips through is still serialised correctly. +Nesting rather than spreading keeps the error out of the record's namespace, which is where `level`, `defaultMeta` and your own metadata live — they overlap on `name`, `message`, `stack`, `code`, `cause` and `errors`, and something has to give. A logger with `defaultMeta: { name: 'my-service' }` keeps both names: `name` is the service, `error.name` is the error. -```ts -format.json({ replacer: serializableErrorReplacer }) -``` +Normalising the arguments also means the error instance is never written as the record, so winston never assigns `level` or `defaultMeta` onto the error itself. That mattered more than it sounds: V8 formats `stack` lazily on first access, so a `defaultMeta.name` used to rewrite the stack's header to `my-service: boom`. + +Interpolation is left alone. A message holding a `util.format` token means the arguments after it are interpolation values rather than metadata — winston merges nothing onto the record for such a call — so `logger.error('failed: %s', err)` keeps the error in the splat position it was passed in, as does any `Error` past the metadata position. Those are still serialised by `serializeErrorFormat` where they lie, so `format.splat()` finds them there. + +> **Upgrading from 2.1.** `logger.error(err)` used to put `name`, `message` and `stack` at the top of the record; error detail now sits under `error` instead, matching `logger.error('msg', { error })`. Read `error.stack` rather than `stack`, and adjust any `omitPaths`/`redactPaths` that pointed at the old top-level keys. +> +> `logger.error('msg', err)` no longer has the error's message concatenated onto yours, and no longer copies `stack` to the top of the record: `message` is `'msg'`, and the detail is under `error`. -> **Upgrading from 2.0.** A record that is itself an `Error` now reaches transports as a plain object rather than an `Error` instance, so that it carries `name`, `message` and `stack` as ordinary properties. A custom transport that tested `info instanceof Error` should read those properties instead. +> **Upgrading from 2.0.** A record that is itself an `Error` now reaches transports as a plain object rather than an `Error` instance. A custom transport that tested `info instanceof Error` should read the serialised properties instead. To plug in a custom transformation (for example, an `Error`-normalising function previously applied via a custom winston-transport), pass it via `errorSerializer` — it's threaded into both mechanisms: diff --git a/package.json b/package.json index b079428..88b2601 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@makerx/node-winston", - "version": "2.1.0", + "version": "2.2.0", "private": false, "description": "A set of winston formats, console transport and logger creation functions", "author": "MakerX", diff --git a/src/index.spec.ts b/src/index.spec.ts index ea76ed5..549447c 100644 --- a/src/index.spec.ts +++ b/src/index.spec.ts @@ -1,4 +1,4 @@ -import { LEVEL } from 'triple-beam' +import { LEVEL, SPLAT } from 'triple-beam' import { config, format } from 'winston' import TransportStream from 'winston-transport' import { describe, expect, it } from 'vitest' @@ -387,19 +387,68 @@ describe('createLogger error as the whole record', () => { // `logger.error(err)` makes the error the record. `message`, `stack` and `name` are not own // enumerable properties, so a transport that spreads or enumerates it used to receive neither // a message nor a stack. - it('gives a transport the message, name and stack', () => { + it('gives a transport the message and the error detail', () => { const transport = new InMemoryTransport({}) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) logger.error(Object.assign(new TypeError('boom'), { code: 'E_BOOM' }) as unknown as string) - expect(transport.logs[0]).toMatchObject({ - name: 'TypeError', - message: 'boom', - code: 'E_BOOM', - level: 'error', + expect(transport.logs[0]).toMatchObject({ message: 'boom', level: 'error' }) + expect(transport.logs[0].error).toMatchObject({ name: 'TypeError', message: 'boom', code: 'E_BOOM' }) + expect(transport.logs[0].error.stack).toContain('TypeError: boom') + // The error's own properties stay with the error rather than being spread across the record. + expect(transport.logs[0].code).toBeUndefined() + }) + + it('leaves the error instance unmutated, so its name and stack header survive', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ + consoleOptions: { silent: true }, + transports: [transport], + loggerOptions: { defaultMeta: { name: 'my-service' } }, + }) + const error = new TypeError('boom') + + logger.error(error as unknown as string) + + // `defaultMeta` used to be assigned onto the error itself, and V8 formats `stack` lazily, so a + // colliding key rewrote the header to `my-service: boom` and took the error's name with it. + expect(transport.logs[0].name).toBe('my-service') + expect(transport.logs[0].error).toMatchObject({ name: 'TypeError', message: 'boom' }) + expect(transport.logs[0].error.stack).toContain('TypeError: boom') + expect(Object.keys(error)).toEqual([]) + }) + + // Winston decides between making the error the record and wrapping it as `{ message: err }` purely + // on whether the message is truthy, so an empty one used to reach transports as an object under + // `message` — `[object Object]` in the pretty console. + it('gives a transport the same shape when the error has an empty message', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + + logger.error(new Error('') as unknown as string) + logger.error(new AggregateError([new Error('inner')]) as unknown as string) + + expect(transport.logs[0]).toMatchObject({ message: '', error: { name: 'Error', message: '' } }) + expect(transport.logs[0].error.stack).toContain('Error') + expect(transport.logs[1]).toMatchObject({ message: '', error: { name: 'AggregateError' } }) + expect(transport.logs[1].error.errors[0]).toMatchObject({ name: 'Error', message: 'inner' }) + }) + + // `defaultMeta` is assigned onto the record before any format runs, and in this branch the record + // is the error, so a flat shape had the two `name`s fight over one key. + it('keeps defaultMeta and the error detail side by side', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ + consoleOptions: { silent: true }, + transports: [transport], + loggerOptions: { defaultMeta: { name: 'my-service' } }, }) - expect(transport.logs[0].stack).toContain('TypeError: boom') + + logger.error(new Error('') as unknown as string) + + expect(transport.logs[0].name).toBe('my-service') + expect(transport.logs[0].error).toMatchObject({ name: 'Error' }) }) it('still routes at the right level', () => { @@ -426,6 +475,92 @@ describe('createLogger error as the whole record', () => { }) }) +describe('createLogger error argument shapes', () => { + // Winston branches three ways on an `Error` argument and produces three unrelated records. The + // arguments are normalised on the way in so it only ever sees the one shape that needs no repair. + const logged = (log: (logger: ReturnType) => void) => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + log(logger) + return transport.logs + } + + it('puts the error under `error` however it was passed', () => { + const detail = { name: 'TypeError', message: 'boom' } + + expect(logged((l) => l.error(new TypeError('boom') as unknown as string))[0]).toMatchObject({ message: 'boom', error: detail }) + expect(logged((l) => l.error('failed', new TypeError('boom')))[0]).toMatchObject({ message: 'failed', error: detail }) + expect(logged((l) => l.error('failed', { error: new TypeError('boom') }))[0]).toMatchObject({ message: 'failed', error: detail }) + expect(logged((l) => l.error(new TypeError('') as unknown as string))[0]).toMatchObject({ message: '', error: { name: 'TypeError' } }) + }) + + it('keeps metadata passed alongside an error', () => { + const logs = logged((l) => l.error(new TypeError('boom') as unknown as string, { requestId: 'x' })) + + expect(logs[0]).toMatchObject({ message: 'boom', requestId: 'x', error: { name: 'TypeError' } }) + }) + + it('normalises `log(level, message, error)` too', () => { + const logs = logged((l) => l.log('error', 'failed', new TypeError('boom'))) + + expect(logs[0]).toMatchObject({ message: 'failed', error: { name: 'TypeError', message: 'boom' } }) + }) + + it('nests an error given to the object form of `log`, via the format', () => { + const logs = logged((l) => l.log({ level: 'error', message: new TypeError('boom') as unknown as string })) + + expect(logs[0]).toMatchObject({ message: 'boom', error: { name: 'TypeError' } }) + }) + + it('normalises a child logger', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + + logger.child({ requestId: 'x' }).error(new TypeError('boom') as unknown as string) + + expect(transport.logs[0]).toMatchObject({ requestId: 'x', message: 'boom', error: { name: 'TypeError' } }) + }) + + it('leaves the error in the splat position when the message holds a format token', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + + logger.error('failed: %s', new TypeError('boom')) + + // The error was passed as an interpolation value, so it stays one — serialised where it lies + // rather than moved to `error`, which is what `format.splat()` needs to find there. + expect(transport.logs[0].message).toBe('failed: %s') + expect(transport.logs[0].error).toBeUndefined() + const splat = (transport.logs[0] as unknown as Record)[SPLAT] as { name: string; message: string }[] + expect(splat[0]).toMatchObject({ name: 'TypeError', message: 'boom' }) + expect(splat[0]).not.toBeInstanceOf(Error) + }) + + it('nests an error whose own message holds a format token', () => { + const transport = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + + logger.error(new TypeError('bad format: %s') as unknown as string) + + expect(transport.logs[0]).toMatchObject({ + message: 'bad format: %s', + error: { name: 'TypeError', message: 'bad format: %s' }, + }) + }) + + it('leaves a call with no error untouched, splat interpolation included', () => { + const logs = logged((l) => { + l.info('hi %s', 'there') + l.info('plain', { requestId: 'x' }) + }) + + expect(logs[0]).toMatchObject({ message: 'hi %s' }) + expect(logs[0].error).toBeUndefined() + expect(logs[1]).toMatchObject({ message: 'plain', requestId: 'x' }) + expect(logs[1].error).toBeUndefined() + }) +}) + describe('createLogger DOMException', () => { // An operation cancelled through an `AbortSignal` rejects with a `DOMException`, whose `message` and `name` are // getter-only prototype accessors. A deep clone cannot rebuild one, so redaction used to throw a @@ -464,8 +599,12 @@ describe('createLogger DOMException', () => { logger.error('delivery failed', aborted() as unknown as string) - expect(transport.logs[0].message).toBe('delivery failed the operation timed out') - expect(transport.logs[0].stack).toContain('TimeoutError') + // Winston would have concatenated the two messages and copied `stack` up; normalising the + // arguments keeps the caller's message and puts the error where every other call shape has it. + expect(transport.logs[0].message).toBe('delivery failed') + expect(transport.logs[0].stack).toBeUndefined() + expect(transport.logs[0].error).toMatchObject({ name: 'TimeoutError', message: 'the operation timed out' }) + expect(transport.logs[0].error.stack).toContain('TimeoutError') }) it('logs one passed as the whole record', () => { @@ -478,7 +617,10 @@ describe('createLogger DOMException', () => { logger.error(aborted() as unknown as string) - expect(transport.logs[0]).toMatchObject({ name: 'TimeoutError', message: 'the operation timed out' }) + expect(transport.logs[0]).toMatchObject({ + message: 'the operation timed out', + error: { name: 'TimeoutError', message: 'the operation timed out' }, + }) }) it('logs one with every logger-level format enabled', () => { @@ -512,7 +654,8 @@ describe('createLogger DOMException', () => { logger.error(aborted() as unknown as string) expect(transport.logs[0].error).toEqual({ kind: 'TimeoutError', detail: 'the operation timed out' }) - expect(transport.logs[1]).toMatchObject({ kind: 'TimeoutError', detail: 'the operation timed out' }) + // Whichever way it was logged, the error detail is in the same place, in the same shape. + expect(transport.logs[1].error).toEqual(transport.logs[0].error) }) }) diff --git a/src/index.ts b/src/index.ts index 7b2df00..730aee8 100644 --- a/src/index.ts +++ b/src/index.ts @@ -16,6 +16,7 @@ import { redactFormat } from './redact-format' import { createSerializableErrorReplacer, ErrorSerializer, serializeError } from './serialize-error' import { serializeErrorFormat } from './serialize-error-format' import { mapAuditLevelForOtel } from './map-audit-level-for-otel' +import { withNormalizedErrorArgs } from './normalize-error-args' // `winston/lib/winston/transports` is a CJS deep import that can't be consumed from ESM: it's a // directory import, and even with a `/index.js` suffix its named exports are defined via @@ -288,5 +289,7 @@ export function createLogger(options: CreateLoggerOptions): any { transports, } - return winstonCreateLogger(loggerOptions) + // Wrapped rather than returned bare: winston branches three ways on an `Error` argument, and only + // one of the shapes it produces needs no repair. See {@link withNormalizedErrorArgs}. + return withNormalizedErrorArgs(winstonCreateLogger(loggerOptions), Object.keys(loggerOptions.levels ?? defaultLevels)) } diff --git a/src/normalize-error-args.spec.ts b/src/normalize-error-args.spec.ts new file mode 100644 index 0000000..d49a9b6 --- /dev/null +++ b/src/normalize-error-args.spec.ts @@ -0,0 +1,198 @@ +import { describe, expect, it } from 'vitest' +import { normalizeErrorArgs, withNormalizedErrorArgs } from './normalize-error-args' + +describe('normalizeErrorArgs', () => { + it('moves an error in the message position to `error`, keeping its message on the line', () => { + const error = new TypeError('boom') + + expect(normalizeErrorArgs([error], 0)).toEqual(['boom', { error }]) + }) + + it('merges with metadata already in place', () => { + const error = new TypeError('boom') + + expect(normalizeErrorArgs([error, { requestId: 'x' }], 0)).toEqual(['boom', { requestId: 'x', error }]) + }) + + it('moves an error in the metadata position to `error`, keeping the caller message', () => { + const error = new TypeError('boom') + + expect(normalizeErrorArgs(['delivery failed', error], 0)).toEqual(['delivery failed', { error }]) + }) + + it('reads the message from the given position, for `log(level, message, meta)`', () => { + const error = new TypeError('boom') + + expect(normalizeErrorArgs(['error', error], 1)).toEqual(['error', 'boom', { error }]) + expect(normalizeErrorArgs(['error', 'delivery failed', error], 1)).toEqual(['error', 'delivery failed', { error }]) + }) + + it('leaves a call holding no error alone, by reference', () => { + const args = ['hello', { requestId: 'x' }] + + expect(normalizeErrorArgs(args, 0)).toBe(args) + }) + + it('leaves splat interpolation alone', () => { + const args = ['hi %s, you are %d', 'there', 42] + + expect(normalizeErrorArgs(args, 0)).toBe(args) + }) + + it('leaves an error further along the arguments to the format', () => { + // Past the metadata position it is a splat interpolation value, not metadata. + const args = ['hi %j', { a: 1 }, new TypeError('boom')] + + expect(normalizeErrorArgs(args, 0)).toBe(args) + }) + + it('inserts rather than overwrites when the metadata position is not a plain object', () => { + const error = new TypeError('boom') + const second = new RangeError('other') + + expect(normalizeErrorArgs([error, second], 0)).toEqual(['boom', { error }, second]) + expect(normalizeErrorArgs([error, 'a splat value'], 0)).toEqual(['boom', { error }, 'a splat value']) + }) + + it('leaves a call alone when the message holds a format token', () => { + // The error is an interpolation value there, not metadata, and winston merges nothing onto the + // record for such a call. Rewriting it would move the error out of the splat position. + const withToken = ['failed: %s', new TypeError('boom')] + const atIndexOne = ['error', 'failed: %s', new TypeError('boom')] + + expect(normalizeErrorArgs(withToken, 0)).toBe(withToken) + expect(normalizeErrorArgs(atIndexOne, 1)).toBe(atIndexOne) + }) + + it('hands over the wrapper shape when the error carries a token in its own message', () => { + // Rewriting to `[err.message, { error }]` would make winston read the metadata as an + // interpolation value and drop it, so the error goes over as `{ message: err }` for the format + // to nest. Winston cannot resolve that to a record that is the error either. + const error = new TypeError('bad format: %s') + + expect(normalizeErrorArgs([error], 0)).toEqual([{ message: error }]) + expect(normalizeErrorArgs([error, { requestId: 'x' }], 0)).toEqual([{ requestId: 'x', message: error }]) + expect(normalizeErrorArgs(['error', error], 1)).toEqual(['error', { message: error }]) + }) + + it('leaves a tokened error with trailing arguments alone, which winston already wraps', () => { + const args = [new TypeError('bad format: %s'), { a: 1 }, 'x'] + + expect(normalizeErrorArgs(args, 0)).toBe(args) + }) + + it('normalises a non-string message holding an error in the metadata position', () => { + const error = new TypeError('boom') + + expect(normalizeErrorArgs([42, error], 0)).toEqual([42, { error }]) + }) + + it('does not mutate the arguments it was given', () => { + const error = new TypeError('boom') + const meta = { requestId: 'x' } + const args = [error, meta] + + normalizeErrorArgs(args, 0) + + expect(args).toEqual([error, meta]) + expect(meta).toEqual({ requestId: 'x' }) + }) + + it('treats a DOMException as an error', () => { + const error = new DOMException('the operation timed out', 'TimeoutError') + + expect(normalizeErrorArgs([error], 0)).toEqual(['the operation timed out', { error }]) + }) + + it('handles an empty argument list', () => { + const args: unknown[] = [] + + expect(normalizeErrorArgs(args, 0)).toBe(args) + }) +}) + +describe('withNormalizedErrorArgs', () => { + const spy = () => { + const calls: unknown[][] = [] + return { calls, fn: (...args: unknown[]) => calls.push(args) } + } + + it('normalises each level method and forwards `this`', () => { + const error = new TypeError('boom') + const receivers: unknown[] = [] + const calls: unknown[][] = [] + const logger = { + marker: 'the logger', + error(this: unknown, ...args: unknown[]) { + receivers.push((this as { marker?: string } | undefined)?.marker) + calls.push(args) + }, + } + withNormalizedErrorArgs(logger, ['error', 'info']) + + logger.error(error) + + expect(calls).toEqual([['boom', { error }]]) + expect(receivers).toEqual(['the logger']) + }) + + it('normalises the positional form of `log` but not the object form', () => { + const error = new TypeError('boom') + const log$ = spy() + const logger = { log: log$.fn } + withNormalizedErrorArgs(logger, []) + + logger.log('error', error) + logger.log({ level: 'error', message: error }) + + expect(log$.calls[0]).toEqual(['error', 'boom', { error }]) + expect(log$.calls[1]).toEqual([{ level: 'error', message: error }]) + }) + + it('treats `log` as `log` even when it appears in the level list', () => { + const error = new TypeError('boom') + const calls: unknown[][] = [] + const logger = { + log(...args: unknown[]) { + calls.push(args) + }, + } + // Winston warns and skips a level named `log`, so this is `Logger.prototype.log`, not a level. + withNormalizedErrorArgs(logger, ['log', 'error']) + + logger.log('error', error) + + // The message is read at index 1, past the level — not at index 0, which would take the level + // string for the message and leave the record without one. + expect(calls).toEqual([['error', 'boom', { error }]]) + }) + + it('skips a level with no method on the logger', () => { + const logger: Record = {} + + expect(() => withNormalizedErrorArgs(logger, ['error'])).not.toThrow() + expect(logger.error).toBeUndefined() + }) + + it('is inherited by an object created from the wrapped logger, as winston builds a child', () => { + const error = new TypeError('boom') + const receivers: unknown[] = [] + const calls: unknown[][] = [] + const parent = { + from: 'parent', + error(this: unknown, ...args: unknown[]) { + receivers.push((this as { from?: string } | undefined)?.from) + calls.push(args) + }, + } + withNormalizedErrorArgs(parent, ['error']) + + const child = Object.create(parent) as typeof parent + child.from = 'child' + child.error(error) + + // Normalised on the way through, and still writing as the child. + expect(calls).toEqual([['boom', { error }]]) + expect(receivers).toEqual(['child']) + }) +}) diff --git a/src/normalize-error-args.ts b/src/normalize-error-args.ts new file mode 100644 index 0000000..042829a --- /dev/null +++ b/src/normalize-error-args.ts @@ -0,0 +1,124 @@ +const isPlainObject = (value: unknown): value is Record => { + if (typeof value !== 'object' || value === null) return false + const prototype = Object.getPrototypeOf(value) as unknown + return prototype === Object.prototype || prototype === null +} + +// Winston reads the arguments after the message as interpolation values rather than metadata when +// the message holds a `util.format` token, and skips merging metadata onto the record altogether: +// `formatRegExp` in `winston/lib/winston/logger.js`, matched by the one in `logform/splat.js`. +// Declared without `g` so `test` stays stateless. +const FORMAT_TOKEN = /%[scdjifoO%]/ + +/** + * Rewrites a log call's arguments so an `Error` always arrives as `{ error }` metadata. + * + * Winston builds four unrelated records from an `Error` argument, depending on where in the call it + * appears. The first two come from the same expression, `create-logger.js:78`, which resolves one way + * or the other on whether the message is truthy: + * + * | Call | Record | + * | --------------------------------- | ----------------------------------------------------- | + * | `logger.error(err)` | the record *is* the error | + * | `logger.error(new Error(''))` | `{ message: err }` | + * | `logger.error('failed', err)` | `{ message: 'failed ' + err.message, stack }`, error under `SPLAT` | + * | `logger.error('failed', { err })` | `{ message: 'failed', error: err }` | + * + * A format can only see what winston has already built, and by then the first shape has had `level` + * and `defaultMeta` assigned onto the error itself, and the third has had the error's message + * concatenated onto the caller's. Normalising the arguments instead means winston only ever sees the + * last shape, which needs no repair: the error is metadata, and `message` is exactly what the caller + * passed. + * + * `messageIndex` is where the message sits in `args` — 0 for a level method (`logger.error(…)`), 1 + * for `logger.log(level, …)`. Only that position and the metadata position after it are considered; + * an `Error` further along is a splat interpolation value, which `serializeErrorFormat` + * serializes where it lies. + * + * An error taking the message position keeps its own `message` on the record, so the log line still + * reads as it did. That is the error's own message rather than the configured serializer's view of + * it: the serializer describes the error under `error`, while `message` is the line the caller is + * writing. + * + * Arguments are never dropped. Metadata already in place is merged with (`{ ...meta, error }`), and + * anything that is not a plain object — another error, a splat value — has `{ error }` inserted + * before it rather than over it. + * + * A message holding a `util.format` token is left alone: `logger.error('failed: %s', err)` passes + * the error as an interpolation value, not as metadata, and winston merges nothing onto the record + * for such a call. Rewriting it would take the error out of the splat position the caller chose, so + * those keep winston's splat semantics, with the error serialized under `SPLAT` where it lies. + * + * An error in the message position gets the same treatment for a different reason: its own message + * can hold a token by accident, which would have winston read the `{ error }` we just added as an + * interpolation value and drop it from the record. Those are handed over as `{ message: err }` + * instead — the shape `serializeErrorFormat` already nests, and one winston cannot turn back into a + * record that is the error. + */ +export const normalizeErrorArgs = (args: unknown[], messageIndex: number): unknown[] => { + const message = args[messageIndex] + const metaIndex = messageIndex + 1 + const meta = args[metaIndex] + + if (message instanceof Error) { + if (FORMAT_TOKEN.test(message.message)) { + // Only the shapes winston would otherwise resolve to the error itself need rewriting; with a + // trailing argument it already builds `{ message: err }`, which the format nests. + if (args.length > metaIndex + 1 || (meta !== undefined && !isPlainObject(meta))) return args + return [...args.slice(0, messageIndex), { ...meta, message }] + } + const next = [...args] + next[messageIndex] = message.message + if (meta === undefined || isPlainObject(meta)) next[metaIndex] = { ...meta, error: message } + else next.splice(metaIndex, 0, { error: message }) + return next + } + + if (meta instanceof Error) { + if (typeof message === 'string' && FORMAT_TOKEN.test(message)) return args + const next = [...args] + next[metaIndex] = { error: meta } + return next + } + + return args +} + +/** + * Installs {@link normalizeErrorArgs} on a winston logger's level methods and `log`. + * + * The wrappers are assigned as own properties, shadowing the prototype methods they call, so + * everything else on the logger — `add`, `remove`, the stream and event APIs — is untouched. + * + * `child` needs no wrapping: winston builds a child with `Object.create(logger, { write })`, so the + * parent instance is the child's prototype and these own properties are on the chain. `this` is + * forwarded, so a wrapped method called on a child still writes through the child. + */ +export const withNormalizedErrorArgs = (logger: T, levelNames: string[]): T => { + const target = logger as unknown as Record + + for (const level of levelNames) { + // Winston refuses to define a level method named `log` — it would shadow `Logger.prototype.log` + // — and warns instead, so `target.log` is that method rather than a level. The block below + // wraps it with the right message position; skipping it here avoids a second, pointless pass. + if (level === 'log') continue + const original = target[level] + if (typeof original !== 'function') continue + const method = original as (this: unknown, ...args: unknown[]) => unknown + target[level] = function (this: unknown, ...args: unknown[]) { + return method.apply(this, normalizeErrorArgs(args, 0)) + } + } + + const log = target.log + if (typeof log === 'function') { + const method = log as (this: unknown, ...args: unknown[]) => unknown + target.log = function (this: unknown, ...args: unknown[]) { + // `log(info)` passes the record as one object, where `message` holding an error is a shape + // `serializeErrorFormat` already covers. Only the positional forms are rewritten. + return method.apply(this, typeof args[0] === 'string' ? normalizeErrorArgs(args, 1) : args) + } + } + + return logger +} diff --git a/src/serialize-error-format.spec.ts b/src/serialize-error-format.spec.ts index ac544e1..e282556 100644 --- a/src/serialize-error-format.spec.ts +++ b/src/serialize-error-format.spec.ts @@ -123,15 +123,19 @@ describe('serializeErrorFormat', () => { expect(result[SPLAT][1].error).toMatchObject({ message: 'boom' }) expect(result[SPLAT][1].when).toBeInstanceOf(Date) }) - it('replaces a record that is itself an error, keeping level and the routing symbols', () => { + it('nests a record that is itself an error, keeping level and the routing symbols', () => { const error = Object.assign(new TypeError('boom'), { [LEVEL]: 'error', level: 'error' }) const fmt = serializeErrorFormat() const result = fmt.transform(error as unknown as TransformableInfo, fmt.options) as unknown as Record expect(result).not.toBeInstanceOf(Error) - expect(result).toMatchObject({ name: 'TypeError', message: 'boom', level: 'error' }) - expect(result.stack).toBeDefined() + expect(result).toMatchObject({ message: 'boom', level: 'error' }) + const nested = result.error as { name: string; message: string; stack: string; level?: unknown } + expect(nested).toMatchObject({ name: 'TypeError', message: 'boom' }) + expect(nested.stack).toBeDefined() + // Winston's routing, stamped onto the error itself, stays at record level. + expect('level' in nested).toBe(false) expect(result[LEVEL]).toBe('error') }) @@ -141,13 +145,98 @@ describe('serializeErrorFormat', () => { const result = fmt.transform(error as unknown as TransformableInfo, fmt.options) as unknown as Record - expect(result).toMatchObject({ kind: 'TypeError', level: 'error' }) + expect(result).toMatchObject({ error: { kind: 'TypeError' }, level: 'error' }) + // The serializer returned no `message`, and winston's slot still has to hold a string. + expect(result.message).toBe('') expect(result[LEVEL]).toBe('error') }) + it('keeps metadata assigned onto a record that is itself an error at record level', () => { + const error = Object.assign(new TypeError('boom'), { [LEVEL]: 'error', level: 'error', name: 'my-service', requestId: 'x' }) + const fmt = serializeErrorFormat() + + const result = fmt.transform(error as unknown as TransformableInfo, fmt.options) as unknown as Record + + // `defaultMeta` is assigned onto the error before any format runs, so its keys are indistinguishable + // from the error's own enumerable ones. They are carried to record level, where a consumer expects + // them; the serializer still sees them on the error, so they appear inside `error` as well. + expect(result).toMatchObject({ name: 'my-service', requestId: 'x', message: 'boom' }) + expect(result.error).toMatchObject({ name: 'my-service', requestId: 'x' }) + }) + + it('nests an error winston wrapped under `message` because its message was empty', () => { + const input = { [LEVEL]: 'error', level: 'error', message: new Error('') } as unknown as TransformableInfo + const fmt = serializeErrorFormat() + + const result = fmt.transform(input, fmt.options) as unknown as Record + + expect(result.message).toBe('') + const nested = result.error as { name: string; message: string; stack: string } + expect(nested).toMatchObject({ name: 'Error', message: '' }) + expect(nested.stack).toBeDefined() + }) + + it('produces the same shape whichever branch winston took', () => { + const fmt = serializeErrorFormat() + const asRecord = Object.assign(new TypeError('boom'), { [LEVEL]: 'error', level: 'error' }) + const wrapped = { [LEVEL]: 'error', level: 'error', message: new TypeError('boom') } as unknown as TransformableInfo + + const fromRecord = fmt.transform(asRecord as unknown as TransformableInfo, fmt.options) as unknown as Record + const fromWrapper = fmt.transform(wrapped, fmt.options) as unknown as Record + + expect(Object.keys(fromRecord).sort()).toEqual(Object.keys(fromWrapper).sort()) + expect((fromRecord.error as { name: string }).name).toBe((fromWrapper.error as { name: string }).name) + expect(fromRecord.message).toBe(fromWrapper.message) + }) + + it('keeps the level and routing symbols when nesting a wrapped error', () => { + const input = { [LEVEL]: 'error', level: 'error', message: new Error('') } as unknown as TransformableInfo + const fmt = serializeErrorFormat() + + const result = fmt.transform(input, fmt.options) as unknown as Record + + expect(result[LEVEL]).toBe('error') + expect(result.level).toBe('error') + }) + + it('nests a wrapped AggregateError, keeping its serialised errors', () => { + const input = { [LEVEL]: 'error', level: 'error', message: new AggregateError([new Error('inner')]) } as unknown as TransformableInfo + const fmt = serializeErrorFormat() + + const result = fmt.transform(input, fmt.options) as unknown as Record + + const nested = result.error as { name: string; errors: { name: string; message: string; stack: string }[] } + expect(nested.name).toBe('AggregateError') + expect(nested.errors).toHaveLength(1) + expect(nested.errors[0]).toMatchObject({ name: 'Error', message: 'inner' }) + expect(nested.errors[0].stack).toBeDefined() + expect(nested.errors[0]).not.toBeInstanceOf(Error) + }) + + it("leaves the record's own keys alone when nesting a wrapped error", () => { + const input = { [LEVEL]: 'error', level: 'error', message: new Error(''), requestId: 'x' } as unknown as TransformableInfo + const fmt = serializeErrorFormat() + + const result = fmt.transform(input, fmt.options) as unknown as Record + + expect(result.requestId).toBe('x') + expect(result.error).toMatchObject({ name: 'Error' }) + }) + + it('nests a wrapped error with the configured serializer', () => { + const input = { [LEVEL]: 'error', level: 'error', message: new TypeError('') } as unknown as TransformableInfo + const fmt = serializeErrorFormat({ serializer: (e: Error) => ({ kind: e.name }) }) + + const result = fmt.transform(input, fmt.options) as unknown as Record + + expect(result).toMatchObject({ error: { kind: 'TypeError' }, level: 'error' }) + expect(result.message).toBe('') + }) + it('leaves a plain info object that merely looks like a log record alone', () => { const result = run({ message: 'not an error', stack: 'a string' }) expect(result).toMatchObject({ message: 'not an error', stack: 'a string' }) + expect(Object.keys(result)).toEqual(['level', 'message', 'stack']) }) it('rebuilds a cyclic splat branch so no live error is reachable through the cycle', () => { const branch: Record = { error: new Error('boom') } @@ -179,7 +268,7 @@ describe('serializeErrorFormat', () => { const result = fmt.transform(error as unknown as TransformableInfo, fmt.options) as unknown as Record - expect(result).toMatchObject({ kind: 'TypeError', level: 'error' }) + expect(result).toMatchObject({ error: { kind: 'TypeError' }, level: 'error' }) expect(result[LEVEL]).toBe('error') }) it('leaves a cyclic splat argument holding no error completely alone', () => { diff --git a/src/serialize-error-format.ts b/src/serialize-error-format.ts index 126d56b..40ae7e7 100644 --- a/src/serialize-error-format.ts +++ b/src/serialize-error-format.ts @@ -110,30 +110,88 @@ const replaceErrors = (value: unknown, serializer: ErrorSerializer, rebuilt: Map } /** - * Replaces the record itself when it is an `Error`. + * Puts a serialized error under `error`, and its message in winston's `message` slot. * - * `logger.error(err)` takes a winston branch of its own: it assigns `level` and the routing symbols - * onto the error and writes the error as the record. `message`, `stack` and `name` are not own - * enumerable properties of an `Error`, so every transport that spreads or enumerates the record - * loses them — `{ ...info }` yields neither a message nor a stack. Serializing lifts them onto a - * plain object. + * An error's own field names — `name`, `message`, `stack`, `code`, `cause`, `errors` — overlap the + * record's, where `level`, `defaultMeta` and the caller's metadata live. Spreading the error onto + * the record makes the two namespaces collide, and either precedence loses something real: the + * caller winning drops error fields, the error winning drops metadata. A logger carrying + * `defaultMeta: { name: 'my-service' }` demonstrates it — one of the two names has to go. * - * `level` and every own symbol are re-applied afterwards: they are winston's routing, not error - * data, and a custom serializer has no reason to return them. `message` is left to the serializer, - * so one that drops it produces a record without one, exactly as it already does for a nested - * error. + * Nesting removes the overlap rather than arbitrating it, and it makes `logger.error(err)` produce + * the same record as `logger.error('failed', { error: err })`, which is how most callers already log + * an error and what {@link serializeErrorFormat} has always done to a nested one. Error detail has a + * single path in every case: `error.stack`. + * + * `message` is still set, because it is winston's own slot rather than error data: `format.printf` + * and `prettyConsoleFormat` interpolate it, and an object or `undefined` there renders as + * `[object Object]` or `undefined`. It is taken from the serializer so a custom one that rewrites or + * redacts the message is respected, and falls back to `''` for one that drops it entirely. + * + * A record that carries both a wrapped error and its own `error` key is a shape winston never + * produces; if a caller builds one, the wrapped error wins, since it is what the log line is about. + * + * Both callers hand over a copy of the serializer's output rather than the object itself: a + * serializer is free to return a frozen record, or a cached one shared between calls. + */ +const nestError = (record: Record, serialized: Record): Record => { + const message = serialized.message + record.message = typeof message === 'string' ? message : '' + record.error = serialized + return record +} + +/** + * Unpicks the record when it is itself an `Error`. + * + * `logger.error(err)` takes a winston branch of its own: it assigns `level`, the routing symbols and + * any `defaultMeta` onto the error and writes the error as the record. `message`, `stack` and `name` + * are not own enumerable properties of an `Error`, so every transport that spreads or enumerates the + * record loses them — `{ ...info }` yields neither a message nor a stack. + * + * That leaves one object holding both the record and the error. An `Error`'s intrinsic fields are + * non-enumerable, so its own enumerable keys are the record side of the merge — `level`, the + * symbols, `defaultMeta`, and anything the thrower attached — and they are carried across to stay + * where a consumer expects them. The error itself is then nested: see {@link nestError}. */ const serializeRecord = (error: Error, serializer: ErrorSerializer): Record => { - // Copied, never mutated in place: a serializer is free to return a frozen record, or a cached one - // shared between calls, and stamping routing onto either would throw or leak. - const record = { ...serializer(error) } as Record - // Guarded because `serializeErrorFormat` is also usable outside `createLogger`, on a record - // winston has not stamped a level onto. - if ('level' in error) record.level = (error as unknown as { level: unknown }).level + // A fresh object rather than the error: the record has to stop being an `Error` instance, or every + // transport that spreads or enumerates it is back where it started. + const record: Record = {} + for (const key of Object.keys(error)) record[key] = (error as unknown as Record)[key] for (const symbol of Object.getOwnPropertySymbols(error)) { record[symbol] = (error as unknown as Record)[symbol] } - return record + const serialized = { ...serializer(error) } + // Winston stamped `level` onto the error before any format ran, so the serializer saw it as an own + // property. It is routing, not error data, and the loop above already put it at record level. + delete serialized.level + return nestError(record, serialized) +} + +/** + * Unpicks the record when it holds an `Error` under `message`. + * + * This is the other side of the branch {@link serializeRecord} covers. + * `winston/lib/winston/create-logger.js:78` reads `msg && msg.message && msg || { message: msg }`, + * so a truthy message makes the error the record and an empty one nests it: `new Error('')`, or an + * `AggregateError` whose detail is all in `errors`, arrives as `{ message: theError }`. Left alone, + * the walk below would serialize that nested error correctly but leave it under `message`, where + * `prettyConsoleFormat` prints `[object Object]` and a transport querying a string message finds an + * object. + * + * The record is already the record here — only the error moves, to the same place + * {@link serializeRecord} puts it, so one call cannot produce two shapes. Every other key the + * caller set stays untouched: `{ message: err, requestId }` keeps its `requestId`. + * + * The shape can also be passed deliberately rather than built by winston, and there is no way to + * tell the two apart — both are treated as an error under `message`, since a caller who puts one + * there wants it logged as an error either way. + */ +const hoistWrappedError = (record: Record, serializer: ErrorSerializer): Record => { + const wrapped = record.message + if (!(wrapped instanceof Error)) return record + return nestError(record, { ...serializer(wrapped) }) } /** @@ -141,10 +199,14 @@ const serializeRecord = (error: Error, serializer: ErrorSerializer): Record, error: { … } }` — so + * neither depends on which branch winston took: see {@link serializeRecord}, + * {@link hoistWrappedError} and {@link nestError}. Otherwise only the top-level `info` object is + * mutated (to preserve winston's Symbol-keyed routing props); nested objects and arrays are + * rebuilt, so caller-supplied metadata references are never mutated. * * Errors under the `SPLAT` symbol are replaced too. Winston keeps the raw metadata argument there * in addition to merging its properties onto `info`, so an `Error` logged as @@ -169,7 +231,9 @@ export const serializeErrorFormat = format((info, opts) => { seen.delete(value) } } - const record = (info instanceof Error ? serializeRecord(info, serializer) : info) as unknown as Record + const record = (info instanceof Error + ? serializeRecord(info, serializer) + : hoistWrappedError(info as unknown as Record, serializer)) as unknown as Record const seen = new WeakSet([record]) for (const key of Object.keys(record)) record[key] = walk(record[key], seen) const splat = record[SPLAT]