From 2a0c1b68a4b1e389b4c6b80d8f37e049800d17f6 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Tue, 1 Sep 2026 14:23:53 +0800 Subject: [PATCH 1/5] fix: hoist an error winston nested under `message` MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `logger.error(err)` on an error whose `message` is empty loses the error's name, stack and cause in the pretty console, which prints `[object Object]`. Winston's single-argument hot path (`winston/lib/winston/create-logger.js:78`) reads `msg && msg.message && msg || { message: msg }`, so the branch is decided purely by whether the message is truthy: a truthy one makes the error the record — the case fix A in #148 handled — and an empty one nests it as `{ message: err }`. A bare `new Error('')` does it, and so does an `AggregateError` whose detail is all in `errors`. In the nested case the record is not an `Error`, so the root-error branch never fires. The walk serialises the nested error correctly but leaves it under `message`, where `prettyConsoleFormat` interpolates an object, and `format.json` keeps every field but emits `message` as an object where a log query expects a string. `hoistWrappedError` serialises it and spreads the result onto the record before the walk runs, so `message` is a string and `name`/`stack` are siblings whichever branch winston took. Only `message` comes from the serialiser; every other key the caller already set wins, so `{ message: err, requestId }` keeps its `requestId`. Not `serializeRecord`: that lifts `level` and the routing symbols off the error, and here they are on the record already. The same shape can be passed deliberately rather than built by winston, and there is no way to tell the two apart, so both are hoisted — a caller who puts an `Error` in `message` wants it logged as an error either way. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 7 ++-- package.json | 2 +- src/serialize-error-format.spec.ts | 58 ++++++++++++++++++++++++++++++ src/serialize-error-format.ts | 46 ++++++++++++++++++++++-- 4 files changed, 104 insertions(+), 9 deletions(-) diff --git a/README.md b/README.md index 78455a8..f1d7d33 100644 --- a/README.md +++ b/README.md @@ -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() })], }) ``` @@ -321,7 +318,7 @@ try { `createLogger` solves both with two complementary mechanisms: -- `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. +- `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. `logger.error(err)` on an error whose `message` is empty (a bare `new Error('')`, or an `AggregateError` whose detail is all in `errors`) reaches winston's other branch and arrives as `{ message: err }`; that error is hoisted onto the record too, so `message` is always a string and `name`/`stack` are siblings either way. - `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 diff --git a/package.json b/package.json index b079428..1ea90c9 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@makerx/node-winston", - "version": "2.1.0", + "version": "2.1.1", "private": false, "description": "A set of winston formats, console transport and logger creation functions", "author": "MakerX", diff --git a/src/serialize-error-format.spec.ts b/src/serialize-error-format.spec.ts index ac544e1..2bd3413 100644 --- a/src/serialize-error-format.spec.ts +++ b/src/serialize-error-format.spec.ts @@ -145,9 +145,67 @@ describe('serializeErrorFormat', () => { expect(result[LEVEL]).toBe('error') }) + it('hoists an error winston nested under `message` because its message was empty', () => { + const error = new Error('') + const input = { [LEVEL]: 'error', level: 'error', message: error } as unknown as TransformableInfo + const fmt = serializeErrorFormat() + + const result = fmt.transform(input, fmt.options) as unknown as Record + + expect(typeof result.message).toBe('string') + expect(result).toMatchObject({ name: 'Error', message: '', level: 'error' }) + expect(result.stack).toBeDefined() + }) + + it('keeps the level and routing symbols when hoisting a nested 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('hoists an 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 + + expect(result.name).toBe('AggregateError') + const errors = result.errors as { name: string; message: string; stack: string }[] + expect(errors).toHaveLength(1) + expect(errors[0]).toMatchObject({ name: 'Error', message: 'inner' }) + expect(errors[0].stack).toBeDefined() + expect(errors[0]).not.toBeInstanceOf(Error) + }) + + it("leaves the record's own keys alone when hoisting a nested 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.name).toBe('Error') + }) + + it('hoists a nested 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({ kind: 'TypeError', level: 'error' }) + // The serializer returned no `message`, so the record has none rather than the live error. + expect('message' in result).toBe(false) + }) + 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') } diff --git a/src/serialize-error-format.ts b/src/serialize-error-format.ts index 126d56b..d9669de 100644 --- a/src/serialize-error-format.ts +++ b/src/serialize-error-format.ts @@ -136,13 +136,51 @@ const serializeRecord = (error: Error, serializer: ErrorSerializer): Record, serializer: ErrorSerializer): Record => { + const wrapped = record.message + if (!(wrapped instanceof Error)) return record + + const serialized = serializer(wrapped) + // Removed first, so a serializer that returns no `message` leaves the record without one rather + // than keeping the live error — the same outcome it already produces for a nested error. + delete record.message + for (const [key, value] of Object.entries(serialized)) { + if (!(key in record)) record[key] = value + } + return record +} + /** * Walks the log info object, replacing any `Error` instances (including nested ones) * with the plain-object result of the configured serializer so downstream formats and * transports see JSON-serializable errors with `message` and `stack` intact. * - * A record that is itself an `Error` is replaced outright: see {@link serializeRecord}. Otherwise - * only the top-level `info` object is mutated (to preserve winston's Symbol-keyed + * `logger.error(err)` reaches this format as one of two shapes, decided by + * `winston/lib/winston/create-logger.js:78` purely on whether the error's `message` is truthy: the + * record either *is* the error, or nests it as `{ message: err }`. Both are flattened onto the + * record before the walk runs — see {@link serializeRecord} and {@link hoistWrappedError}. + * 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. * @@ -169,7 +207,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] From dcb03ae06bcd0197e2c33eac0c2972656f7227fc Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Tue, 1 Sep 2026 15:07:35 +0800 Subject: [PATCH 2/5] feat: nest serialised error detail under `error` MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `logger.error(err)` put the error's fields at the top of the record. That puts the error in the same namespace as `level`, `defaultMeta` and the caller's own metadata, and the two overlap on `name`, `message`, `stack`, `code`, `cause` and `errors`. Either precedence loses something real. With `defaultMeta: { name: 'my-service' }`: logger.error(new Error('boom')) { name: 'my-service', message: 'boom', stack: 'my-service: boom\n at …' } The error's name is gone, and the stack header reads `my-service: boom` — V8 formats `stack` lazily on first access, and winston assigns `defaultMeta` onto the record before any format runs, which in this branch is the error itself. Nesting removes the overlap instead of arbitrating it. Both winston branches now produce the shape a nested error already had, so error detail is always at `error` and `message` is always a string: logger.error(new Error('boom')) { message: 'boom', error: { name, message, stack } } logger.error(new Error('')) { message: '', error: { name, message, stack } } logger.error('failed', { error: err }) { message: 'failed', error: { name, message, stack } } That last one is unchanged, and is how most callers already log an error, so `error.stack` is now the single path to error detail however it was logged. Two branches, one shape. `serializeRecord` carries the error's own enumerable keys to record level — an `Error`'s intrinsic fields are non-enumerable, so its own enumerable keys are the record side of the merge winston made — and nests the serialised error. `hoistWrappedError` covers the other side of `winston/lib/winston/create-logger.js:78`, where an empty message makes the record `{ message: err }`, and nests it in the same place. `message` is still set from the serialiser, because it is winston's slot rather than error data: `format.printf` and `prettyConsoleFormat` interpolate it, and an object there is the `[object Object]` this started as. A serialiser that drops `message` yields `''`. Minor rather than patch: 2.1.0's top-level `name`/`message`/`stack` shape is one release old, and this is the cheapest moment to correct it. README documents the migration. Known and unchanged: in the whole-record branch, `defaultMeta` keys are indistinguishable from properties the thrower attached, so they are carried to record level *and* seen by the serialiser, and a colliding key still poisons the nested error's `name` and stack header. Not fixable from inside a format. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 41 +++++++--- package.json | 2 +- src/index.spec.ts | 50 +++++++++--- src/serialize-error-format.spec.ts | 81 ++++++++++++++------ src/serialize-error-format.ts | 118 +++++++++++++++++------------ 5 files changed, 199 insertions(+), 93 deletions(-) diff --git a/README.md b/README.md index f1d7d33..a2caf4d 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`. An error logged on its own 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. @@ -318,14 +318,33 @@ try { `createLogger` solves both with two complementary mechanisms: -- `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. `logger.error(err)` on an error whose `message` is empty (a bare `new Error('')`, or an `AggregateError` whose detail is all in `errors`) reaches winston's other branch and arrives as `{ message: err }`; that error is hoisted onto the record too, so `message` is always a string and `name`/`stack` are siblings either 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. - `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 format.json({ replacer: serializableErrorReplacer }) ``` -> **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. +#### One shape, however the error was logged + +Winston decides what to do with `logger.error(err)` on one test — `msg && msg.message && msg || { message: msg }` — so an error with a message becomes the record itself, and one with an empty message (a bare `new Error('')`, or an `AggregateError` whose detail is all in `errors`) is wrapped as `{ message: err }`. Left as they arrive, the same call produces two different records, and the wrapped one renders as `[object Object]`. + +Both are normalised to the shape a nested error already has, so error detail is always at `error` and `message` is always a string: + +```ts +logger.error(new Error('boom')) // { level, message: 'boom', 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: [ … ] } } +logger.error('failed', { error: new Error('boom') }) // { level, message: 'failed', error: { name, message, stack } } +``` + +Nesting rather than spreading also keeps the error out of the record's namespace, which is where `level`, `defaultMeta` and your own metadata live. A logger with `defaultMeta: { name: 'my-service' }` keeps both names: `name` is the service, `error.name` is the error. + +> **Upgrading from 2.1.** `logger.error(err)` used to put `name`, `message` and `stack` at the top of the record; the 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. `message` is unchanged — still the error's message. +> +> Winston's third shape is untouched: `logger.error('msg', err)` is handled by winston core, which concatenates the messages and lifts `stack` onto the record before any format runs. + +> **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 1ea90c9..88b2601 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@makerx/node-winston", - "version": "2.1.1", + "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..952335c 100644 --- a/src/index.spec.ts +++ b/src/index.spec.ts @@ -387,19 +387,47 @@ 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', code: 'E_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') + }) + + // 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', () => { @@ -478,7 +506,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 +543,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/serialize-error-format.spec.ts b/src/serialize-error-format.spec.ts index 2bd3413..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,23 +145,51 @@ 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('hoists an error winston nested under `message` because its message was empty', () => { - const error = new Error('') - const input = { [LEVEL]: 'error', level: 'error', message: error } as unknown as TransformableInfo + 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(typeof result.message).toBe('string') - expect(result).toMatchObject({ name: 'Error', message: '', level: 'error' }) - expect(result.stack).toBeDefined() + 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 hoisting a nested error', () => { + 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() @@ -167,39 +199,38 @@ describe('serializeErrorFormat', () => { expect(result.level).toBe('error') }) - it('hoists an AggregateError, keeping its serialised errors', () => { + 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 - expect(result.name).toBe('AggregateError') - const errors = result.errors as { name: string; message: string; stack: string }[] - expect(errors).toHaveLength(1) - expect(errors[0]).toMatchObject({ name: 'Error', message: 'inner' }) - expect(errors[0].stack).toBeDefined() - expect(errors[0]).not.toBeInstanceOf(Error) + 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 hoisting a nested 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.name).toBe('Error') + expect(result.error).toMatchObject({ name: 'Error' }) }) - it('hoists a nested error with the configured serializer', () => { + 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({ kind: 'TypeError', level: 'error' }) - // The serializer returned no `message`, so the record has none rather than the live error. - expect('message' in result).toBe(false) + 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', () => { @@ -237,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 d9669de..40ae7e7 100644 --- a/src/serialize-error-format.ts +++ b/src/serialize-error-format.ts @@ -110,65 +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) } /** - * Lifts an `Error` out from under `message`. + * Unpicks the record when it holds an `Error` under `message`. * - * `logger.error(err)` on an error whose `message` is falsy takes 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. + * 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. * - * Serializing it and spreading the result onto the record puts `message`, `name` and `stack` where - * the root-error case already puts them. Only `message` is taken from the serializer: every other - * key the caller already set wins, so `{ 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. + * 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`. * - * Not {@link serializeRecord}: that lifts `level` and the routing symbols off the *error*, and here - * they are on the record already. + * 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 - - const serialized = serializer(wrapped) - // Removed first, so a serializer that returns no `message` leaves the record without one rather - // than keeping the live error — the same outcome it already produces for a nested error. - delete record.message - for (const [key, value] of Object.entries(serialized)) { - if (!(key in record)) record[key] = value - } - return record + return nestError(record, { ...serializer(wrapped) }) } /** @@ -178,11 +201,12 @@ const hoistWrappedError = (record: Record, serializer: * * `logger.error(err)` reaches this format as one of two shapes, decided by * `winston/lib/winston/create-logger.js:78` purely on whether the error's `message` is truthy: the - * record either *is* the error, or nests it as `{ message: err }`. Both are flattened onto the - * record before the walk runs — see {@link serializeRecord} and {@link hoistWrappedError}. - * 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. + * record either *is* the error, or nests it as `{ message: err }`. Both are normalised before the + * walk runs to the shape a nested error already has — `{ message: , 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 From ad1a98f1e56869c7689f48658e10dcfb568eb73e Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Tue, 1 Sep 2026 15:34:18 +0800 Subject: [PATCH 3/5] feat: normalise an `Error` argument before winston branches on it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `logger.error(err)` and `logger.error('failed', err)` now produce the same record. Winston decides what to do with an `Error` argument in three separate places and the results have nothing in common: logger.error(err) the record IS the error logger.error(new Error('')) { message: err } — the branch turns on a truthy message logger.error('failed', err) { message: 'failed ' + err.message, stack }, error under SPLAT logger.error('failed', { err }) { message: 'failed', error: err } A format only sees what winston has already built. By then the first shape has had `level` and `defaultMeta` assigned onto the error instance, and the third has had the error's message concatenated onto the caller's — recoverable, if at all, only by guessing. So `createLogger` now rewrites the arguments instead, and winston only ever sees the last shape, which needs no repair. `normalizeErrorArgs` moves an `Error` from the message or metadata position into `{ error }`, keeping the caller's message (or, for an error passed alone, its own) and merging with metadata already there. Nothing is dropped: a non-plain-object in the metadata position has `{ error }` inserted before it. Interpolation is untouched, and an `Error` past the metadata position is a splat value, left to `serializeErrorFormat`. `withNormalizedErrorArgs` installs it on the level methods and `log` as own properties, shadowing the prototype methods they call, so the rest of the winston API is untouched. `child` needs no wrapping: winston builds a child with `Object.create(logger, { write })`, so these own properties are already on its prototype chain, and `this` is forwarded so a wrapped method called on a child still writes through the child. This closes the caveat from the previous commit. The error is never written as the record, so winston never assigns `defaultMeta` onto it, so a colliding `defaultMeta.name` can no longer take the error's name or — V8 formats `stack` lazily on first access — rewrite its stack header to `my-service: boom`. `serializeErrorFormat` keeps handling both record shapes. It is exported for use outside `createLogger`, and `logger.write`, winston's exception handlers and the object form of `log` all reach it without passing through a level method. Behaviour change beyond the record shape: `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. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 71 +++++++-------- src/index.spec.ts | 90 ++++++++++++++++++- src/index.ts | 5 +- src/normalize-error-args.spec.ts | 147 +++++++++++++++++++++++++++++++ src/normalize-error-args.ts | 95 ++++++++++++++++++++ 5 files changed, 364 insertions(+), 44 deletions(-) create mode 100644 src/normalize-error-args.spec.ts create mode 100644 src/normalize-error-args.ts diff --git a/README.md b/README.md index a2caf4d..50c6362 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`. An error logged on its own 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. | +| 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. @@ -292,33 +292,19 @@ 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 three 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 and 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 }) // { message: 'failed', error: } — but with no message or 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: - -```ts -logger.error(new Error('cause')) // { ...info } was { level: 'error' } — no message, no stack -``` - -An `Error` **nested** in structured log data loses `message` and `stack` for the same reason: - -```ts -try { - /* ... */ -} catch (error) { - logger.log('message', { info, error }) // { message: 'message', error: {} } -} -``` - -`createLogger` solves both with two complementary mechanisms: - -- `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. +- The logger's own level methods (and `log`) normalise their arguments, so an `Error` always reaches winston as `{ error }` metadata and never as the record or the message. This is what makes the four calls above agree; the rest is winston's ordinary metadata handling. +- `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 @@ -327,22 +313,27 @@ format.json({ replacer: serializableErrorReplacer }) #### One shape, however the error was logged -Winston decides what to do with `logger.error(err)` on one test — `msg && msg.message && msg || { message: msg }` — so an error with a message becomes the record itself, and one with an empty message (a bare `new Error('')`, or an `AggregateError` whose detail is all in `errors`) is wrapped as `{ message: err }`. Left as they arrive, the same call produces two different records, and the wrapped one renders as `[object Object]`. - -Both are normalised to the shape a nested error already has, so error detail is always at `error` and `message` is always a string: +Error detail is always at `error`, and `message` is always the line you wrote: ```ts -logger.error(new Error('boom')) // { level, message: 'boom', 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: [ … ] } } +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: [ … ] } } ``` -Nesting rather than spreading also keeps the error out of the record's namespace, which is where `level`, `defaultMeta` and your own metadata live. A logger with `defaultMeta: { name: 'my-service' }` keeps both names: `name` is the service, `error.name` is the error. +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. + +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. + +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`. + +Only interpolation is left alone — `logger.info('hi %s', name)` passes straight through, as does any `Error` past the metadata position, which is a splat value rather than metadata. Those are still serialised by `serializeErrorFormat` where they lie. -> **Upgrading from 2.1.** `logger.error(err)` used to put `name`, `message` and `stack` at the top of the record; the 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. `message` is unchanged — still the error's message. +> **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. > -> Winston's third shape is untouched: `logger.error('msg', err)` is handled by winston core, which concatenates the messages and lifts `stack` onto the record before any format runs. +> `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. A custom transport that tested `info instanceof Error` should read the serialised properties instead. diff --git a/src/index.spec.ts b/src/index.spec.ts index 952335c..3467fd5 100644 --- a/src/index.spec.ts +++ b/src/index.spec.ts @@ -393,9 +393,30 @@ describe('createLogger error as the whole record', () => { logger.error(Object.assign(new TypeError('boom'), { code: 'E_BOOM' }) as unknown as string) - expect(transport.logs[0]).toMatchObject({ 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 @@ -454,6 +475,65 @@ 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 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 @@ -492,8 +572,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', () => { 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..05e0822 --- /dev/null +++ b/src/normalize-error-args.spec.ts @@ -0,0 +1,147 @@ +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('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('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..f4f0448 --- /dev/null +++ b/src/normalize-error-args.ts @@ -0,0 +1,95 @@ +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 +} + +/** + * Rewrites a log call's arguments so an `Error` always arrives as `{ error }` metadata. + * + * Winston decides what to do with an `Error` argument in three different places, and the shapes it + * produces have nothing in common: + * + * | Call | Record | + * | --------------------------------- | ----------------------------------------------------- | + * | `logger.error(err)` | the record *is* the error | + * | `logger.error(new Error(''))` | `{ message: err }` — the branch turns on a truthy message | + * | `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 {@link 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. + */ +export const normalizeErrorArgs = (args: unknown[], messageIndex: number): unknown[] => { + const message = args[messageIndex] + const metaIndex = messageIndex + 1 + const meta = args[metaIndex] + + if (message instanceof Error) { + 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) { + 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) { + 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 +} From 13f0659348687542f7e225284054d36d4270eaba Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Tue, 1 Sep 2026 16:12:10 +0800 Subject: [PATCH 4/5] fix: keep an error in the splat position when the message holds a token MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Winston reads the arguments after the message as interpolation values rather than metadata when the message holds a `util.format` token, and merges nothing onto the record for such a call. Normalising `logger.error('failed: %s', err)` to `('failed: %s', { error: err })` therefore produced no top-level `error` at all, and put a wrapper object where `format.splat()` expects the error. Those calls are left alone now, so they keep winston's splat semantics: the error stays in the position the caller passed it, serialized under `SPLAT` where the format finds it. Reported by Copilot on #149. An error in the *message* position gets the same guard for a different reason: its own message can hold a token by accident — `new Error('bad format: %s')` — which would have winston read the `{ error }` just added as an interpolation value and drop it. Those go over as `{ message: err }` instead, the shape `serializeErrorFormat` already nests, and one winston cannot resolve back to a record that is the error. Also from the same review: the README's `logger.error('failed', { error })` example referenced an undeclared binding, so it could not be copied or type-checked. Inlined `new Error('cause')` like the lines around it, and corrected "three results" to four. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 12 ++++++------ src/index.spec.ts | 29 +++++++++++++++++++++++++++- src/normalize-error-args.spec.ts | 33 ++++++++++++++++++++++++++++++++ src/normalize-error-args.ts | 24 +++++++++++++++++++++++ 4 files changed, 91 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 50c6362..f30d1db 100644 --- a/README.md +++ b/README.md @@ -292,13 +292,13 @@ 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 `'{}'`. -Worse, winston treats an `Error` differently depending on where in the call it appears, and none of the three results resemble each other: +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.error(new Error('cause')) // the record IS the error — { ...info } yields no message and 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 }) // { message: 'failed', error: } — but with no message or 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 ``` `createLogger` solves all of it with three complementary mechanisms: @@ -329,7 +329,7 @@ Nesting rather than spreading keeps the error out of the record's namespace, whi 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`. -Only interpolation is left alone — `logger.info('hi %s', name)` passes straight through, as does any `Error` past the metadata position, which is a splat value rather than metadata. Those are still serialised by `serializeErrorFormat` where they lie. +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. > diff --git a/src/index.spec.ts b/src/index.spec.ts index 3467fd5..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' @@ -521,6 +521,33 @@ describe('createLogger error argument shapes', () => { 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') diff --git a/src/normalize-error-args.spec.ts b/src/normalize-error-args.spec.ts index 05e0822..7937f1b 100644 --- a/src/normalize-error-args.spec.ts +++ b/src/normalize-error-args.spec.ts @@ -54,6 +54,39 @@ describe('normalizeErrorArgs', () => { 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' } diff --git a/src/normalize-error-args.ts b/src/normalize-error-args.ts index f4f0448..fed6b18 100644 --- a/src/normalize-error-args.ts +++ b/src/normalize-error-args.ts @@ -4,6 +4,12 @@ const isPlainObject = (value: unknown): value is Record => { 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. * @@ -36,6 +42,17 @@ const isPlainObject = (value: unknown): value is Record => { * 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 {@link 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] @@ -43,6 +60,12 @@ export const normalizeErrorArgs = (args: unknown[], messageIndex: number): unkno 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 } @@ -51,6 +74,7 @@ export const normalizeErrorArgs = (args: unknown[], messageIndex: number): unkno } if (meta instanceof Error) { + if (typeof message === 'string' && FORMAT_TOKEN.test(message)) return args const next = [...args] next[metaIndex] = { error: meta } return next From 86eda7fbf1279719f5f255bea10b3a3a155d54e3 Mon Sep 17 00:00:00 2001 From: Sam Curry Date: Tue, 1 Sep 2026 16:18:08 +0800 Subject: [PATCH 5/5] docs: correct the claims the interpolation carve-out invalidated MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The carve-out in the previous commit left two statements overclaiming. The README said an `Error` "always" reaches winston as `{ error }` metadata and "never" as the record or the message, which a tokened message now contradicts on both counts. And `normalizeErrorArgs`'s own doc introduced a four-row table as "three different places" — the same slip Copilot caught in the README, where the first two rows are in fact one expression resolving two ways. Also: two `{@link serializeErrorFormat}` references in a module that imports nothing, so neither could resolve; plain code spans instead. `log` is skipped in the level loop. Winston declines to define a level named `log`, so `target.log` is `Logger.prototype.log` and the block below already wraps it with the message at index 1; the level loop would wrap it again with the message at index 0. Both passes together happen to be idempotent for every shape that reaches them, so this is a second pointless pass rather than a bug — but reading the same method twice invites one. The accompanying test pins the message position, which is the part that would actually break. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 2 +- src/normalize-error-args.spec.ts | 18 ++++++++++++++++++ src/normalize-error-args.ts | 17 +++++++++++------ 3 files changed, 30 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index f30d1db..2a7f210 100644 --- a/README.md +++ b/README.md @@ -303,7 +303,7 @@ logger.error('failed', { error: new Error('cause') }) // { message: 'failed', `createLogger` solves all of it with three complementary mechanisms: -- The logger's own level methods (and `log`) normalise their arguments, so an `Error` always reaches winston as `{ error }` metadata and never as the record or the message. This is what makes the four calls above agree; the rest is winston's ordinary metadata handling. +- 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. diff --git a/src/normalize-error-args.spec.ts b/src/normalize-error-args.spec.ts index 7937f1b..d49a9b6 100644 --- a/src/normalize-error-args.spec.ts +++ b/src/normalize-error-args.spec.ts @@ -149,6 +149,24 @@ describe('withNormalizedErrorArgs', () => { 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 = {} diff --git a/src/normalize-error-args.ts b/src/normalize-error-args.ts index fed6b18..042829a 100644 --- a/src/normalize-error-args.ts +++ b/src/normalize-error-args.ts @@ -13,13 +13,14 @@ const FORMAT_TOKEN = /%[scdjifoO%]/ /** * Rewrites a log call's arguments so an `Error` always arrives as `{ error }` metadata. * - * Winston decides what to do with an `Error` argument in three different places, and the shapes it - * produces have nothing in common: + * 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 }` — the branch turns on a truthy message | + * | `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 }` | * @@ -31,7 +32,7 @@ const FORMAT_TOKEN = /%[scdjifoO%]/ * * `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 {@link serializeErrorFormat} + * 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 @@ -51,8 +52,8 @@ const FORMAT_TOKEN = /%[scdjifoO%]/ * 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 {@link serializeErrorFormat} already nests, and one winston cannot turn back - * into a record that is the error. + * 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] @@ -97,6 +98,10 @@ export const withNormalizedErrorArgs = (logger: T, levelNames: 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