diff --git a/.github/workflows/pr.yml b/.github/workflows/pr.yml index af07b92..57296f1 100644 --- a/.github/workflows/pr.yml +++ b/.github/workflows/pr.yml @@ -2,7 +2,7 @@ name: Pull Request on: pull_request: - branches: [main] + branches: [main, v2.x] paths-ignore: - '**/*.md' diff --git a/README.md b/README.md index 3e7f526..5f44596 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ # Node Winston -A set of [winston](https://github.com/winstonjs/winston) [formats](https://github.com/winstonjs/winston#formats), a console transport and a logger factory that simplify structured logging in Node.js services — with colourised YAML output for local development and support for OTEL integration. +A set of [winston](https://github.com/winstonjs/winston) [formats](https://github.com/winstonjs/winston#formats), a console transport and a logger factory that simplify structured logging in Node.js services, with colourised YAML output for local development and records shaped for OpenTelemetry. Start with the [quick start](#quick-start). ## Installation @@ -10,37 +10,135 @@ npm install @makerx/node-winston `winston`, `logform`, `winston-transport`, `triple-beam` and `es-toolkit` are peer dependencies so the package shares a single instance with your app's `winston`. npm 7+ and pnpm install them automatically; on Yarn Classic, install them yourself. +`@opentelemetry/winston-transport` `>=0.29` is an optional peer dependency. Install it only when you ship logs through OpenTelemetry: see [step 1 of the quick start](#1-instrument-the-app-optional). + Requires Node.js `>=20`. -### Upgrading from v1 +### Upgrade from an earlier version + +See [Migrating from v2](#migrating-from-v2) and [Migrating from v1](#migrating-from-v1) at the bottom for breaking changes and new functionality. + +## Quick start + +A typical service instruments itself for OpenTelemetry, creates one logger, and sends audit records to a store of their own. Steps 1 and 3 are optional. + +### 1. Instrument the app (optional) + +Install `@opentelemetry/sdk-node`, `@opentelemetry/instrumentation-winston` and `@opentelemetry/winston-transport`, and the other instrumentations you use, such as `@opentelemetry/instrumentation-http` below. The winston instrumentation loads the transport at runtime but does not depend on it, and without it no record is sent. An ES module app also needs `@opentelemetry/instrumentation`, for the hook that `tracing.ts` registers. + +An instrumentation patches a module as that module loads, so tracing must start before anything imports winston. In an ES module app, an entry point with no static imports enforces that order: + +```ts +// main.ts +await import('./tracing.js') +await import('./server.js') +``` + +```ts +// tracing.ts +import { register } from 'node:module' +import { HttpInstrumentation } from '@opentelemetry/instrumentation-http' +import { WinstonInstrumentation } from '@opentelemetry/instrumentation-winston' +import { NodeSDK } from '@opentelemetry/sdk-node' + +const instrumentations = [new HttpInstrumentation(), new WinstonInstrumentation()] + +// For an ES module app: winston is loaded by `import`, which only this hook can patch. +register('@opentelemetry/instrumentation/hook.mjs', import.meta.url) + +export const sdk = new NodeSDK({ instrumentations }) +sdk.start() +``` + +A CommonJS app can `require('./tracing')` first instead, and needs no `register` call. `NodeSDK` reads its exporters from the standard `OTEL_*` environment variables. Call `sdk.shutdown()` last on shutdown, to send what is still queued. -See [Migrating from v1](#migrating-from-v1) at the bottom for breaking changes and new functionality. +### 2. Create the logger + +```ts +// logger.ts +import { isLocalDev } from '@makerx/node-common' +import { createLogger } from '@makerx/node-winston' + +export const logger = createLogger({ + consoleFormat: isLocalDev ? 'pretty' : 'json', + loggerOptions: { + level: process.env.LOG_LEVEL ?? 'info', + defaultMeta: { service: 'my-api' }, + }, + redactPaths: ['headers.authorization', 'token'], + otel: true, +}) +``` + +`otel: true` shapes what the OpenTelemetry transport from step 1 receives. The console keeps nested JSON, or coloured YAML locally. Without step 1, or where the SDK does not run, as in most tests, `otel` changes nothing. To silence the console in tests, pass `consoleOptions: { silent: true }`. Every option is listed under [Options](#options). + +### 3. Send audit records to their own table (optional) + +`logger.audit()` writes at the custom `audit` level (see [Log levels](#log-levels)). To keep audit records in a Log Analytics table of their own as well, send them through a [`CallbackTransport`](#callbacktransport). This example uses the Azure Monitor Logs Ingestion API, with a data collection rule for the custom table: + +```ts +// audit.ts +import { DefaultAzureCredential } from '@azure/identity' +import { LogsIngestionClient } from '@azure/monitor-ingestion' +import { CallbackTransport, type LogError } from '@makerx/node-winston' + +const client = new LogsIngestionClient(process.env.AUDIT_ENDPOINT_URL!, new DefaultAzureCredential()) + +export const createAuditTransport = (logError: LogError) => + new CallbackTransport( + ({ message, meta }) => + client.upload(process.env.AUDIT_RULE_ID!, process.env.AUDIT_STREAM_NAME!, [ + { TimeGenerated: new Date().toISOString(), Message: message, Info: meta }, + ]), + logError, + { onlyLevels: ['audit'], closeTimeoutMs: 5_000 }, + ) +``` + +```ts +// logger.ts +import { createAuditTransport } from './audit.js' + +const auditTransport = createAuditTransport((message, ...args) => logger.error(message, ...args)) + +export const logger = createLogger({ + // ...the options from step 2 + transports: [auditTransport], +}) + +/** Call on shutdown, before `sdk.shutdown()`. Waits up to 5 seconds for audit uploads still running. */ +export const closeAuditTransport = () => auditTransport.close() +``` + +- `onlyLevels: ['audit']` forwards `audit` records only. The `level` option would also forward `error` and `warn`. +- An upload that fails goes to `logError`, which logs it as an error. Errors never reach this transport, so a failing endpoint cannot loop. +- Winston does not wait for a transport to close, so await `close()` yourself. `closeTimeoutMs` bounds the wait, and any uploads still running are reported through `logError`. +- The record's columns, `TimeGenerated`, `Message` and `Info`, must match the stream that the data collection rule declares. ## Creating a Logger `createLogger` builds a winston `Logger` with a pre-configured `Console` transport and a set of logger-level formats that apply to every transport. -Formats are applied in two layers: +Formats are applied in layers: -- **Logger-level** (applied to all transports, in order): `serializeErrorFormat` → `mapAuditLevelForOtel` (if enabled) → `omitFormat` (if `omitPaths`) → `redactFormat` (if `redactPaths`) → `loggerOptions.format` (if supplied) → `otelAttributesFormat` (if `flatten: 'otel'`) or `jsonStringifyValuesFormat` (if `flatten: true`); always last so it captures every prior transformation. +- **Logger-level** (applied to all transports, in order): `serializeErrorFormat` → `omitFormat` (if `omitPaths`) → `redactFormat` (if `redactPaths`) → `loggerOptions.format` (if supplied). - **Console transport** (applied to Console output only): `omitNilFormat` → any `consoleFormats` → either `prettyConsoleFormat` (when `consoleFormat: 'pretty'`) or `timestamp` + `json` (when `consoleFormat: 'json'`). +- **OpenTelemetry transport** (with `otel`): `otelAttributesFormat`, after the logger-level formats. See [OpenTelemetry](#opentelemetry). ### Options -| Option | Type | Description | -| ---------------------- | ------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `consoleFormat` | `'json' \| 'pretty'` | Output format for the Console transport. `json` (default) for deployed environments, `pretty` for colourised YAML during local development. | -| `consoleOptions` | `ConsoleTransportOptions` | Options forwarded to the Console transport (e.g. `silent`, per-transport `level`). The `format` property is managed by this library. | -| `consoleFormats` | `Format[]` | Extra formats appended to the Console transport's format chain, before the final `json`/`pretty` step. Applies to the Console transport only. | -| `transports` | `Transport[]` | Additional winston transports attached alongside the Console transport. | -| `omitPaths` | `string[]` | Dot-notation paths to remove from every log entry. Applied at the logger level, so affects all transports. | -| `redactPaths` | `string[]` | Dot-notation paths whose values are replaced with `redactedValue`. Applied at the logger level, so affects all transports. | -| `redactedValue` | `string` | Replacement value used by `redactPaths`. Defaults to `''`. | -| `flatten` | `boolean \| 'otel'` | Flattens every record as the last logger-level format. `'otel'` produces the attribute shape `@opentelemetry/winston-transport` 0.29 and later needs; `true` serialises every object value to a JSON string, for a transport before 0.29. See [OpenTelemetry](#opentelemetry). | -| `flattenReplacer` | `(key, value) => any` | Optional `JSON.stringify` replacer used by either `flatten` mode for every value it serialises. | -| `errorSerializer` | `ErrorSerializer` | Custom serializer applied to every `Error` instance at the logger level (via `serializeErrorFormat`) and as the Console transport's `format.json` replacer. Defaults to the library's `serializeError`, which captures `name`/`message`/`stack`/`code`/`cause`/`errors` even when non-enumerable, walks own enumerable properties, and is safe against circular references. | -| `mapAuditLevelForOtel` | `boolean` | When `true`, rewrites the triple-beam `LEVEL` from `audit` to `info` and copies the original onto `logLevel` for OTEL compatibility. See [Shipping the audit level via OpenTelemetry](#shipping-the-audit-level-via-opentelemetry). | -| `loggerOptions` | `LoggerOptions` | Winston logger options (e.g. `level`, `defaultMeta`). A `format` supplied here is appended after the library's logger-level formats but still runs before `flatten` when enabled. | +| Option | Type | Description | +| ----------------- | ---------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `consoleFormat` | `'json' \| 'pretty'` | Output format for the Console transport. `json` (default) for deployed environments, `pretty` for colourised YAML during local development. | +| `consoleOptions` | `ConsoleTransportOptions` | Options forwarded to the Console transport (e.g. `silent`, per-transport `level`). The `format` property is managed by this library. | +| `consoleFormats` | `Format[]` | Extra formats appended to the Console transport's format chain, before the final `json`/`pretty` step. Applies to the Console transport only. | +| `transports` | `Transport[]` | Additional winston transports attached alongside the Console transport. | +| `omitPaths` | `string[]` | Dot-notation paths to remove from every log entry. Applied at the logger level, so affects all transports. | +| `redactPaths` | `string[]` | Dot-notation paths whose values are replaced with `redactedValue`. A plain key matches at every depth, inside serialized errors too. Applied at the logger level, so affects all transports. | +| `redactedValue` | `string` | Replacement value used by `redactPaths`. Defaults to `''`. | +| `otel` | `boolean \| OtelAttributesFormatOptions` | Gives each OpenTelemetry transport on the logger, such as the one `@opentelemetry/instrumentation-winston` adds, the `otelAttributesFormat`. Other transports are unchanged. `true` uses the format's defaults, and an object is passed to the format as its options. See [OpenTelemetry](#opentelemetry). | +| `errorSerializer` | `ErrorSerializer` | Custom serializer applied to every `Error` instance at the logger level (via `serializeErrorFormat`) and as the Console transport's `format.json` replacer. Defaults to the library's `serializeError`, which captures `name`/`message`/`stack`/`code`/`cause`/`errors` even when non-enumerable, walks own enumerable properties, and is safe against circular references. Build one with `createErrorSerializer` to leave properties out of every error. | +| `loggerOptions` | `LoggerOptions` | Winston logger options, for example `level` and `defaultMeta`. A `format` supplied here is appended after the library's logger-level formats. | ### Log levels @@ -50,6 +148,8 @@ Formats are applied in two layers: { error: 0, warn: 1, audit: 2, info: 3, debug: 4, verbose: 5 } ``` +`audit` is for audit-trail events: a sign-in, a role change, a data export. It is a log level, not an audit store, and it adds no delivery or retention guarantee. To send audit records somewhere else as well, see [step 3 of the quick start](#3-send-audit-records-to-their-own-table-optional). OpenTelemetry has no `audit` severity, so with `otel` an `audit` record is exported at `info` severity with `logLevel: 'audit'`. See [Audit severity](#audit-severity). + Colours for the default levels (including `audit`) are registered on the first `createLogger` call that uses them, so `colorize` / pretty output works out of the box. Pass your own `levels` via `loggerOptions` to override. When you do, the returned logger is typed against your level keys (so `logger.audit` is only present when the default levels are in use), and you should register colours for your levels via `winston.addColors`: @@ -79,55 +179,6 @@ const logger = createLogger({ logger.http('GET /items') // typed; logger.audit would be a type error ``` -### Example: environment-driven configuration - -At MakerX we typically drive logger configuration from config files, varying output by environment: - -`logger.ts`: - -```ts -import { isLocalDev } from '@makerx/node-common' -import { createLogger } from '@makerx/node-winston' -import config from 'config' - -const logger = createLogger({ - consoleFormat: isLocalDev ? 'pretty' : 'json', - consoleOptions: config.get('logging.consoleOptions'), - loggerOptions: config.get('logging.loggerOptions'), - omitPaths: config.get('logging.omitPaths'), -}) - -export default logger -``` - -Runtime configurations for different environments might look like: - -```ts -// local development — coloured YAML, verbose level, strip redundant defaultMeta -const logger = createLogger({ - consoleFormat: 'pretty', - loggerOptions: { - defaultMeta: { service: 'my-application-name' }, - level: 'verbose', - }, - omitPaths: ['service'], -}) - -// deployed — structured JSON, info level -const logger = createLogger({ - consoleFormat: 'json', - loggerOptions: { - defaultMeta: { service: 'my-application-name' }, - level: 'info', - }, -}) - -// integration tests — silence console output -const logger = createLogger({ - consoleOptions: { silent: true }, -}) -``` - ## Transports `createLogger` creates a `Console` transport by default. Add [other transports](https://github.com/winstonjs/winston/blob/master/docs/transports.md) via the `transports` option — they share the logger-level formats: @@ -147,103 +198,46 @@ const logger = createLogger({ }) ``` -### Custom transport as an integration point - -A custom `winston-transport` is a clean place to fan selected log records out to an external destination — an audit endpoint, a queue, an analytics service. Subclass `Transport`, override `log` to filter and dispatch, and override `close` to drain in-flight work on shutdown so records aren't lost when the process exits. - -The library exports `extractTransformableInfo`, a small helper that strips winston's internal `triple-beam` symbols (`LEVEL`, `SPLAT`) from the `TransformableInfo` and splits out `level`, `message` and the remaining metadata: - -```ts -import Transport from 'winston-transport' -import { type TransformableInfo } from 'logform' -import { extractTransformableInfo } from '@makerx/node-winston' - -export type LogError = (message: string, ...args: any[]) => void - -class AuditTransport extends Transport { - private readonly inFlight = new Set>() - - constructor(private readonly logError: LogError) { - super() - } - - override log(info: TransformableInfo, next: () => void): void { - const { level, message, meta } = extractTransformableInfo(info) - - if (level !== 'audit') { - next() - return - } - - const promise = Promise.resolve() - .then(() => sendToAuditEndpoint({ level, message, ...meta })) - .catch((error) => this.logError('Error in AuditTransport:', { error })) - .finally(() => this.inFlight.delete(promise)) - - this.inFlight.add(promise) - - next() - } - - override async close(): Promise { - await Promise.allSettled([...this.inFlight]) - } -} - -const logger = createLogger({ - transports: [new AuditTransport((message, ...args) => logger.error(message, ...args))], -}) -``` - -A few things worth calling out: - -- Always call `next()` exactly once per record, including when the level filter rejects it — winston-transport is a `Writable` stream, and skipping the callback stalls the pipeline. -- Don't `await` the dispatch inside `log`. Track the promise in a `Set` so `close()` can wait on it later, and let the dispatch run in the background. -- Inject an error sink (`logError`) rather than logging dispatch failures via the same logger this transport is attached to — otherwise a failing endpoint produces an audit record that produces another failing dispatch. -- Override `close()` and `Promise.allSettled` the in-flight set so a failing dispatch doesn't reject the drain. Winston calls `close` from `logger.close()` / `logger.end()`, so transports get a chance to flush before exit. +### `CallbackTransport` -#### `CallbackTransport` +`CallbackTransport` sends records to a promise-returning handler, such as an audit table, a queue or an analytics service. It takes the handler, a `LogError` sink for handler failures, and options: -For the common case where the only thing you'd customise is the dispatch itself, the library exports `CallbackTransport` — a ready-made subclass that wraps the boilerplate above. Construct it with a promise-returning `LogHandler` (receives a `TransformedInfo` — the same `{ level, message, meta }` shape `extractTransformableInfo` returns) and a `LogError` sink for dispatch failures, and pass any standard winston-transport options (e.g. `level`) through the third argument: +| Option | Description | +| ---------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `onlyLevels` | Forwards only records at these levels. | +| `level` | Forwards a level and every level above it. It compares the string `info.level`, so it stays accurate when a logger-level format such as `mapAuditLevelForOtel` rewrites the triple-beam `LEVEL` symbol. | +| `closeTimeoutMs` | The longest `close()` waits for dispatches still running. By default it waits for all of them. | -```ts -import { CallbackTransport, createLogger } from '@makerx/node-winston' +The handler receives `{ level, message, meta }`, the shape `extractTransformableInfo` returns. A handler that rejects is reported to `logError` and never fails the log call. Give it a `logError` whose records this transport does not forward, or a failing endpoint produces a record that fails again. [Step 3 of the quick start](#3-send-audit-records-to-their-own-table-optional) is a complete example. -const logger = createLogger({ - transports: [ - new CallbackTransport( - ({ level, message, meta }) => sendToAuditEndpoint({ level, message, ...meta }), - (message, ...args) => logger.error(message, ...args), - { level: 'audit' }, - ), - ], -}) -``` +## OpenTelemetry -In-flight dispatches are tracked internally and drained via `Promise.allSettled` on `close()`, and any rejection from the handler is routed to the supplied `logError` so a failing endpoint can't recurse back through this transport. +Send logs through OpenTelemetry with [`@opentelemetry/instrumentation-winston`](https://www.npmjs.com/package/@opentelemetry/instrumentation-winston) and `createLogger({ otel: true })`, as in steps [1](#1-instrument-the-app-optional) and [2](#2-create-the-logger) of the quick start. The instrumentation adds an [`@opentelemetry/winston-transport`](https://www.npmjs.com/package/@opentelemetry/winston-transport) transport to every logger and stamps trace and span ids on each record. `otel: true` gives that transport `otelAttributesFormat`, which shapes each record into the attributes the logs SDK and most backends need. The console and every other transport are unchanged. -`CallbackTransport` filters on the string `info.level` rather than the triple-beam `LEVEL` symbol, so the `level` option remains accurate when paired with `mapAuditLevelForOtel` (which rewrites the symbol but leaves the string untouched). For the same reason it sidesteps the `mapAuditLevelForOtel` + `level: 'audit'` guard in `createLogger` — the option is intercepted by the transport rather than passed down to the base `winston-transport` class. +Do not also add an `OpenTelemetryTransportV3` yourself while the instrumentation sends logs: every record would be exported twice. `otel` also shapes a transport passed in `transports`, but a transport added later with `logger.add` gets no format. -## OpenTelemetry +### Supported transport lines -[`@opentelemetry/winston-transport`](https://www.npmjs.com/package/@opentelemetry/winston-transport) forwards each winston record through the OpenTelemetry Logs SDK. Add it yourself, or let [`@opentelemetry/instrumentation-winston`](https://www.npmjs.com/package/@opentelemetry/instrumentation-winston) add it to every logger. Two `createLogger` options shape the records it receives: `flatten`, chosen by transport line below, and `mapAuditLevelForOtel: true` when using the default level set (which includes `audit`). +| `@opentelemetry/winston-transport` | Matching SDK line | What the transport does | +| ---------------------------------- | ----------------- | ------------------------------------------------------------------------------------------ | +| 0.29 – 0.31 | 0.219 – 0.221 | Records an `err`/`error` value as the record's exception; passes every other value through | +| 0.32 – 0.33 | 0.222 – 0.223 | As 0.29, and normalises object values into nested map attributes | +| 0.34 and later | 0.223 and later | As 0.32, and takes `severityMapping` and `logSeverity` options | -### Flattening for OpenTelemetry +A transport before 0.29 is not supported: see [Migrating from v2](#migrating-from-v2). -Most backends — Azure Log Analytics included — index only scalar attributes, so a nested value needs to arrive as a JSON string to be queryable. What else the record needs depends on the transport line: +The transport is tied to an SDK line through its `@opentelemetry/api-logs` dependency, so move the two together. With two copies of `api-logs` in the tree, a transport constructed before the SDK registers its logger provider stays bound to a no-op logger, and every line it writes is dropped. -| `@opentelemetry/winston-transport` | Matching SDK line | What the transport does | Use | -| ---------------------------------- | ----------------- | ------------------------------------------------------------------------------------------ | ----------------------------------------------- | -| before 0.29 | ≤ 0.218 | Passes every value through as it is | `flatten: true`, or `jsonStringifyValuesFormat` | -| 0.29 – 0.31 | 0.219 – 0.221 | Records an `err`/`error` value as the record's exception; passes every other value through | `flatten: 'otel'`, or `otelAttributesFormat` | -| 0.32 and later | 0.222 and later | As 0.29, and normalises object values into nested map attributes | `flatten: 'otel'`, or `otelAttributesFormat` | +### What a record looks like -From 0.29 the transport gives the logs SDK an `err`/`error` value as the exception, and the SDK keeps only `name`, `message`, `stack` and a cause's message: they become `exception.type`, `exception.message`, `exception.stacktrace` and `error.cause.*`, and every other field of the error is dropped. Two things go wrong without help: +From 0.29 the transport gives the logs SDK an `err`/`error` value as the exception. The SDK keeps only `name`, `message`, `stack` and a cause's message: they become `exception.type`, `exception.message`, `exception.stacktrace` and `error.cause.*`, and every other field of the error is dropped. So `otelAttributesFormat`: -- **`flatten: true`** turns the error into a JSON string first, and the SDK records the whole string as `exception.message`, with no `exception.type` or stack trace. -- **No flattening** records the exception, but loses the rest of the error — an HTTP status, a provider's error body, the cause chain — and other object values arrive as nested maps. +- leaves the error an object with only the fields the SDK reads, and moves the rest of it, such as an HTTP status, a provider's error body or the cause chain, to `errorDetail` as JSON +- writes every other object value as a JSON string, because most backends, Azure Log Analytics included, index only scalar attributes +- leaves scalars as they are, and writes a `Date` as its ISO string +- copies every record's level onto `logLevel`, and exports an `audit` record at `info` severity (see [Audit severity](#audit-severity)) -`flatten: 'otel'` keeps the error an object with only the fields the SDK reads, moves the rest of it to `errorDetail` as JSON, and serialises every other object value to a JSON string. Scalars are left alone, and a `Date` becomes its ISO string. A provider error logged as `logger.error('Chat failed', { error, request: { route: '/chat' } })` is exported as: +A provider error logged as `logger.error('Chat failed', { error, request: { route: '/chat' } })` is exported as: ```ts { @@ -254,63 +248,77 @@ From 0.29 the transport gives the logs SDK an `err`/`error` value as the excepti 'error.cause.message': 'body exceeds limit', errorDetail: '{"statusCode":413,"data":{"error":{"code":"request_too_large"}},"cause":{…}}', request: '{"route":"/chat"}', + logLevel: 'error', } ``` The SDK takes a truthy `code` over `name` as `exception.type`, so `code` goes to `errorDetail` unless the error has no `name`. -#### Where to apply it +### Options -`flatten` is a logger-level format, so it changes what every transport receives — the console included. When you construct the OpenTelemetry transport yourself, put the format on that transport instead and the console keeps its nested JSON: +Pass options as `otel: { … }`. -```ts -import { OpenTelemetryTransportV3 } from '@opentelemetry/winston-transport' -import { createLogger, otelAttributesFormat } from '@makerx/node-winston' +| Option | Default | Description | +| -------------------- | ------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `maxAttributeLength` | none | The longest string the format writes. A longer one is cut short and ends in `[Truncated]`. By default every string is written whole. Strings the record already held are never cut. | +| `replacer` | none | `JSON.stringify` replacer for every value the format stringifies, `errorDetail` included. It is called with the object that holds the value as `this`, so it can decide on a property from the other properties of that object. | -const logger = createLogger({ - mapAuditLevelForOtel: true, - transports: [new OpenTelemetryTransportV3({ format: otelAttributesFormat() })], -}) -``` +### Audit severity -`@opentelemetry/instrumentation-winston` constructs its transport without a format, so with it the logger-level option is the only place to apply one: +OpenTelemetry's log spec has no severity for the custom `audit` level. Without one, a backend stores the record with no severity or a default one, and a `logSeverity` filter drops it. So the format exports an `audit` record at `info` severity. A logger whose levels have no `audit` has nothing to rewrite. -```ts -const logger = createLogger({ flatten: 'otel', mapAuditLevelForOtel: true }) -``` +The format also copies every record's level onto `logLevel`. App Insights stores only a coarse severity, which puts `audit` with `info` and `debug` with `verbose`, so `logLevel` is how to tell them apart. In Azure Log Analytics, query `customDimensions.logLevel == "audit"`. + +The format runs on the OpenTelemetry transport only, after that transport's level filter. A logger or transport set to `level: 'audit'` keeps audit records, and the console still shows `"level": "audit"`. + +### Record size and privacy + +Three options control what a record holds, for errors from any library: -Pair either `flatten` mode with `flattenReplacer` to customise the `JSON.stringify` replacer for every value it serialises. +| Option | Effect | Applies to | +| ----------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------ | -------------------- | +| `redactPaths` | Replaces values on every record. A plain key matches at every depth, inside serialized errors too. | Every transport | +| `errorSerializer`, built with `createErrorSerializer` | Leaves properties out of every error with `omit`. With `dedupe`, writes an object two properties share only once. See [Error serialization](#error-serialization). | Every transport | +| `maxAttributeLength` | Cuts any string the format writes at a backend's limit, and ends it in `[Truncated]` so the cut is visible. | OpenTelemetry output | -### Shipping the audit level via OpenTelemetry +The logs SDK's own `attributeValueLengthLimit` cuts a value without a marker, and a cut JSON value does not parse. To change only the OpenTelemetry output, use `otel: { replacer }`. -`@opentelemetry/winston-transport` derives OTEL's `severityText` / `severityNumber` from Winston's triple-beam `LEVEL` symbol and strips the string `level` property before building attributes. OTEL's log spec only defines a fixed severity enumeration (trace/debug/info/warn/error/fatal), so Winston's custom `audit` level arrives with `severityNumber: undefined` and no queryable record of the original level. This is most visible on Azure Monitor / Log Analytics (which ignores records without a mapped severity), but affects any OTEL backend that relies on the spec-defined severity. +#### Example: AI SDK errors in App Insights -Set `mapAuditLevelForOtel: true` to opt in: +The Vercel AI SDK's `APICallError` carries the whole request body as `requestBodyValues`, the prompt included, and the provider's response as `responseHeaders`, `responseBody` and `data`. Its `RetryError` holds every attempt under `errors`, and the last attempt again under `lastError`. A failed retry can overrun the 8,192-character limit of an App Insights custom dimension, which App Insights then cuts short so it no longer parses as JSON. ```ts +import { createErrorSerializer, createLogger } from '@makerx/node-winston' + const logger = createLogger({ - mapAuditLevelForOtel: true, + otel: { maxAttributeLength: 8192 }, + redactPaths: ['requestBodyValues'], + errorSerializer: createErrorSerializer({ + omit: (key, error) => key === 'responseHeaders' || (key === 'lastError' && 'errors' in error), + }), }) ``` -The format rewrites the triple-beam `LEVEL` symbol from `audit` to `info` (so OTEL maps the record onto `info` severity) and copies the original level onto a `logLevel` property (so it survives as an OTEL attribute — e.g. queryable as `customDimensions.logLevel == "audit"` in Azure Log Analytics). The string `info.level` is left as `audit` for other transports — so local Console JSON output still shows `"level": "audit"`. +`dedupe: true` is an alternative to the `lastError` rule: the last attempt is written in full under `errors`, and `lastError` as `'[Duplicate]'`. + +### Exceptions found in metadata -**Caveat:** the `LEVEL` symbol also drives transport-level filtering, so a logger, console, or transport explicitly set to `level: 'audit'` would silently drop these records after the rewrite (`info` is more verbose than `audit`). `createLogger` detects this combination and throws at construction — use `'info'` (or a more verbose level) instead. Only enable this option when shipping logs via OTEL — typically a deployed-environment concern. +With no `err` or `error` on a record, the transport takes the first metadata object that has a `name`, `code`, `message` or `stack` as the record's exception. So `logger.info('created', { name: 'Alice' })` is exported with `exception.type: 'Alice'`, and a backend may file it as an exception. This is the transport's behaviour, not the format's. Log such values under a more specific key, such as `userName`. ## Formats 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`. 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 `''`). | -| `otelAttributesFormat` | Shapes a record into OpenTelemetry log attributes for `@opentelemetry/winston-transport` 0.29 and later: the error stays an object the transport records as the exception, the rest of it goes to `errorDetail`, and every other object value becomes a JSON string. Accepts an optional `replacer`. See [OpenTelemetry](#opentelemetry). | -| `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 `''`). | +| `otelAttributesFormat` | Shapes a record into OpenTelemetry log attributes for `@opentelemetry/winston-transport` 0.29 and later: the error stays an object the transport records as the exception, the rest of it goes to `errorDetail`, and every other object value becomes a JSON string. It also writes `logLevel` and exports `audit` at `info` severity. `otel` puts it on the OpenTelemetry transport. See [OpenTelemetry](#opentelemetry). | +| `jsonStringifyValuesFormat` | Serialises every top-level value to a JSON string, producing a flat `{ key: string }` shape. Accepts an optional `replacer`. For a sink other than the OpenTelemetry transport; from transport 0.29 use `otelAttributesFormat`. | +| `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 the custom `audit` level gets an OpenTelemetry severity. `otelAttributesFormat` already does this; use it in a chain you build yourself. | `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. @@ -391,6 +399,21 @@ const logger = createLogger({ }) ``` +`createErrorSerializer` builds a serializer that works like `serializeError`, with two options: + +| Option | Effect | +| -------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `omit` | Leaves a property out of every error the serializer reaches: the error itself, its `cause`, each entry of its `errors`, and any error held in a property. It is called with the property name and the error that holds it, so a rule can depend on the error's other properties. An error is an `Error` instance, or an object with a string `name`, `message` and `stack`, such as an error already serialized elsewhere. It is not called for any other object. | +| `dedupe` | Writes an object that two properties of one error share only once, and each later occurrence as `'[Duplicate]'`. The first property in key order keeps the object. | + +```ts +import { createErrorSerializer, createLogger } from '@makerx/node-winston' + +const logger = createLogger({ + errorSerializer: createErrorSerializer({ omit: (key) => key === 'headers', dedupe: true }), +}) +``` + #### `DOMException` An `AbortSignal` carries a `DOMException` as its `reason`, and an operation cancelled through one rejects with that reason. A `DOMException` is therefore what a `catch` block receives whenever a fetch, a stream or a job is abandoned on a deadline. It needs no special treatment: log it like any other error. @@ -416,6 +439,35 @@ const serializer = (error: Error) => ({ kind: error.name, detail: error.message format.combine(serializeErrorFormat({ serializer }), format.json({ replacer: createSerializableErrorReplacer(serializer) })) ``` +## Migrating from v2 + +v3 has one OpenTelemetry setup, shown in the [quick start](#quick-start): `WinstonInstrumentation` adds the transport, and `createLogger({ otel: true })` shapes what it receives. It supports `@opentelemetry/winston-transport` 0.29 and later only. 2.x gets fixes only, published under the `latest-2` dist-tag. + +Breaking changes: + +- `flatten`, `flattenReplacer` and `mapAuditLevelForOtel` are removed from `createLogger`. They are type errors, and `createLogger` throws if one is passed, so config-built options cannot silently fall back to nested output. Replace them as follows: + +| 2.x | 3.0 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------ | +| `flatten: 'otel'` or `flatten: true`, with `mapAuditLevelForOtel: true` | `otel: true` | +| `flatten: 'otel'` without `mapAuditLevelForOtel` | `otel: true`. Records also get `logLevel`, and `audit` is exported at `info` severity. | +| `flattenReplacer: r` | `otel: { replacer: r }` | +| An `OpenTelemetryTransportV3` you add yourself, with `otelAttributesFormat()` or `jsonStringifyValuesFormat()`, and `disableLogSending: true` on `WinstonInstrumentation` | Remove the transport and `disableLogSending`, and use `otel: true`. See the [quick start](#quick-start). | +| A transport before 0.29 | Move the transport and the SDK to 0.29 or later. If you cannot move yet, stay on 2.x. | +| A hand-written `errorSerializer` that walks `serializeError`'s output to drop properties | `createErrorSerializer({ omit })`, with the rule as the predicate. See [the AI SDK example](#example-ai-sdk-errors-in-app-insights). | + +- `@opentelemetry/winston-transport` is an optional peer dependency at `>=0.29`. npm 7 and later refuse to install alongside an older transport, and pnpm and Yarn warn. Consumers that do not ship logs through OpenTelemetry are unaffected. +- `otel` shapes the OpenTelemetry transport only. The console and other transports keep nested values and `level: 'audit'`, so a local `flatten: false` is no longer needed. A logger or transport set to `level: 'audit'` is allowed. +- `otelAttributesFormat` always writes `logLevel` and exports `audit` at `info` severity. In 2.x, `flatten: 'otel'` did neither without `mapAuditLevelForOtel`. +- A `Date` under `otel` is its ISO string, unquoted. `flatten: true` wrote it as a quoted JSON string. + +New functionality: + +- `otel` finds the transport `WinstonInstrumentation` adds, so the console stays readable while OpenTelemetry receives flat attributes. +- `otelAttributesFormat` takes a `maxAttributeLength` option, beside its `replacer`. +- `createErrorSerializer` builds an error serializer that can leave properties out of every error, or write a shared object once. +- `CallbackTransport` takes `onlyLevels`, to forward only some levels, and `closeTimeoutMs`, to bound how long `close()` waits. + ## Migrating from v1 Breaking changes: @@ -432,10 +484,10 @@ Breaking changes: New functionality: - New `redactPaths` / `redactedValue` options replace values at dot-notation paths with a placeholder (default `''`). Like `omitPaths` they apply at the logger level and affect every transport, so they're a drop-in replacement for any hand-rolled redaction you previously bolted onto `loggerOptions.format` or a custom transport. Also exported as the standalone `redactFormat`, plus the `redactValues` / `redactValuesWith` helpers for direct use. -- New `flatten` / `flattenReplacer` options serialise every top-level value on the log info to a JSON string, producing a flat `{ key: string }` shape suited to OTEL + Azure Log Analytics and other scalar-only aggregators. Also available as `jsonStringifyValuesFormat` and `jsonStringifyValues`. +- New `flatten` / `flattenReplacer` options serialise every top-level value on the log info to a JSON string, producing a flat `{ key: string }` shape suited to OTEL + Azure Log Analytics and other scalar-only aggregators. Also available as `jsonStringifyValuesFormat` and `jsonStringifyValues`. (The options were replaced by `otel` in v3.) - The new `serializeErrorFormat` is exported for direct use in your own format chains, and accepts a `serializer` override for swapping in custom error normalisation. - `createLogger` is now generic over the level map. When you pass `loggerOptions.levels`, the returned logger's method signatures narrow to your level keys (`logger.fatal(...)` becomes valid, `logger.audit` becomes a type error). - Colours for the default levels (including `audit`) are registered on first use of the default levels, so `colorize` / pretty output works out of the box without a module-load side effect. - `defaultLevels` and `defaultLevelColors` are exported directly if you want to extend or re-use them. - `winstonDefaultLevels` and `winstonDefaultLevelColors` re-export winston's stock `npm` level set (`error`/`warn`/`info`/`http`/`verbose`/`debug`/`silly`) so consumers can opt back into the standard winston levels via `loggerOptions.levels` — colours register automatically on first use. -- New `mapAuditLevelForOtel` option (and standalone format) rewrites the triple-beam `LEVEL` symbol from `audit` to `info` so OTEL maps the record onto a known severity tier, while preserving the original level on a `logLevel` property. See [Shipping the audit level via OpenTelemetry](#shipping-the-audit-level-via-opentelemetry). +- New `mapAuditLevelForOtel` option (and standalone format) rewrites the triple-beam `LEVEL` symbol from `audit` to `info` so OTEL maps the record onto a known severity tier, while preserving the original level on a `logLevel` property. (The option was replaced by `otel` in v3; see [Audit severity](#audit-severity).) diff --git a/eslint.config.mjs b/eslint.config.mjs index 4351651..675d5ea 100644 --- a/eslint.config.mjs +++ b/eslint.config.mjs @@ -34,4 +34,26 @@ export default [ }, }, }, + { + // The OpenTelemetry transport is an optional peer. Importing it, or `@opentelemetry/api-logs`, from + // the library would make it required and can add a second `api-logs` copy to an app. A transport + // that gets its logger from a second copy before the SDK registers its provider writes every line + // to a no-op logger. Specs and the fixture under src/tests import the real packages, which are + // dev dependencies. + files: ['src/**/*.ts'], + ignores: ['src/**/*.spec.ts', 'src/tests/**'], + rules: { + 'no-restricted-imports': [ + 'error', + { + patterns: [ + { + group: ['@opentelemetry/*', 'otel-winston-transport-*'], + message: 'The library must not depend on OpenTelemetry packages. See the comment in eslint.config.mjs.', + }, + ], + }, + ], + }, + }, ] diff --git a/package-lock.json b/package-lock.json index 2fe4e6c..20a3e53 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "@makerx/node-winston", - "version": "2.3.0", + "version": "3.0.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "@makerx/node-winston", - "version": "2.3.0", + "version": "3.0.0", "license": "MIT", "dependencies": { "@colors/colors": "^1.6.0", @@ -23,6 +23,7 @@ "@makerx/ts-toolkit": "^5.0.0-beta.0", "@opentelemetry/api": "^1.9.1", "@opentelemetry/api-logs": "^0.223.0", + "@opentelemetry/instrumentation-winston": "^0.68.1", "@opentelemetry/sdk-logs": "^0.223.0", "@opentelemetry/winston-transport": "^0.34.0", "@rollup/plugin-commonjs": "29.0.2", @@ -40,8 +41,7 @@ "eslint-plugin-node": "^11.1.0", "eslint-plugin-prettier": "^5.5.5", "npm-run-all": "^4.1.5", - "otel-winston-transport-0.27": "npm:@opentelemetry/winston-transport@^0.27.0", - "otel-winston-transport-0.31": "npm:@opentelemetry/winston-transport@^0.31.0", + "otel-winston-transport-0.29": "npm:@opentelemetry/winston-transport@~0.29.0", "rimraf": "^6.1.3", "rollup": "4.60.2", "tslib": "^2.8.1", @@ -53,11 +53,17 @@ "node": ">=20" }, "peerDependencies": { + "@opentelemetry/winston-transport": ">=0.29", "es-toolkit": ">=1", "logform": ">=2", "triple-beam": ">=1", "winston": ">=3", "winston-transport": ">=4" + }, + "peerDependenciesMeta": { + "@opentelemetry/winston-transport": { + "optional": true + } } }, "node_modules/@andrewbranch/untar.js": { @@ -1003,6 +1009,41 @@ "@opentelemetry/api": ">=1.0.0 <1.10.0" } }, + "node_modules/@opentelemetry/instrumentation": { + "version": "0.223.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/instrumentation/-/instrumentation-0.223.0.tgz", + "integrity": "sha512-tttBo88TbwK1zpsH6VeJoxLQopxOjW3cnrP50fsQJRZftkSKDDwjolXXBvow2jy0LKXlNRkDQh0NT6yI/q+BEQ==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/api-logs": "0.223.0", + "import-in-the-middle": "^3.0.0", + "require-in-the-middle": "^8.0.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": "^1.3.0" + } + }, + "node_modules/@opentelemetry/instrumentation-winston": { + "version": "0.68.1", + "resolved": "https://registry.npmjs.org/@opentelemetry/instrumentation-winston/-/instrumentation-winston-0.68.1.tgz", + "integrity": "sha512-J+ko44pKaIqDF0xS5YbwHU0DlcrX6LTC3tjmJZdJNKiYkZ/xe7bI82Plk2VdNk8Ns4NfIPVUrMaYNQ6GySfTnw==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "@opentelemetry/api-logs": "^0.223.0", + "@opentelemetry/instrumentation": "^0.223.0" + }, + "engines": { + "node": "^18.19.0 || >=20.6.0" + }, + "peerDependencies": { + "@opentelemetry/api": "^1.3.0" + } + }, "node_modules/@opentelemetry/resources": { "version": "2.12.0", "resolved": "https://registry.npmjs.org/@opentelemetry/resources/-/resources-2.12.0.tgz", @@ -4433,6 +4474,35 @@ "url": "https://github.com/sponsors/sindresorhus" } }, + "node_modules/import-in-the-middle": { + "version": "3.5.2", + "resolved": "https://registry.npmjs.org/import-in-the-middle/-/import-in-the-middle-3.5.2.tgz", + "integrity": "sha512-WseIA/4o56+GYO3RmlOPvejYi771OFeJEeK/ejROsr9bdjW+E5NXTOD1Di8TL40Qgg3JJX9aa97Hf8iiSVIKZw==", + "dev": true, + "license": "Apache-2.0", + "dependencies": { + "cjs-module-lexer": "^2.2.0", + "es-module-lexer": "^3.0.2", + "module-details-from-path": "^1.0.4" + }, + "engines": { + "node": ">=18" + } + }, + "node_modules/import-in-the-middle/node_modules/cjs-module-lexer": { + "version": "2.3.0", + "resolved": "https://registry.npmjs.org/cjs-module-lexer/-/cjs-module-lexer-2.3.0.tgz", + "integrity": "sha512-lmNyBzi6iYiqyrExTctfmjd8tInx+dHu9PBomTfH5RXS53c27JMFJgzNv5TyAnm3PgGf+MLy0+Ws41/HlVxdKQ==", + "dev": true, + "license": "MIT" + }, + "node_modules/import-in-the-middle/node_modules/es-module-lexer": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/es-module-lexer/-/es-module-lexer-3.0.4.tgz", + "integrity": "sha512-BldNY5mwkVu+cQ5Ymn3e6hB9Sx8XHx4ZevWbiUyZbfKxJxYO27Hf0wfzkxIaD5CAJMaGl3YspKELj0ff/7nCMA==", + "dev": true, + "license": "MIT" + }, "node_modules/imurmurhash": { "version": "0.1.4", "resolved": "https://registry.npmjs.org/imurmurhash/-/imurmurhash-0.1.4.tgz", @@ -5610,6 +5680,13 @@ "node": ">=10" } }, + "node_modules/module-details-from-path": { + "version": "1.0.4", + "resolved": "https://registry.npmjs.org/module-details-from-path/-/module-details-from-path-1.0.4.tgz", + "integrity": "sha512-EGWKgxALGMgzvxYF1UyGTy0HXX/2vHLkw6+NvDKW2jypWbHpjQuj4UMcqQWXHERJhVGKikolT06G3bcKe4fi7w==", + "dev": true, + "license": "MIT" + }, "node_modules/ms": { "version": "2.1.3", "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.3.tgz", @@ -6000,54 +6077,25 @@ "node": ">= 0.8.0" } }, - "node_modules/otel-winston-transport-0.27": { + "node_modules/otel-winston-transport-0.29": { "name": "@opentelemetry/winston-transport", - "version": "0.27.0", - "resolved": "https://registry.npmjs.org/@opentelemetry/winston-transport/-/winston-transport-0.27.0.tgz", - "integrity": "sha512-Imeoqm9CqxSJRo6INwtOn1Kx2XXYZzkyrH6q2teIDJ7ZypKx7DRf23l5ylQZ3vYibkcCLIANbzpeMqCNPp4CEw==", + "version": "0.29.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/winston-transport/-/winston-transport-0.29.0.tgz", + "integrity": "sha512-/VX3xYkWZIFWLasxqPSj/3JFu8Ea8zP22zFsiiSlM8cHQ9ciqmbuX8k2N2CTTezBknteCMeOxt255s59RN3Wkg==", "dev": true, "license": "Apache-2.0", "dependencies": { - "@opentelemetry/api-logs": "^0.217.0", + "@opentelemetry/api-logs": "^0.219.0", "winston-transport": "4.*" }, "engines": { "node": "^18.19.0 || >=20.6.0" } }, - "node_modules/otel-winston-transport-0.27/node_modules/@opentelemetry/api-logs": { - "version": "0.217.0", - "resolved": "https://registry.npmjs.org/@opentelemetry/api-logs/-/api-logs-0.217.0.tgz", - "integrity": "sha512-Cdq0jW2lknrNfrAm92MyEAvpe2cRsKjdnQLHUL6xRA4IVUnsWx6P65E7NcUO0Y+L4w1Aee5iV8FvjSwd+lrs9A==", - "dev": true, - "license": "Apache-2.0", - "dependencies": { - "@opentelemetry/api": "^1.3.0" - }, - "engines": { - "node": ">=8.0.0" - } - }, - "node_modules/otel-winston-transport-0.31": { - "name": "@opentelemetry/winston-transport", - "version": "0.31.0", - "resolved": "https://registry.npmjs.org/@opentelemetry/winston-transport/-/winston-transport-0.31.0.tgz", - "integrity": "sha512-higyMoGHbDTNlCX5ue1dJjDQuYSWwC0L4k6x57RKLG0uXdCIdyIu/OQYnjciL+7Kv2XmPMy4VQloeh36NTJTuQ==", - "dev": true, - "license": "Apache-2.0", - "dependencies": { - "@opentelemetry/api-logs": "^0.221.0", - "@opentelemetry/semantic-conventions": "^1.41.1", - "winston-transport": "4.*" - }, - "engines": { - "node": "^18.19.0 || >=20.6.0" - } - }, - "node_modules/otel-winston-transport-0.31/node_modules/@opentelemetry/api-logs": { - "version": "0.221.0", - "resolved": "https://registry.npmjs.org/@opentelemetry/api-logs/-/api-logs-0.221.0.tgz", - "integrity": "sha512-OlanaW1vv7ufTqQ3/fPLI4arGt5ZoM+P8abOMki6uEYnpRazepSWDwDnnw+la7kE26SHVC18//SMccrDvLKOXQ==", + "node_modules/otel-winston-transport-0.29/node_modules/@opentelemetry/api-logs": { + "version": "0.219.0", + "resolved": "https://registry.npmjs.org/@opentelemetry/api-logs/-/api-logs-0.219.0.tgz", + "integrity": "sha512-FFx7YnaYJlIjqWW/AG/yAZ0L/NEY724PipXXXQLdtZPbLwBGbUMTGL1i/esI56TWfTUXxhLfpgrnWJCG8aUJyg==", "dev": true, "license": "Apache-2.0", "dependencies": { @@ -6488,6 +6536,20 @@ "node": ">=0.10.0" } }, + "node_modules/require-in-the-middle": { + "version": "8.0.1", + "resolved": "https://registry.npmjs.org/require-in-the-middle/-/require-in-the-middle-8.0.1.tgz", + "integrity": "sha512-QT7FVMXfWOYFbeRBF6nu+I6tr2Tf3u0q8RIEjNob/heKY/nh7drD/k7eeMFmSQgnTtCzLDcCu/XEnpW2wk4xCQ==", + "dev": true, + "license": "MIT", + "dependencies": { + "debug": "^4.3.5", + "module-details-from-path": "^1.0.3" + }, + "engines": { + "node": ">=9.3.0 || >=8.10.0 <9.0.0" + } + }, "node_modules/resolve": { "version": "1.22.12", "resolved": "https://registry.npmjs.org/resolve/-/resolve-1.22.12.tgz", diff --git a/package.json b/package.json index 94c5111..62b8a13 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@makerx/node-winston", - "version": "2.3.0", + "version": "3.0.0", "private": false, "description": "A set of winston formats, console transport and logger creation functions", "author": "MakerX", @@ -49,6 +49,7 @@ "@makerx/ts-toolkit": "^5.0.0-beta.0", "@opentelemetry/api": "^1.9.1", "@opentelemetry/api-logs": "^0.223.0", + "@opentelemetry/instrumentation-winston": "^0.68.1", "@opentelemetry/sdk-logs": "^0.223.0", "@opentelemetry/winston-transport": "^0.34.0", "@rollup/plugin-commonjs": "29.0.2", @@ -66,8 +67,7 @@ "eslint-plugin-node": "^11.1.0", "eslint-plugin-prettier": "^5.5.5", "npm-run-all": "^4.1.5", - "otel-winston-transport-0.27": "npm:@opentelemetry/winston-transport@^0.27.0", - "otel-winston-transport-0.31": "npm:@opentelemetry/winston-transport@^0.31.0", + "otel-winston-transport-0.29": "npm:@opentelemetry/winston-transport@~0.29.0", "rimraf": "^6.1.3", "rollup": "4.60.2", "tslib": "^2.8.1", @@ -76,12 +76,18 @@ "vitest": "^4.1.12" }, "peerDependencies": { + "@opentelemetry/winston-transport": ">=0.29", "es-toolkit": ">=1", "logform": ">=2", "triple-beam": ">=1", "winston": ">=3", "winston-transport": ">=4" }, + "peerDependenciesMeta": { + "@opentelemetry/winston-transport": { + "optional": true + } + }, "dependencies": { "@colors/colors": "^1.6.0", "yamlify-object": "^3.0.0", diff --git a/scripts/smoke-cjs.cjs b/scripts/smoke-cjs.cjs index 86f8911..848fa68 100644 --- a/scripts/smoke-cjs.cjs +++ b/scripts/smoke-cjs.cjs @@ -13,12 +13,16 @@ const expectedFns = [ 'createSerializableErrorReplacer', 'serializableErrorReplacer', 'serializeErrorFormat', + 'createErrorSerializer', 'createLogger', + 'otelAttributesFormat', + 'mapAuditLevelForOtel', 'jsonStringifyValuesFormat', 'redactFormat', 'omitFormat', 'omitNilFormat', 'prettyConsoleFormat', + 'CallbackTransport', ] const missing = expectedFns.filter((name) => typeof main[name] !== 'function') if (missing.length > 0) { @@ -26,6 +30,11 @@ if (missing.length > 0) { process.exit(1) } +if (distPkg.peerDependenciesMeta?.['@opentelemetry/winston-transport']?.optional !== true) { + console.error('CJS smoke: dist/package.json does not mark @opentelemetry/winston-transport as an optional peer') + process.exit(1) +} + const err = new Error('boom') err.cause = new Error('cause') const out = main.serializeError(err) @@ -37,4 +46,7 @@ if (!out || out.message !== 'boom' || !out.cause || out.cause.message !== 'cause const logger = main.createLogger({ name: 'smoke', consoleOptions: { silent: true } }) logger.info('cjs smoke ok') +const otelLogger = main.createLogger({ otel: true, consoleOptions: { silent: true } }) +otelLogger.audit('cjs smoke otel ok', { error: err }) + console.log('CJS smoke test passed') diff --git a/src/audit-level.ts b/src/audit-level.ts new file mode 100644 index 0000000..a34384c --- /dev/null +++ b/src/audit-level.ts @@ -0,0 +1,18 @@ +// Internal: deliberately not re-exported from index.ts. +import { type TransformableInfo } from 'logform' +import { LEVEL } from 'triple-beam' + +/** + * Copies the record's level onto `logLevel`, and exports an `audit` record at `info` severity. + * + * The level is read from the triple-beam `LEVEL` symbol, because a format such as + * `format.colorize()` rewrites the string `level`. A `logLevel` the record already has is kept, + * so a second pass leaves `logLevel` at `audit` after the first pass has changed `LEVEL`. + * See `mapAuditLevelForOtel` for why the mapping exists. + */ +export const applyAuditLevelMapping = (info: TransformableInfo): TransformableInfo => { + const level = info[LEVEL] as string | undefined + if (typeof info.logLevel !== 'string') info.logLevel = level + if (level === 'audit') info[LEVEL] = 'info' + return info +} diff --git a/src/callback-transport.spec.ts b/src/callback-transport.spec.ts index 14fa16f..23c8cc0 100644 --- a/src/callback-transport.spec.ts +++ b/src/callback-transport.spec.ts @@ -122,8 +122,8 @@ describe('CallbackTransport', () => { ), ) - // Simulate `mapAuditLevelForOtel`: LEVEL symbol rewritten from 'audit' to 'info', string - // `level` left untouched. winston-transport's stock filter would drop this; ours must not. + // As `mapAuditLevelForOtel` leaves a record: LEVEL rewritten from 'audit' to 'info', the string + // `level` untouched. winston-transport's stock filter would drop this record, and ours must not. const audit = { [LEVEL]: 'info', level: 'audit', message: 'audit-event' } as TransformableInfo transport.log!(audit, () => {}) @@ -139,13 +139,13 @@ describe('CallbackTransport', () => { () => {}, { level: 'audit' }, ) - // We intercept `level` in our constructor so `createLogger`'s mapAuditLevelForOtel guard - // (which reads `transport.level`) does not trip when the transport is configured for audit. + // The constructor keeps `level` for itself, so the base class's filter, which reads the LEVEL + // symbol, never runs. expect(transport.level).toBeUndefined() }) - it('routes audit records through createLogger with mapAuditLevelForOtel and level: audit', async () => { - const { createLogger } = await import('./index') + it('routes audit records at level audit after a logger-level mapAuditLevelForOtel', async () => { + const { createLogger, mapAuditLevelForOtel } = await import('./index') const received: TransformedInfo[] = [] const transport = new CallbackTransport( async (info) => { @@ -155,11 +155,11 @@ describe('CallbackTransport', () => { { level: 'audit' }, ) - // Without the level interception this combination would either throw at construction - // (createLogger guard) or silently drop the record (LEVEL rewrite + symbol-based filter). + // The mapping rewrites LEVEL before any transport filters, so a filter on LEVEL would drop the + // audit record. const logger = createLogger({ consoleOptions: { silent: true }, - mapAuditLevelForOtel: true, + loggerOptions: { format: mapAuditLevelForOtel() }, transports: [transport], }) @@ -171,4 +171,62 @@ describe('CallbackTransport', () => { expect(received.map((info) => info.message)).toEqual(['audit-event']) }) + + it('forwards only the levels in onlyLevels', async () => { + const received: TransformedInfo[] = [] + const transport = attachLevels( + new CallbackTransport( + async (info) => { + received.push(info) + }, + () => {}, + { onlyLevels: ['audit'] }, + ), + ) + + for (const level of ['error', 'warn', 'audit', 'info']) transport.log!(buildInfo(level, `${level}-event`), () => {}) + await transport.close!() + + expect(received.map((info) => info.message)).toEqual(['audit-event']) + }) + + it('forwards only audit records through createLogger with onlyLevels, so an error it logs is not sent back to it', async () => { + const { createLogger } = await import('./index') + const received: TransformedInfo[] = [] + const transport = new CallbackTransport( + async (info) => { + received.push(info) + }, + (message, ...args) => logger.error(message, ...args), + { onlyLevels: ['audit'] }, + ) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + + logger.error('error-event') + logger.audit('audit-event', { actor: 'a-1' }) + logger.info('info-event') + await transport.close!() + + expect(received).toEqual([{ level: 'audit', message: 'audit-event', meta: { actor: 'a-1' } }]) + }) + + it('stops waiting at closeTimeoutMs and reports the dispatches still running', async () => { + const logError = vi.fn() + const transport = new CallbackTransport(() => new Promise(() => {}), logError, { closeTimeoutMs: 20 }) + + transport.log!(buildInfo('info', 'never-finishes'), () => {}) + await transport.close!() + + expect(logError).toHaveBeenCalledWith('CallbackTransport closed after 20 ms with 1 dispatch(es) still running') + }) + + it('reports nothing when dispatches finish within closeTimeoutMs', async () => { + const logError = vi.fn() + const transport = new CallbackTransport(() => Promise.resolve(), logError, { closeTimeoutMs: 1_000 }) + + transport.log!(buildInfo('info', 'quick'), () => {}) + await transport.close!() + + expect(logError).not.toHaveBeenCalled() + }) }) diff --git a/src/callback-transport.ts b/src/callback-transport.ts index b841791..9bec700 100644 --- a/src/callback-transport.ts +++ b/src/callback-transport.ts @@ -16,45 +16,65 @@ export type LogError = (message: string, ...args: any[]) => void */ export type LogHandler = (info: TransformedInfo) => Promise +export interface CallbackTransportOptions extends Transport.TransportStreamOptions { + /** + * Forwards only records at these levels. `level` forwards a level and every level above it, so + * `level: 'audit'` also forwards `error` and `warn`. `onlyLevels: ['audit']` forwards `audit` + * records alone. + */ + onlyLevels?: readonly string[] + + /** + * The longest `close()` waits for dispatches that are still running, in milliseconds. When it + * stops waiting, it reports how many are still running through `logError`. By default `close()` + * waits for every dispatch to finish. + */ + closeTimeoutMs?: number +} + /** * Custom winston transport that forwards each log record to a promise-returning callback, with * built-in tracking of in-flight dispatches so `close()` can drain them on shutdown. Construct * with the dispatch handler, an error sink for dispatch failures, and (optionally) the standard - * winston-transport options. + * winston-transport options and {@link CallbackTransportOptions}. * - * Unlike the stock winston-transport `level` filter — which compares the triple-beam `LEVEL` - * symbol — this transport filters on the string `info.level` instead. That makes the `level` - * option safe to combine with `mapAuditLevelForOtel`, which rewrites the `LEVEL` symbol but - * leaves `info.level` alone. The option is intercepted in the constructor (not forwarded to - * the base class), so `createLogger`'s `mapAuditLevelForOtel` + `level: 'audit'` guard does not - * trip on it. + * The stock winston-transport `level` filter compares the triple-beam `LEVEL` symbol. This transport + * filters on the string `info.level` instead, so its `level` option stays accurate when a + * logger-level format such as `mapAuditLevelForOtel` rewrites the `LEVEL` symbol. The constructor + * keeps the option and does not pass it to the base class, so the base filter never runs. + * + * Winston does not wait for a transport's `close()`. Await it yourself on shutdown, so that + * dispatches still running can finish before the process exits. * * @example * ```ts - * const logger = createLogger({ - * mapAuditLevelForOtel: true, - * transports: [ - * new CallbackTransport( - * ({ level, message, meta }) => sendToAuditEndpoint({ level, message, ...meta }), - * (message, ...args) => logger.error(message, ...args), - * { level: 'audit' }, - * ), - * ], - * }) + * const auditTransport = new CallbackTransport( + * ({ message, meta }) => sendToAuditEndpoint({ message, ...meta }), + * (message, ...args) => logger.error(message, ...args), + * { onlyLevels: ['audit'], closeTimeoutMs: 5_000 }, + * ) + * const logger = createLogger({ transports: [auditTransport] }) + * + * // on shutdown + * await auditTransport.close() * ``` */ export class CallbackTransport extends Transport { private readonly inFlight = new Set>() private readonly minLevel: string | undefined + private readonly onlyLevels: ReadonlySet | undefined + private readonly closeTimeoutMs: number | undefined constructor( private readonly handler: LogHandler, private readonly logError: LogError, - options?: Transport.TransportStreamOptions, + options?: CallbackTransportOptions, ) { - const { level, ...rest } = options ?? {} + const { level, onlyLevels, closeTimeoutMs, ...rest } = options ?? {} super(rest) this.minLevel = level + this.onlyLevels = onlyLevels ? new Set(onlyLevels) : undefined + this.closeTimeoutMs = closeTimeoutMs } override log(info: TransformableInfo, next: () => void): void { @@ -63,7 +83,8 @@ export class CallbackTransport extends Transport { // `levels` is set on the transport by winston when it's piped from a logger; the stock // `winston-transport` type definitions don't declare it, so we read it via cast. const levels = (this as unknown as { levels?: Record }).levels - if (this.minLevel !== undefined && levels && levels[this.minLevel] < levels[transformed.level]) { + const belowMinLevel = this.minLevel !== undefined && levels && levels[this.minLevel] < levels[transformed.level] + if (belowMinLevel || (this.onlyLevels && !this.onlyLevels.has(transformed.level))) { next() return } @@ -79,6 +100,22 @@ export class CallbackTransport extends Transport { } override async close(): Promise { - await Promise.allSettled([...this.inFlight]) + const settled = Promise.allSettled([...this.inFlight]) + if (this.closeTimeoutMs === undefined) { + await settled + return + } + + let timer: NodeJS.Timeout | undefined + const timedOut = await Promise.race([ + settled.then(() => false), + new Promise((resolve) => { + timer = setTimeout(() => resolve(true), this.closeTimeoutMs) + }), + ]) + clearTimeout(timer) + if (timedOut) { + this.logError(`CallbackTransport closed after ${this.closeTimeoutMs} ms with ${this.inFlight.size} dispatch(es) still running`) + } } } diff --git a/src/index.spec.ts b/src/index.spec.ts index 417381e..289cdce 100644 --- a/src/index.spec.ts +++ b/src/index.spec.ts @@ -2,7 +2,14 @@ import { LEVEL, SPLAT } from 'triple-beam' import { config, format } from 'winston' import TransportStream from 'winston-transport' import { describe, expect, it } from 'vitest' -import { createLogger, defaultLevelColors, defaultLevels, winstonDefaultLevelColors, winstonDefaultLevels } from './index' +import { + createErrorSerializer, + createLogger, + defaultLevelColors, + defaultLevels, + winstonDefaultLevelColors, + winstonDefaultLevels, +} from './index' describe('logger', () => { it('verbose logs are screened out when level is debug', () => { @@ -161,13 +168,13 @@ describe('createLogger Date metadata', () => { expect(JSON.stringify(parameters)).toBe('["2026-01-02T03:04:05.000Z",1]') }) - it('flatten writes a Date in metadata as its ISO string', () => { - const transport = new InMemoryTransport({}) - const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], flatten: true }) + it('otel writes a Date in metadata as its ISO string, unquoted', () => { + const transport = new OpenTelemetryTransportV3({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], otel: true }) logger.info('db query', { parameters: [when, 1], at: when }) const info = transport.logs[0] as Record expect(info.parameters).toBe('["2026-01-02T03:04:05.000Z",1]') - expect(info.at).toBe('"2026-01-02T03:04:05.000Z"') + expect(info.at).toBe('2026-01-02T03:04:05.000Z') }) it('a Date survives redaction beside a redacted key', () => { @@ -304,123 +311,156 @@ describe('createLogger child loggers', () => { }) }) -describe('createLogger flatten', () => { - it('stringifies object and array values and leaves scalars alone', () => { - const transport = new InMemoryTransport({}) +describe('createLogger otel', () => { + it('gives the format to an OpenTelemetry transport and leaves other transports nested', () => { + const otelTransport = new OpenTelemetryTransportV3({}) + const sibling = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [otelTransport, sibling], otel: true }) + logger.error('failed', { error: Object.assign(new Error('boom'), { statusCode: 500 }), obj: { a: 1 }, count: 3 }) + expect(otelTransport.logs[0]).toMatchObject({ obj: '{"a":1}', count: 3, error: { name: 'Error', message: 'boom' } }) + expect(JSON.parse(otelTransport.logs[0].errorDetail as string)).toEqual({ statusCode: 500 }) + expect(sibling.logs[0]).toMatchObject({ obj: { a: 1 }, error: { message: 'boom', statusCode: 500 } }) + expect(sibling.logs[0]).not.toHaveProperty('errorDetail') + }) + + it('leaves an OpenTelemetry transport that has its own format alone', () => { + const own = format((info) => Object.assign(info, { shapedBy: 'own' })) + const otelTransport = new OpenTelemetryTransportV3({ format: own() }) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [otelTransport], otel: true }) + logger.info('hello', { obj: { a: 1 } }) + expect(otelTransport.logs[0]).toMatchObject({ shapedBy: 'own', obj: { a: 1 } }) + }) + + it('passes its options to the format, replacer included', () => { + const transport = new OpenTelemetryTransportV3({}) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], - flatten: true, + otel: { replacer: (key, value: unknown) => (key === 'secret' ? '' : value) }, }) - logger.info('hello', { obj: { a: 1 }, arr: [1, 2], count: 3, flag: true, text: 'literal' }) - const info = transport.logs[0] as Record - expect(info.obj).toBe('{"a":1}') - expect(info.arr).toBe('[1,2]') - expect(info.count).toBe(3) - expect(info.flag).toBe(true) - expect(info.text).toBe('literal') + logger.info('hello', { data: { secret: 'abc', other: 'def' } }) + const { data } = transport.logs[0] as { data: string } + expect(JSON.parse(data)).toEqual({ secret: '', other: 'def' }) }) - it('forwards flattenReplacer to JSON.stringify for each value', () => { - const transport = new InMemoryTransport({}) + it('shapes the record after the logger-level formats, redaction and loggerOptions.format included', () => { + const transport = new OpenTelemetryTransportV3({}) + const inject = format((info) => Object.assign(info, { injected: { a: 1 } })) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], - flatten: true, - flattenReplacer: (key, value) => (key === 'secret' ? '' : value), + otel: true, + redactPaths: ['body'], + loggerOptions: { format: inject() }, }) - logger.info('hello', { data: { secret: 'abc', other: 'def' } }) - const { data } = transport.logs[0] as { data: string } - const parsed = JSON.parse(data) as { secret: string; other: string } - expect(parsed.secret).toBe('') - expect(parsed.other).toBe('def') + logger.error('failed', { error: Object.assign(new Error('boom'), { body: { prompt: 'secret' }, statusCode: 500 }) }) + expect(JSON.parse(transport.logs[0].errorDetail as string)).toEqual({ body: '', statusCode: 500 }) + expect(transport.logs[0].injected).toBe('{"a":1}') }) - it('runs after loggerOptions.format so injected object values are stringified', () => { - const transport = new InMemoryTransport({}) - const injectFormat = format((info) => { - info.injected = { a: 1 } - return info - }) + it('leaves out error properties with an errorSerializer from createErrorSerializer', () => { + const transport = new OpenTelemetryTransportV3({}) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], - flatten: true, - loggerOptions: { format: injectFormat() }, + otel: true, + errorSerializer: createErrorSerializer({ omit: (key) => key === 'headers' }), }) - logger.info('hello') - expect((transport.logs[0] as { injected: unknown }).injected).toBe('{"a":1}') + logger.error('failed', { error: Object.assign(new Error('boom'), { headers: { a: '1' }, statusCode: 500 }) }) + expect(JSON.parse(transport.logs[0].errorDetail as string)).toEqual({ statusCode: 500 }) + }) + + it('leaves the OpenTelemetry transport nested without it', () => { + const transport = new OpenTelemetryTransportV3({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + logger.info('hello', { obj: { a: 1 } }) + expect(transport.logs[0].obj).toEqual({ a: 1 }) }) }) -describe('createLogger mapAuditLevelForOtel', () => { - it('rewrites the LEVEL symbol from audit to info, preserves the original on logLevel, and leaves the string level alone', () => { - const transport = new InMemoryTransport({}) +describe('createLogger otel audit level', () => { + it('exports audit at info on the OpenTelemetry transport only, with logLevel audit', () => { + const otelTransport = new OpenTelemetryTransportV3({}) + const sibling = new InMemoryTransport({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [otelTransport, sibling], otel: true }) + logger.audit('audit-event', { actor: 'user-1' }) + expect(otelTransport.logs[0]).toMatchObject({ level: 'audit', logLevel: 'audit', actor: 'user-1' }) + expect((otelTransport.logs[0] as Record)[LEVEL]).toBe('info') + expect((sibling.logs[0] as Record)[LEVEL]).toBe('audit') + expect(sibling.logs[0]).not.toHaveProperty('logLevel') + }) + + it('records logLevel on every other level and leaves its LEVEL alone', () => { + const transport = new OpenTelemetryTransportV3({}) + const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], otel: true }) + logger.warn('heads-up') + expect(transport.logs[0].logLevel).toBe('warn') + expect((transport.logs[0] as Record)[LEVEL]).toBe('warn') + }) + + it('records logLevel and rewrites nothing for a logger whose own levels have no audit', () => { + const transport = new OpenTelemetryTransportV3({}) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], - mapAuditLevelForOtel: true, + otel: true, + loggerOptions: { levels: { error: 0, info: 1, trace: 2 }, level: 'trace' }, }) - logger.audit('audit-event', { actor: 'user-1' }) - const info = transport.logs[0] as Record - expect(info[LEVEL]).toBe('info') - expect(info.level).toBe('audit') - expect(info.logLevel).toBe('audit') - expect(info.actor).toBe('user-1') + logger.trace('trace-event') + expect((transport.logs[0] as Record)[LEVEL]).toBe('trace') + expect(transport.logs[0].logLevel).toBe('trace') }) - it('leaves non-audit levels untouched but still records logLevel', () => { - const transport = new InMemoryTransport({}) + it('maps audit after a loggerOptions.format that colorizes the string level', () => { + const transport = new OpenTelemetryTransportV3({}) const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport], - mapAuditLevelForOtel: true, + otel: true, + loggerOptions: { format: format.colorize() }, }) - logger.warn('heads-up') - const info = transport.logs[0] as Record - expect(info.level).toBe('warn') - expect(info[LEVEL]).toBe('warn') - expect(info.logLevel).toBe('warn') + logger.audit('audit-event') + expect((transport.logs[0] as Record)[LEVEL]).toBe('info') + expect(transport.logs[0].logLevel).toBe('audit') }) - it('is opt-in — when disabled, audit records keep their level and no logLevel is added', () => { - const transport = new InMemoryTransport({}) - const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport] }) + it('keeps audit records when the logger, the console or the OpenTelemetry transport is set to level audit', () => { + const otelTransport = new OpenTelemetryTransportV3({ level: 'audit' }) + const other = new InMemoryTransport({ level: 'audit' }) + const logger = createLogger({ + consoleOptions: { silent: true, level: 'audit' }, + transports: [otelTransport, other], + otel: true, + loggerOptions: { level: 'audit' }, + }) logger.audit('audit-event') - const info = transport.logs[0] as Record - expect(info.level).toBe('audit') - expect(info[LEVEL]).toBe('audit') - expect(info.logLevel).toBeUndefined() + logger.info('info-event') + expect(otelTransport.logs.map((info) => info.message)).toEqual(['audit-event']) + expect(otelTransport.logs[0].logLevel).toBe('audit') + expect(other.logs.map((info) => info.message)).toEqual(['audit-event']) }) +}) - it('throws when loggerOptions.level is audit (records would be silently dropped after rewrite)', () => { - expect(() => - createLogger({ - mapAuditLevelForOtel: true, - consoleOptions: { silent: true }, - loggerOptions: { level: 'audit' }, - }), - ).toThrow(/loggerOptions\.level/) +describe('createLogger removed 2.x options', () => { + it.each([ + ['flatten', true], + ['flatten', false], + ['flattenReplacer', () => undefined], + ['mapAuditLevelForOtel', true], + ])('throws for %s, pointing to the migration guide', (key, value) => { + const options = { consoleOptions: { silent: true }, [key]: value } + expect(() => createLogger(options)).toThrow(/Migrating from v2/) }) - it('throws when consoleOptions.level is audit', () => { + it('rejects them at compile time in an object literal', () => { expect(() => - createLogger({ - mapAuditLevelForOtel: true, - consoleOptions: { level: 'audit', silent: true }, - }), - ).toThrow(/consoleOptions\.level/) - }) - - it('throws when any supplied transport has level audit', () => { - const transport = new InMemoryTransport({ level: 'audit' }) + // @ts-expect-error removed in 3.0 + createLogger({ consoleOptions: { silent: true }, flatten: 'otel' }), + ).toThrow(/flatten/) expect(() => - createLogger({ - mapAuditLevelForOtel: true, - consoleOptions: { silent: true }, - transports: [transport], - }), - ).toThrow(/transports\[0\]\.level/) + // @ts-expect-error removed in 3.0 + createLogger({ consoleOptions: { silent: true }, mapAuditLevelForOtel: true }), + ).toThrow(/mapAuditLevelForOtel/) }) }) @@ -671,15 +711,14 @@ describe('createLogger DOMException', () => { transports: [transport], omitPaths: ['service'], redactPaths: ['authorization'], - mapAuditLevelForOtel: true, - flatten: true, + otel: true, }) logger.error('everything on', { service: 'svc', authorization: 'Bearer abc', error: aborted() }) expect(transport.logs[0].service).toBeUndefined() expect(transport.logs[0].authorization).toBe('') - expect(transport.logs[0].error).toContain('TimeoutError') + expect(transport.logs[0].error).toMatchObject({ name: 'TimeoutError', message: 'the operation timed out' }) }) it('serialises one with a configured errorSerializer, wherever it sits in the record', () => { @@ -717,3 +756,6 @@ class InMemoryTransport extends TransportStream { close(): void {} } + +/** Named as `@opentelemetry/winston-transport`'s class is, which is how `otel` finds the transport. */ +class OpenTelemetryTransportV3 extends InMemoryTransport {} diff --git a/src/index.ts b/src/index.ts index 38a92df..3aea2f2 100644 --- a/src/index.ts +++ b/src/index.ts @@ -8,15 +8,13 @@ import { transports, } from 'winston' import * as Transport from 'winston-transport' -import { jsonStringifyValuesFormat } from './json-stringify-values-format' -import { otelAttributesFormat } from './otel-attributes-format' +import { otelAttributesFormat, OtelAttributesFormatOptions } from './otel-attributes-format' import { omitFormat } from './omit-format' import { omitNilFormat } from './omit-nil-format' import { prettyConsoleFormat } from './pretty-console-format' 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 @@ -155,37 +153,16 @@ export interface CreateLoggerOptions { redactedValue?: string /** - * Appends a flattening format as the final logger-level format — applied after every other - * logger-level format (including any `loggerOptions.format`), so it affects every transport. + * Shapes what `@opentelemetry/winston-transport` 0.29 and later receives. Each + * `OpenTelemetryTransportV3` on the logger that has no format of its own gets + * {@link otelAttributesFormat}: the transport `WinstonInstrumentation` adds, and any passed in + * `transports`. Other transports, the console included, keep their nested output. `true` uses the + * format's defaults, and an object is passed to the format as its options. * - * - `'otel'` appends {@link otelAttributesFormat}: the shape `@opentelemetry/winston-transport` 0.29 - * and later needs. An `err`/`error` value stays an object holding `name`, `message` and `stack`, - * which the transport records as the exception, the rest of the error goes to `Detail` as - * JSON, and every other object value becomes a JSON string. - * - `true` appends `jsonStringifyValuesFormat`, serialising every top-level object value — errors - * included — to a JSON string. For a transport before 0.29; from 0.29 the transport records a - * stringified error as one `exception.message` holding the whole JSON. - * - * To flatten only what one transport receives, put the format on that transport instead. + * The format runs after the transport's level filter, so its audit mapping never drops a record. + * A transport added later with `logger.add` is not shaped: give it `otelAttributesFormat()`. */ - flatten?: boolean | 'otel' - - /** - * Optional `JSON.stringify` replacer forwarded to `flatten` when serialising each value. - * Applied in both `flatten` modes. - */ - // eslint-disable-next-line @typescript-eslint/no-explicit-any - flattenReplacer?: (this: any, key: string, value: any) => any - - /** - * When `true`, prepends `mapAuditLevelForOtel` to the logger-level format chain. Rewrites the - * triple-beam `LEVEL` symbol from `audit` to `info` so OTEL maps the record onto a known severity - * tier, and copies the original level onto a `logLevel` property so it survives as an OTEL attribute - * (the OTEL winston-transport strips the string `level`). Enable when shipping logs via OTEL — most - * visibly for Azure Monitor / Log Analytics, but applies to any OTEL backend that relies on the - * spec-defined severity. - */ - mapAuditLevelForOtel?: boolean + otel?: boolean | OtelAttributesFormatOptions /** * Custom serializer used whenever an `Error` instance is encountered: by the logger-level @@ -194,18 +171,53 @@ export interface CreateLoggerOptions { * replacer (safety net for errors that slip through). Defaults to the library's * `serializeError`, which captures `name`/`message`/`stack`/`code`/`cause`/`errors` even when * non-enumerable, walks own enumerable properties, and is safe against circular references. + * Build one with `createErrorSerializer` to leave properties out of every error. */ errorSerializer?: ErrorSerializer /** * Winston `LoggerOptions` forwarded to the underlying logger (e.g. `level`, `defaultMeta`). * `transports` is managed by this library; pass extras via `transports` instead. - * A `format` provided here is appended after the library's logger-level formats, but still runs - * before `flatten` (which is always last when enabled). + * A `format` provided here is appended after the library's logger-level formats. */ loggerOptions?: Omit } +/** 2.x options that 3.0 removed. Each maps onto `otel`. See "Migrating from v2" in the README. */ +const REMOVED_OPTIONS = ['flatten', 'flattenReplacer', 'mapAuditLevelForOtel'] as const + +/** + * Throws for an option that 3.0 removed. TypeScript rejects one in an object literal, but not in + * options built from config or spread from another object. Ignoring it would send OpenTelemetry + * records nested, with no warning. + */ +const rejectRemovedOptions = (options: CreateLoggerOptions) => { + const given = REMOVED_OPTIONS.filter((key) => (options as Record)[key] !== undefined) + if (given.length === 0) return + throw new Error( + `createLogger no longer accepts ${given.join(', ')}. Use the \`otel\` option. ` + + `See "Migrating from v2" in the @makerx/node-winston README.`, + ) +} + +/** + * The class `@opentelemetry/winston-transport` exports. It is matched by name because this library + * does not depend on the transport, which is an optional peer. + */ +const OTEL_TRANSPORT_CLASS = 'OpenTelemetryTransportV3' + +/** + * Gives each OpenTelemetry transport on the logger that has no format of its own the + * `otelAttributesFormat`. `WinstonInstrumentation` adds its transport while winston configures the + * logger, so it is on the logger by the time winston's `createLogger` returns. + */ +const shapeOtelTransports = (logger: WinstonLogger, otelOptions: OtelAttributesFormatOptions) => { + const otelFormat = otelAttributesFormat(otelOptions) + for (const transport of logger.transports) { + if (transport.constructor?.name === OTEL_TRANSPORT_CLASS && !transport.format) transport.format = otelFormat + } +} + export const createConsoleTransport = ({ consoleFormat = 'json', consoleOptions, @@ -237,15 +249,11 @@ export function createLogger>( export function createLogger(options: CreateLoggerOptions): Logger // eslint-disable-next-line @typescript-eslint/no-explicit-any export function createLogger(options: CreateLoggerOptions): any { - const { - omitPaths, - redactPaths, - redactedValue = '', - flatten, - flattenReplacer, - errorSerializer, - mapAuditLevelForOtel: mapAuditForOtel, - } = options + const { omitPaths, redactPaths, redactedValue = '', errorSerializer, otel } = options + + rejectRemovedOptions(options) + + const otelOptions: OtelAttributesFormatOptions | undefined = otel === true ? {} : otel || undefined // register default colours on first use of a known level set so `colorize` / pretty output works. // Detected by referential equality: an unknown `levels` map means the caller is responsible for @@ -254,25 +262,6 @@ export function createLogger(options: CreateLoggerOptions): any { if (!userLevels || userLevels === defaultLevels) registerDefaultColors() else if (userLevels === winstonDefaultLevels) registerWinstonDefaultColors() - // Guard against silent audit-record loss: the format rewrites the LEVEL symbol from 'audit' to 'info', - // which the filter on any transport set to level:'audit' would then drop (info is more verbose than audit). - if (mapAuditForOtel) { - const misconfigured: string[] = [] - if (options.loggerOptions?.level === 'audit') misconfigured.push('loggerOptions.level') - if (options.consoleOptions?.level === 'audit') misconfigured.push('consoleOptions.level') - options.transports?.forEach((t, i) => { - if (t.level === 'audit') misconfigured.push(`transports[${i}].level`) - }) - if (misconfigured.length > 0) { - throw new Error( - `Set ${misconfigured.join(', ')} to 'info' (or a more verbose level) instead of 'audit'. ` + - `mapAuditLevelForOtel rewrites the triple-beam LEVEL symbol from 'audit' to 'info' so ` + - `OTEL maps the record onto a known severity tier — an 'audit'-level filter would then ` + - `drop those records after the rewrite.`, - ) - } - } - // aggregate transports const consoleTransport = createConsoleTransport(options) const transports: Transport[] = [consoleTransport] @@ -280,7 +269,6 @@ export function createLogger(options: CreateLoggerOptions): any { // logger-level formats apply to all transports const loggerFormats: Format[] = [serializeErrorFormat({ serializer: errorSerializer })] - if (mapAuditForOtel) loggerFormats.push(mapAuditLevelForOtel()) if (omitPaths) loggerFormats.push(omitFormat({ paths: omitPaths })) // `errorSerializer` is passed for consistency rather than for effect: `serializeErrorFormat` runs // first and leaves no live `Error` behind, so redaction has nothing left to substitute here. It @@ -288,9 +276,6 @@ export function createLogger(options: CreateLoggerOptions): any { // path ever does let one through. if (redactPaths) loggerFormats.push(redactFormat({ paths: redactPaths, redactedValue, errorSerializer })) if (options.loggerOptions?.format) loggerFormats.push(options.loggerOptions.format) - // flatten is applied last so all prior transformations are captured in the stringified values - if (flatten === 'otel') loggerFormats.push(otelAttributesFormat({ replacer: flattenReplacer })) - else if (flatten) loggerFormats.push(jsonStringifyValuesFormat({ replacer: flattenReplacer })) // create logger options using supplied options + transports; loggerOptions.levels (if any) overrides defaultLevels const loggerOptions: LoggerOptions = { @@ -300,7 +285,10 @@ export function createLogger(options: CreateLoggerOptions): any { transports, } + const logger = winstonCreateLogger(loggerOptions) + if (otelOptions) shapeOtelTransports(logger, otelOptions) + // 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)) + return withNormalizedErrorArgs(logger, Object.keys(loggerOptions.levels ?? defaultLevels)) } diff --git a/src/json-stringify-values-format.ts b/src/json-stringify-values-format.ts index 6333725..1bcf800 100644 --- a/src/json-stringify-values-format.ts +++ b/src/json-stringify-values-format.ts @@ -3,8 +3,10 @@ import { format } from 'winston' /** * Serialises all top-level object values on the log info to JSON strings, producing a flat - * `{ key: string }` shape suitable for transports and aggregators that expect scalar values - * (e.g. OTEL + Azure Log Analytics). + * `{ key: string }` shape for transports and aggregators that expect scalar values. + * + * Do not use it for `@opentelemetry/winston-transport`: from 0.29 the transport records an error + * written as a JSON string as one `exception.message`. Use `otelAttributesFormat` there. * * Accepts an optional `replacer` forwarded to `JSON.stringify` for each value. * diff --git a/src/map-audit-level-for-otel.ts b/src/map-audit-level-for-otel.ts index 21acbed..113c6bd 100644 --- a/src/map-audit-level-for-otel.ts +++ b/src/map-audit-level-for-otel.ts @@ -1,32 +1,30 @@ -import { LEVEL } from 'triple-beam' import { format } from 'winston' +import { applyAuditLevelMapping } from './audit-level' /** * OTEL's log spec defines a fixed severity enumeration (trace/debug/info/warn/error/fatal). - * `@opentelemetry/winston-transport` (auto-installed by `@opentelemetry/instrumentation-winston`) - * derives `severityText` / `severityNumber` from Winston's triple-beam `LEVEL` symbol and strips - * the string `level` property before building attributes — so Winston's custom `audit` level - * arrives at any OTEL backend with `severityNumber: undefined` and no queryable record of the - * original level. This is most visible on Azure Monitor / Log Analytics (which ignores records - * without a mapped severity), but applies to any OTEL backend that relies on the spec-defined - * severity. + * `@opentelemetry/winston-transport` derives `severityText` / `severityNumber` from Winston's + * triple-beam `LEVEL` symbol and strips the string `level` property before building attributes, + * so the custom `audit` level arrives at an OTEL backend with no severity and no queryable + * record of the original level. A backend stores such a record with no severity or a default one, + * and a transport `logSeverity` filter drops it. * * This format: * - rewrites `info[LEVEL]` from `audit` to `info` so OTEL maps to a known severity tier * - copies the original level onto `logLevel` on every record so it survives as an OTEL - * attribute (e.g. queryable as `customDimensions.logLevel == "audit"` in Azure Log Analytics) + * attribute (e.g. queryable as `customDimensions.logLevel == "audit"` in Azure Log Analytics). + * A record that already has a string `logLevel` keeps it. * - * The string `info.level` is left as-is — it's only consumed by other winston transports (e.g. - * our Console transport's JSON output), so leaving it alone keeps local output readable. + * The level is read from `info[LEVEL]`, so a format that rewrites the string `info.level`, such as + * `format.colorize()`, can run first. The string `info.level` is left as it is, so other + * transports still show `audit`. * - * Caveat: because the `LEVEL` symbol also drives transport-level filtering, a logger/transport - * explicitly set to `level: 'audit'` would drop these records after rewrite (info is more - * verbose than audit). `createLogger` guards against that by throwing when the option is - * enabled alongside an `audit`-level logger/console/transport; when using the format - * standalone, apply the same discipline. Only enable this when shipping logs via OTEL. + * `otelAttributesFormat` already does this, so most loggers need only that. Use this format on + * its own in a chain you build yourself, for example beside `jsonStringifyValuesFormat`. + * + * Caveat: the `LEVEL` symbol also drives transport-level filtering. On a transport's own format + * the mapping runs after that transport's filter, so it is always safe there. At the logger + * level it runs before every transport's filter, so a logger or transport set to `level: 'audit'` + * would drop these records (`info` is more verbose than `audit`). Use `'info'` there instead. */ -export const mapAuditLevelForOtel = format((info) => { - info.logLevel = info.level - if (info.level === 'audit') info[LEVEL] = 'info' - return info -}) +export const mapAuditLevelForOtel = format((info) => applyAuditLevelMapping(info)) diff --git a/src/otel-attributes-format.spec.ts b/src/otel-attributes-format.spec.ts index 456efe4..f5365bc 100644 --- a/src/otel-attributes-format.spec.ts +++ b/src/otel-attributes-format.spec.ts @@ -101,3 +101,120 @@ describe('otelAttributesFormat — other values', () => { expect(run({ obj: { a: 1 } })[LEVEL]).toBe('error') }) }) + +describe('otelAttributesFormat — level', () => { + const at = (level: string) => run({ [LEVEL]: level, level }) + + it('exports an audit record at info severity and keeps the original on logLevel', () => { + const result = at('audit') + expect(result[LEVEL]).toBe('info') + expect(result.level).toBe('audit') + expect(result.logLevel).toBe('audit') + }) + + it('records logLevel on every other level and leaves its LEVEL alone', () => { + const result = at('warn') + expect(result[LEVEL]).toBe('warn') + expect(result.logLevel).toBe('warn') + }) + + it('reads the level from LEVEL, so a colorized string level still maps', () => { + const result = run({ [LEVEL]: 'audit', level: '\u001b[35maudit\u001b[39m' }) + expect(result[LEVEL]).toBe('info') + expect(result.logLevel).toBe('audit') + }) + + it('keeps a string logLevel the record already has', () => { + expect(run({ [LEVEL]: 'audit', level: 'audit', logLevel: 'custom' }).logLevel).toBe('custom') + }) +}) + +/** A serialized error holding other errors: a cause, a list of attempts, and the latest attempt again. */ +const withAttempts = () => { + const attempt = (n: number) => serialized({ message: `attempt ${n}`, headers: { 'x-request-id': `req-${n}` } }) + const attempts = [attempt(1), attempt(2)] + return serialized({ cause: serialized({ message: 'root' }), attempts, latest: attempts[1] }) +} + +describe('otelAttributesFormat — replacer', () => { + it('is called with the holding object as `this`, so it can leave a property out by its siblings', () => { + function replacer(this: Record, key: string, value: unknown) { + if (key === 'headers') return undefined + if (key === 'latest' && Array.isArray(this.attempts)) return undefined + return value + } + const detail = JSON.parse(run({ error: withAttempts() }, { replacer }).errorDetail as string) as Record + expect(detail).not.toHaveProperty('latest') + expect(detail.attempts).toEqual([ + { name: 'Error', message: 'attempt 1', stack: 'Error: boom\n at x' }, + { name: 'Error', message: 'attempt 2', stack: 'Error: boom\n at x' }, + ]) + }) +}) + +describe('otelAttributesFormat — length cap', () => { + const long = 'x'.repeat(20_000) + + it('writes every string whole by default', () => { + expect(JSON.parse(run({ ctx: { body: long } }).ctx as string)).toEqual({ body: long }) + expect(JSON.parse(run({ error: serialized({ body: long }) }).errorDetail as string)).toEqual({ body: long }) + }) + + it('cuts errorDetail to maxAttributeLength, ending in [Truncated]', () => { + const detail = run({ error: serialized({ body: long }) }, { maxAttributeLength: 8192 }).errorDetail as string + expect(detail).toHaveLength(8192) + expect(detail.endsWith('[Truncated]')).toBe(true) + }) + + it('cuts other stringified values too', () => { + const value = run({ ctx: { body: long } }, { maxAttributeLength: 100 }).ctx as string + expect(value).toHaveLength(100) + expect(value.endsWith('[Truncated]')).toBe(true) + }) + + it('leaves strings the caller wrote, the message and the exception whole', () => { + const result = run({ message: long, text: long, error: serialized({ message: long, stack: long }) }, { maxAttributeLength: 100 }) + expect(result.message).toBe(long) + expect(result.text).toBe(long) + expect(result.error).toMatchObject({ message: long, stack: long }) + }) + + // `{"body":"` is 9 characters and each emoji is 2, so at 31 the cut falls inside a pair and at 30 + // it falls between two pairs. + it.each([30, 31])('does not split a surrogate pair at maxAttributeLength %i', (max) => { + const value = run({ ctx: { body: '😀'.repeat(100) } }, { maxAttributeLength: max }).ctx as string + expect(value.length).toBeLessThanOrEqual(max) + expect(value.endsWith('[Truncated]')).toBe(true) + expect(/[\uD800-\uDBFF](?![\uDC00-\uDFFF])/.test(value)).toBe(false) + }) + + it('writes as much of the marker as fits when maxAttributeLength is shorter than it', () => { + expect(run({ ctx: { body: 'x'.repeat(100) } }, { maxAttributeLength: 5 }).ctx).toBe('[Trun') + }) + + it('cuts nothing when maxAttributeLength is negative or NaN', () => { + expect(JSON.parse(run({ ctx: { body: 'x' } }, { maxAttributeLength: -1 }).ctx as string)).toEqual({ body: 'x' }) + expect(JSON.parse(run({ ctx: { body: 'x' } }, { maxAttributeLength: NaN }).ctx as string)).toEqual({ body: 'x' }) + }) +}) + +describe('otelAttributesFormat — shared state', () => { + it('changes no nested value, so other transports keep their own objects', () => { + const error = withAttempts() + const ctx = { inner: { a: 1 }, list: [{ b: 2 }] } + const before = structuredClone({ error, ctx }) + run({ error, ctx }) + expect({ error, ctx }).toEqual(before) + }) + + it('applied twice writes the same record as applied once', () => { + const fmt = otelAttributesFormat() + const input = { [LEVEL]: 'audit', level: 'audit', message: 'm', error: withAttempts(), ctx: { a: 1 } } as unknown as TransformableInfo + const once = fmt.transform(input, fmt.options) as TransformableInfo + const onceCopy = { ...once } + const twice = fmt.transform(once, fmt.options) as TransformableInfo + expect(twice).toEqual(onceCopy) + expect(twice[LEVEL]).toBe('info') + expect(twice.logLevel).toBe('audit') + }) +}) diff --git a/src/otel-attributes-format.ts b/src/otel-attributes-format.ts index 5b7f311..3e6e393 100644 --- a/src/otel-attributes-format.ts +++ b/src/otel-attributes-format.ts @@ -1,13 +1,57 @@ import { format } from 'winston' +import { applyAuditLevelMapping } from './audit-level' import { serializeError } from './serialize-error' import { serializesItself } from './serializes-itself' // eslint-disable-next-line @typescript-eslint/no-explicit-any type Replacer = (this: any, key: string, value: any) => any +const TRUNCATED = '[Truncated]' + export interface OtelAttributesFormatOptions { - /** `JSON.stringify` replacer applied to every value this format stringifies, `errorDetail` included. */ + /** + * `JSON.stringify` replacer applied to every value this format stringifies, `errorDetail` + * included. It is called with the object that holds the value as `this`, so it can decide on a + * property from the other properties of that object. Return `undefined` to leave the property out. + */ replacer?: Replacer + + /** + * The longest string this format writes. A longer one is cut short and ends in `[Truncated]`. Set + * it to the backend's limit so that the backend does not cut the value without a marker. By + * default every string is written whole. Values that were already strings are never cut. A limit + * shorter than the 11-character marker writes as much of the marker as fits. + * + * @example App Insights keeps 8,192 characters of a custom dimension + * ```ts + * otelAttributesFormat({ maxAttributeLength: 8192 }) + * ``` + */ + maxAttributeLength?: number +} + +interface Settings { + replacer: Replacer | undefined + maxAttributeLength: number +} + +const resolveSettings = (opts: OtelAttributesFormatOptions): Settings => ({ + replacer: opts.replacer, + maxAttributeLength: opts.maxAttributeLength ?? Infinity, +}) + +/** A format instance keeps one options object for its lifetime, so its settings are resolved once. */ +const settingsCache = new WeakMap() +const defaultSettings = resolveSettings({}) + +const settingsFor = (opts: OtelAttributesFormatOptions | undefined): Settings => { + if (!opts) return defaultSettings + let settings = settingsCache.get(opts) + if (!settings) { + settings = resolveSettings(opts) + settingsCache.set(opts, settings) + } + return settings } /** The keys `@opentelemetry/winston-transport` reads an exception from, in the order it tries them. */ @@ -35,38 +79,59 @@ const isDescribableCause = (cause: unknown): boolean => typeof cause.code === 'string' || typeof cause.code === 'number')) -/** Plain JSON for any value: errors serialized, BigInts written as `n`, and never a throw out of the log call. */ -const stringify = (value: unknown, replacer: Replacer | undefined): string => { +/** + * Cuts a string to `max`, ending in `[Truncated]`, without splitting a surrogate pair. A `max` + * shorter than the marker gets as much of the marker as fits. A negative or `NaN` `max` cuts nothing. + */ +const cap = (text: string, max: number): string => { + if (!(text.length > max)) return text + if (max < 0) return text + if (max < TRUNCATED.length) return TRUNCATED.slice(0, max) + let end = max - TRUNCATED.length + const last = text.charCodeAt(end - 1) + if (last >= 0xd800 && last <= 0xdbff) end -= 1 + return text.slice(0, end) + TRUNCATED +} + +/** Plain JSON for any value: errors serialized, BigInts written as `n`, the result capped, and never a throw out of the log call. */ +const stringify = (value: unknown, settings: Settings): string => { + const { replacer } = settings const plain = function (this: unknown, key: string, entry: unknown): unknown { const converted = entry instanceof Error ? serializeError(entry) : typeof entry === 'bigint' ? `${entry}n` : entry return replacer ? (replacer.call(this, key, converted) as unknown) : converted } + let json: string try { - return JSON.stringify(value, plain) ?? String(value) + json = JSON.stringify(value, plain) ?? String(value) } catch { - return '[Unserializable]' + json = '[Unserializable]' } + return cap(json, settings.maxAttributeLength) } /** A value that writes itself as a primitive (a `Date`'s ISO string) is kept unquoted, so a query reads it as it is. */ -const flatValue = (value: object, replacer: Replacer | undefined): unknown => { - if (!replacer && serializesItself(value)) { +const flatValue = (value: object, settings: Settings): unknown => { + if (!settings.replacer && serializesItself(value)) { try { const json: unknown = (value as { toJSON: () => unknown }).toJSON() - if (json === null || typeof json === 'string' || typeof json === 'number' || typeof json === 'boolean') return json + if (typeof json === 'string') return cap(json, settings.maxAttributeLength) + if (json === null || typeof json === 'number' || typeof json === 'boolean') return json } catch { // fall through to the JSON of the value itself } } - return stringify(value, replacer) + return stringify(value, settings) } /** * Leaves the exception what the logs SDK reads — `name`, `message`, `stack`, and a cause it can * describe — and moves the rest of the error to `Detail` as JSON. The SDK takes a truthy `code` * over `name` for `exception.type`, so `code` moves too, unless there is no `name` to take its place. + * + * A `Detail` that is already a string is kept: the error was split by an earlier pass, and + * splitting what that pass left would replace the detail with the cause alone. */ -const splitException = (record: Record, key: string, error: Record, replacer: Replacer | undefined) => { +const splitException = (record: Record, key: string, error: Record, settings: Settings) => { const exception: Record = {} const detail: Record = {} for (const [field, value] of Object.entries(error)) { @@ -79,7 +144,9 @@ const splitException = (record: Record, key: string, error: Rec delete detail.code } record[key] = exception - if (Object.keys(detail).length > 0) record[`${key}Detail`] = stringify(detail, replacer) + const detailKey = `${key}Detail` + if (typeof record[detailKey] === 'string') return + if (Object.keys(detail).length > 0) record[detailKey] = stringify(detail, settings) } /** @@ -98,21 +165,29 @@ const splitException = (record: Record, key: string, error: Rec * turn them into nested map attributes, which most backends — Azure Log Analytics included — do not * index. Scalars are left alone. A `Date` becomes its ISO string, unquoted. * - * Use it on the transport to keep other transports' output nested, or through - * `createLogger({ flatten: 'otel' })` when the transport is added for you, as `WinstonInstrumentation` - * does. For a transport before 0.29, which has no exception handling, use `jsonStringifyValuesFormat`. + * OpenTelemetry has no severity for the custom `audit` level, so the format exports an `audit` + * record at `info` severity. It copies every record's level onto `logLevel`, which keeps `audit` + * apart from `info`, and `debug` apart from `verbose`, in a backend that stores only the severity. + * See {@link OtelAttributesFormatOptions} to cap the strings it writes or pass a replacer. + * + * `createLogger({ otel: true })` puts it on the OpenTelemetry transport, so other transports keep + * their nested output. Use it directly only in a format chain you build yourself, on that + * transport's own format: there the audit mapping runs after the transport's level filter, so it + * never drops a record. * - * Mutates `info` in place, so winston's Symbol-keyed routing properties are preserved. + * Mutates `info` in place, so winston's Symbol-keyed routing properties are preserved. Nested + * values are never changed. */ export const otelAttributesFormat = format((info, opts) => { - const { replacer } = (opts ?? {}) as OtelAttributesFormatOptions + const settings = settingsFor(opts as OtelAttributesFormatOptions | undefined) + applyAuditLevelMapping(info) const record = info as unknown as Record const lifted = EXCEPTION_KEYS.find((key) => isExceptionCandidate(record[key])) for (const key of Object.keys(record)) { const value = record[key] if (!isObject(value)) continue - if (key === lifted) splitException(record, key, value instanceof Error ? serializeError(value) : value, replacer) - else record[key] = flatValue(value, replacer) + if (key === lifted) splitException(record, key, value instanceof Error ? serializeError(value) : value, settings) + else record[key] = flatValue(value, settings) } return info }) diff --git a/src/otel-transport.spec.ts b/src/otel-transport.spec.ts index 4c65e61..8275389 100644 --- a/src/otel-transport.spec.ts +++ b/src/otel-transport.spec.ts @@ -2,22 +2,23 @@ * What a record looks like once it is an OpenTelemetry log record, through the real * `@opentelemetry/winston-transport` and the logs SDK — the row a backend stores. * - * Three transport lines, installed side by side under npm aliases: - * - 0.27: no exception handling; every attribute is passed through as it is. - * - 0.31: lifts `err`/`error` off the record as the exception (from 0.29). - * - 0.34: also normalises object attributes into nested maps, errors included (from 0.32). + * The supported transport line, installed side by side: + * - 0.29, under an npm alias: the oldest release that lifts `err`/`error` off the record as the + * exception. + * - latest, under its own name: also normalises object attributes into nested maps (from 0.32), + * and takes `severityMapping` and `logSeverity` options (from 0.34). * * Each transport binds its logger when it is constructed, so the provider is registered first. */ -import { logs } from '@opentelemetry/api-logs' +import { logs, SeverityNumber } from '@opentelemetry/api-logs' import { InMemoryLogRecordExporter, LoggerProvider, SimpleLogRecordProcessor } from '@opentelemetry/sdk-logs' -import { OpenTelemetryTransportV3 as Transport034 } from '@opentelemetry/winston-transport' -import { OpenTelemetryTransportV3 as Transport027 } from 'otel-winston-transport-0.27' -import { OpenTelemetryTransportV3 as Transport031 } from 'otel-winston-transport-0.31' +import { OpenTelemetryTransportV3 as Transport029 } from 'otel-winston-transport-0.29' +import { OpenTelemetryTransportV3 as TransportLatest } from '@opentelemetry/winston-transport' import { afterAll, beforeAll, describe, expect, it } from 'vitest' +import { format } from 'winston' import type TransportStream from 'winston-transport' -import { CallbackTransport, createLogger, type CreateLoggerOptions } from './index' -import { otelAttributesFormat } from './otel-attributes-format' +import { CallbackTransport, createErrorSerializer, createLogger, type CreateLoggerOptions, type Logger } from './index' +import { jsonStringifyValuesFormat } from './json-stringify-values-format' type TransportClass = new (options?: TransportStream.TransportStreamOptions) => TransportStream @@ -42,65 +43,61 @@ class ProviderError extends Error { const failure = () => new ProviderError('Request too large', { cause: new Error('body exceeds limit') }) const at = new Date('2026-01-02T03:04:05.000Z') +/** An AI SDK `APICallError`: the prompt and the response headers are own properties. */ +const apiCallError = (attempt: number) => + Object.assign(new Error(`attempt ${attempt} failed`), { + name: 'AI_APICallError', + statusCode: 429, + requestBodyValues: { messages: [{ role: 'user', content: 'the whole prompt' }] }, + responseHeaders: { 'x-request-id': `req-${attempt}` }, + }) + +/** An AI SDK `RetryError`: every attempt under `errors`, and the last once more under `lastError`. */ +const retryError = () => { + const errors = [apiCallError(1), apiCallError(2)] + return Object.assign(new Error('Failed after 2 attempts'), { name: 'AI_RetryError', errors, lastError: errors[1] }) +} + let sequence = 0 -/** Logs one error line through a fresh logger on `Transport` and returns its exported attributes. */ -async function exported(Transport: TransportClass, options: Partial = {}, transport?: TransportStream) { +/** Logs one line through a fresh logger and returns the log records it exported. */ +async function emitted(options: Partial, log: (logger: Logger, message: string) => void) { const message = `line ${++sequence}` - const logger = createLogger({ consoleOptions: { silent: true }, transports: [transport ?? new Transport()], ...options }) - logger.error(message, { error: failure(), at, request: { route: '/chat', attempt: 2 } }) + const logger = createLogger({ consoleOptions: { silent: true }, ...options }) + log(logger, message) await new Promise((resolve) => setImmediate(resolve)) - const records = exporter.getFinishedLogRecords().filter((record) => record.body === message) + return exporter.getFinishedLogRecords().filter((record) => record.body === message) +} + +/** Logs one error line through a fresh logger on `Transport` and returns its exported attributes. */ +async function exported(Transport: TransportClass, options: Partial = {}, transport?: TransportStream) { + const records = await emitted({ transports: [transport ?? new Transport()], ...options }, (logger, message) => + logger.error(message, { error: failure(), at, request: { route: '/chat', attempt: 2 } }), + ) expect(records).toHaveLength(1) return records[0].attributes as Record } const isScalar = (value: unknown) => value === null || ['string', 'number', 'boolean'].includes(typeof value) -describe('flatten: true', () => { - it('0.27 writes the error as one JSON attribute holding its message and status', async () => { - const attributes = await exported(Transport027, { flatten: true }) - expect(JSON.parse(attributes.error as string)).toMatchObject({ message: 'Request too large', statusCode: 413 }) - expect(attributes).not.toHaveProperty('exception.message') - }) - - it.each([ - ['0.31', Transport031], - ['0.34', Transport034], - ])( - '%s records the whole error JSON as exception.message, which is why flatten: true is for transports before 0.29', - async (_, Transport) => { - const attributes = await exported(Transport, { flatten: true }) - expect(String(attributes['exception.message']).startsWith('{')).toBe(true) - expect(attributes).not.toHaveProperty('exception.type') - }, - ) -}) - -describe('no flatten', () => { - it('0.34 records the exception but drops the rest of the error', async () => { - const attributes = await exported(Transport034) - expect(attributes['exception.message']).toBe('Request too large') - expect(JSON.stringify(attributes)).not.toContain('413') - }) -}) +const lines: [string, TransportClass][] = [ + ['0.29', Transport029], + ['latest', TransportLatest], +] -describe.each([ - ['0.31', Transport031], - ['0.34', Transport034], -])("flatten: 'otel' on %s", (_, Transport) => { +describe.each(lines)('otel: true on %s', (_, Transport) => { it('records the error as exception.type, exception.message and exception.stacktrace', async () => { - const attributes = await exported(Transport, { flatten: 'otel' }) + const attributes = await exported(Transport, { otel: true }) expect(attributes).toMatchObject({ 'exception.type': 'ProviderError', 'exception.message': 'Request too large' }) expect(String(attributes['exception.stacktrace'])).toContain('Request too large') }) it("records the error's cause as error.cause.message", async () => { - expect((await exported(Transport, { flatten: 'otel' }))['error.cause.message']).toBe('body exceeds limit') + expect((await exported(Transport, { otel: true }))['error.cause.message']).toBe('body exceeds limit') }) it("keeps the error's status, provider data and cause chain under errorDetail", async () => { - const attributes = await exported(Transport, { flatten: 'otel' }) + const attributes = await exported(Transport, { otel: true }) expect(JSON.parse(attributes.errorDetail as string)).toMatchObject({ statusCode: 413, data: { error: { code: 'request_too_large' } }, @@ -109,36 +106,122 @@ describe.each([ }) it('writes every attribute as a scalar, none of them [object Object]', async () => { - const attributes = await exported(Transport, { flatten: 'otel' }) + const attributes = await exported(Transport, { otel: true }) expect(Object.values(attributes).every(isScalar)).toBe(true) expect(Object.values(attributes)).not.toContain('[object Object]') }) it('writes other objects as JSON strings and a Date as its ISO string', async () => { - const attributes = await exported(Transport, { flatten: 'otel' }) + const attributes = await exported(Transport, { otel: true }) expect(attributes.request).toBe('{"route":"/chat","attempt":2}') expect(attributes.at).toBe('2026-01-02T03:04:05.000Z') }) -}) -describe('otelAttributesFormat on the transport', () => { - it('flattens what the OpenTelemetry transport receives and leaves other transports nested', async () => { + it('exports an audit record at INFO severity, with logLevel audit', async () => { + const records = await emitted({ otel: true, transports: [new Transport()] }, (logger, message) => logger.audit(message)) + expect(records).toHaveLength(1) + expect(records[0].severityNumber).toBe(SeverityNumber.INFO) + expect(records[0].attributes.logLevel).toBe('audit') + }) + + // The README's recipe for AI SDK errors, built from generic options only. + it('exports an audit record at INFO severity when loggerOptions.format colorizes the level', async () => { + const records = await emitted( + { otel: true, loggerOptions: { format: format.colorize() }, transports: [new Transport()] }, + (logger, message) => logger.audit(message), + ) + expect(records[0].severityNumber).toBe(SeverityNumber.INFO) + expect(records[0].attributes.logLevel).toBe('audit') + }) + + it('redacts the prompt and trims a failed retry with redactPaths and createErrorSerializer', async () => { + const options: Partial = { + otel: { maxAttributeLength: 8192 }, + redactPaths: ['requestBodyValues'], + errorSerializer: createErrorSerializer({ + omit: (key, error) => key === 'responseHeaders' || (key === 'lastError' && 'errors' in error), + }), + transports: [new Transport()], + } + const [record] = await emitted(options, (logger, message) => logger.error(message, { error: retryError() })) + expect(record.attributes['exception.type']).toBe('AI_RetryError') + const detail = JSON.parse(record.attributes.errorDetail as string) as { errors: Record[] } + expect(detail).not.toHaveProperty('lastError') + expect(detail.errors).toHaveLength(2) + expect(detail.errors.map((attempt) => attempt.requestBodyValues)).toEqual(['', '']) + expect(detail.errors.some((attempt) => 'responseHeaders' in attempt)).toBe(false) + expect(JSON.stringify(record.attributes)).not.toContain('the whole prompt') + }) + + it('caps errorDetail at maxAttributeLength', async () => { + const [record] = await emitted({ otel: { maxAttributeLength: 8192 }, transports: [new Transport()] }, (logger, message) => + logger.error(message, { error: Object.assign(new Error('big'), { body: 'x'.repeat(20_000) }) }), + ) + const detail = record.attributes.errorDetail as string + expect(detail).toHaveLength(8192) + expect(detail.endsWith('[Truncated]')).toBe(true) + }) + + // Upstream behaviour, pinned so that a change to it fails this test. With no `err` or `error` on + // the record, the transport takes the first splat argument that has a `name`, `code`, `message` + // or `stack` as the record's exception. + it('records a metadata object with a name as the exception when there is no err or error', async () => { + const [record] = await emitted({ otel: true, transports: [new Transport()] }, (logger, message) => + logger.info(message, { name: 'Alice' }), + ) + expect(record.attributes['exception.type']).toBe('Alice') + expect(record.attributes.name).toBe('Alice') + }) + + it('leaves other transports nested', async () => { const seen: Record[] = [] const sibling = new CallbackTransport( async ({ meta }) => void seen.push(meta), () => undefined, ) - const message = `line ${++sequence}` - const logger = createLogger({ - consoleOptions: { silent: true }, - transports: [new Transport034({ format: otelAttributesFormat() }), sibling], - }) - logger.error(message, { error: failure(), request: { route: '/chat' } }) - await new Promise((resolve) => setImmediate(resolve)) - - const [record] = exporter.getFinishedLogRecords().filter((r) => r.body === message) + const [record] = await emitted({ otel: true, transports: [new Transport(), sibling] }, (logger, message) => + logger.error(message, { error: failure(), request: { route: '/chat' } }), + ) expect(record.attributes).toMatchObject({ 'exception.type': 'ProviderError', request: '{"route":"/chat"}' }) expect(seen[0].request).toEqual({ route: '/chat' }) expect(seen[0].error).toMatchObject({ statusCode: 413 }) }) + + it('exports audit records at INFO severity from a transport set to level audit', async () => { + const records = await emitted({ otel: true, transports: [new Transport({ level: 'audit' })] }, (logger, message) => { + logger.audit(message) + logger.info(message) + }) + expect(records).toHaveLength(1) + expect(records[0].severityNumber).toBe(SeverityNumber.INFO) + expect(records[0].attributes.logLevel).toBe('audit') + }) +}) + +describe.each(lines)('jsonStringifyValuesFormat on %s', (_, Transport) => { + it('records the whole error JSON as exception.message, which is why it is not for the OpenTelemetry transport', async () => { + const attributes = await exported(Transport, {}, new Transport({ format: jsonStringifyValuesFormat() })) + expect(String(attributes['exception.message']).startsWith('{')).toBe(true) + expect(attributes).not.toHaveProperty('exception.type') + }) +}) + +describe('without otel on latest', () => { + it('records the exception but drops the rest of the error', async () => { + const attributes = await exported(TransportLatest) + expect(attributes['exception.message']).toBe('Request too large') + expect(JSON.stringify(attributes)).not.toContain('413') + }) +}) + +describe('logSeverity on latest', () => { + it('drops an audit record without otel, because nothing gives it a severity', async () => { + const transport = new TransportLatest({ logSeverity: SeverityNumber.INFO }) + expect(await emitted({ transports: [transport] }, (logger, message) => logger.audit(message))).toHaveLength(0) + }) + + it('keeps an audit record otel maps', async () => { + const transport = new TransportLatest({ logSeverity: SeverityNumber.INFO }) + expect(await emitted({ otel: true, transports: [transport] }, (logger, message) => logger.audit(message))).toHaveLength(1) + }) }) diff --git a/src/serialize-error.spec.ts b/src/serialize-error.spec.ts index 05e000d..81ccaa9 100644 --- a/src/serialize-error.spec.ts +++ b/src/serialize-error.spec.ts @@ -1,6 +1,6 @@ import { Readable } from 'node:stream' import { describe, expect, it } from 'vitest' -import { createSerializableErrorReplacer, serializableErrorReplacer, serializeError } from './serialize-error' +import { createErrorSerializer, createSerializableErrorReplacer, serializableErrorReplacer, serializeError } from './serialize-error' describe('serializeError', () => { it('message and stack are not enumerable (and not serialized) by default', () => { @@ -211,3 +211,105 @@ describe('createSerializableErrorReplacer', () => { expect(out.summary).toBeUndefined() }) }) + +describe('createErrorSerializer', () => { + /** An error with response headers as an own property, as an HTTP client's error might carry. */ + const httpError = (attempt: number) => + Object.assign(new Error(`attempt ${attempt} failed`), { statusCode: 429, headers: { 'x-request-id': `req-${attempt}` } }) + + /** An error holding each attempt under `attempts`, and the latest one again under `latest`. */ + const retryError = () => { + const attempts = [httpError(1), httpError(2)] + return Object.assign(new Error('failed after 2 attempts'), { attempts, latest: attempts[1] }) + } + + it('with no options, writes what serializeError writes', () => { + const error = Object.assign(new Error('plain'), { code: 'E_X', detail: { a: [1, 2] } }) + expect(createErrorSerializer()(error)).toEqual(serializeError(error)) + }) + + it('omit leaves a property out of the error and of every error inside it', () => { + const serializer = createErrorSerializer({ omit: (key) => key === 'headers' }) + const out = serializer(new Error('wrapped', { cause: retryError() })) as { cause: { attempts: object[]; latest: object } } + expect(out.cause.attempts).toHaveLength(2) + expect(out.cause.attempts.every((attempt) => !('headers' in attempt))).toBe(true) + expect(out.cause.latest).not.toHaveProperty('headers') + expect(out.cause.attempts[0]).toMatchObject({ message: 'attempt 1 failed', statusCode: 429 }) + }) + + it('omit is given the error, so it can decide by its other properties', () => { + const serializer = createErrorSerializer({ omit: (key, error) => key === 'latest' && 'attempts' in error }) + expect(serializer(retryError())).not.toHaveProperty('latest') + expect(serializer(Object.assign(new Error('x'), { latest: httpError(1) }))).toHaveProperty('latest') + }) + + it('omit can leave out a well-known property', () => { + expect(createErrorSerializer({ omit: (key) => key === 'stack' })(new Error('x'))).not.toHaveProperty('stack') + }) + + it('omit is called for a plain object with a string name, message and stack', () => { + const serialized = { name: 'RemoteError', message: 'm', stack: 'RemoteError: m', headers: { a: '1' } } + const out = createErrorSerializer({ omit: (key) => key === 'headers' })(Object.assign(new Error('x'), { remote: serialized })) + expect(out.remote).toEqual({ name: 'RemoteError', message: 'm', stack: 'RemoteError: m' }) + }) + + it('omit is never asked about any other plain object', () => { + const asked: string[] = [] + const serializer = createErrorSerializer({ + omit: (key) => { + asked.push(key) + return false + }, + }) + serializer(Object.assign(new Error('x'), { context: { headers: {} } })) + expect(asked).not.toContain('headers') + expect(asked).toContain('context') + }) + + it('omit that throws keeps the property', () => { + const serializer = createErrorSerializer({ + omit: () => { + throw new Error('bad predicate') + }, + }) + expect(serializer(new Error('x'))).toMatchObject({ name: 'Error', message: 'x' }) + }) + + it('dedupe writes a shared object once, and every later occurrence as [Duplicate]', () => { + const out = createErrorSerializer({ dedupe: true })(retryError()) as { attempts: object[]; latest: unknown } + expect(out.attempts[1]).toMatchObject({ message: 'attempt 2 failed' }) + expect(out.latest).toBe('[Duplicate]') + }) + + it('dedupe still writes a Date in full each time, and a cycle as [Circular]', () => { + const at = new Date('2026-01-02T03:04:05.000Z') + const error = Object.assign(new Error('x'), { first: at, second: at }) + Object.assign(error, { self: error }) + const out = createErrorSerializer({ dedupe: true })(error) + expect(out).toMatchObject({ first: '2026-01-02T03:04:05.000Z', second: '2026-01-02T03:04:05.000Z', self: '[Circular]' }) + }) + + it('without dedupe, writes a shared object every time', () => { + const out = createErrorSerializer()(retryError()) as { latest: unknown } + expect(out.latest).toMatchObject({ message: 'attempt 2 failed' }) + }) + + it('shapes what a transport receives when passed to createLogger as errorSerializer', async () => { + const { CallbackTransport, createLogger } = await import('./index') + const received: Record[] = [] + const transport = new CallbackTransport( + async ({ meta }) => void received.push(meta), + () => undefined, + ) + const logger = createLogger({ + consoleOptions: { silent: true }, + errorSerializer: createErrorSerializer({ omit: (key) => key === 'headers', dedupe: true }), + transports: [transport], + }) + logger.error('request failed', { error: retryError() }) + await transport.close!() + const error = received[0].error as { attempts: object[]; latest: unknown } + expect(error.attempts[0]).not.toHaveProperty('headers') + expect(error.latest).toBe('[Duplicate]') + }) +}) diff --git a/src/serialize-error.ts b/src/serialize-error.ts index 1e73fbd..1ee9ba3 100644 --- a/src/serialize-error.ts +++ b/src/serialize-error.ts @@ -8,6 +8,38 @@ import { serializesItself } from './serializes-itself' */ export type ErrorSerializer = (error: Error) => Record +export interface ErrorSerializerOptions { + /** + * Leaves a property out of an error. Called with the property name and the error that holds it, + * for every error the serializer reaches: the error itself, its `cause`, each entry of its + * `errors`, and any error held in a property. Return `true` to leave the property out. If it + * throws, the property is kept. + * + * An error is an `Error` instance, or an object with a string `name`, `message` and `stack`, such + * as an error already serialized elsewhere. It is not called for any other object. + * + * @example Leave response headers out of every error, at any depth + * ```ts + * createErrorSerializer({ omit: (key) => key === 'responseHeaders' }) + * ``` + */ + omit?: (key: string, error: Error) => boolean + + /** + * Writes an object that has already been written once in the same error as `'[Duplicate]'`, so + * an object two properties share appears once. The first property in key order keeps the object. + * Values written through their `toJSON`, such as a `Date`, are always written in full. + * Defaults to `false`. + */ + dedupe?: boolean +} + +interface WalkOptions { + omit: ErrorSerializerOptions['omit'] + /** Every object already written, when `dedupe` is on. */ + written: WeakSet | undefined +} + // Stops runaway recursion on pathological structures. 16 is well past anything that occurs in // realistic error trees; consumers who need deeper walks can supply a custom `errorSerializer`. const MAX_DEPTH = 16 @@ -43,7 +75,17 @@ const safeToJSON = (source: object): { ok: true; value: unknown } | { ok: false } } -const walk = (value: unknown, seen: WeakSet, depth: number): unknown => { +/** Calls `omit`. A throw keeps the property, so a faulty predicate cannot throw out of the log call. */ +const isOmitted = (options: WalkOptions, key: string, error: Error): boolean => { + if (!options.omit) return false + try { + return options.omit(key, error) === true + } catch { + return false + } +} + +const walk = (value: unknown, seen: WeakSet, depth: number, options: WalkOptions): unknown => { if (value === null || value === undefined) return value const type = typeof value if (type === 'bigint') return `${value as bigint}n` @@ -56,29 +98,36 @@ const walk = (value: unknown, seen: WeakSet, depth: number): unknown => if (seen.has(obj)) return '[Circular]' if (depth >= MAX_DEPTH) return '[Truncated]' + const errorLike = isErrorLike(obj) + // What `JSON.stringify` would have written: a `Date` becomes its ISO string (`null` when + // invalid) rather than `{}`. An error is never asked, so an error that defines `toJSON`, such as + // an `AxiosError`, is still captured whole below. + const json = !Array.isArray(obj) && !errorLike && serializesItself(obj) ? safeToJSON(obj) : undefined + + // A value written through its `toJSON` is what it returns, not a shared object, so it is never + // a duplicate. + if (!json?.ok && options.written) { + if (options.written.has(obj)) return '[Duplicate]' + options.written.add(obj) + } + seen.add(obj) try { - if (Array.isArray(obj)) return obj.map((entry) => walk(entry, seen, depth + 1)) - - // What `JSON.stringify` would have written: a `Date` becomes its ISO string (`null` when - // invalid) rather than `{}`. An error is never asked, so one that defines `toJSON` — an - // `AxiosError`, say — is still captured whole below. - if (!isErrorLike(obj) && serializesItself(obj)) { - const json = safeToJSON(obj) - if (json.ok) return walk(json.value, seen, depth + 1) - } + if (Array.isArray(obj)) return obj.map((entry) => walk(entry, seen, depth + 1, options)) + if (json?.ok) return walk(json.value, seen, depth + 1, options) const out: Record = {} for (const key of Object.keys(obj)) { + if (errorLike && isOmitted(options, key, obj)) continue const read = safeRead(obj, key) - if (read.ok) out[key] = walk(read.value, seen, depth + 1) + if (read.ok) out[key] = walk(read.value, seen, depth + 1, options) } - if (isErrorLike(obj)) { + if (errorLike) { for (const key of WELL_KNOWN_ERROR_PROPS) { - if (key in out) continue + if (key in out || isOmitted(options, key, obj)) continue const read = safeRead(obj, key) if (!read.ok || read.value === undefined || read.value === null) continue - out[key] = walk(read.value, seen, depth + 1) + out[key] = walk(read.value, seen, depth + 1, options) } } return out @@ -87,6 +136,30 @@ const walk = (value: unknown, seen: WeakSet, depth: number): unknown => } } +/** + * Builds an {@link ErrorSerializer} that works like {@link serializeError}, and can leave + * properties out of each error or write a shared object once. Pass the result as `createLogger`'s + * `errorSerializer`. + * + * @example Leave out response headers, and an error's `lastError` when its `errors` holds it + * ```ts + * createLogger({ + * errorSerializer: createErrorSerializer({ + * omit: (key, error) => key === 'responseHeaders' || (key === 'lastError' && 'errors' in error), + * }), + * }) + * ``` + */ +export const createErrorSerializer = + (options: ErrorSerializerOptions = {}): ErrorSerializer => + (error) => { + if (error === null || error === undefined || typeof error !== 'object') { + return { name: 'NonError', message: typeof error === 'function' ? '' : String(error) } + } + const walkOptions: WalkOptions = { omit: options.omit, written: options.dedupe ? new WeakSet() : undefined } + return walk(error, new WeakSet(), 0, walkOptions) as Record + } + /** * Serialize an `Error` (or any thrown value) into a plain, JSON-serializable object. * @@ -97,13 +170,10 @@ const walk = (value: unknown, seen: WeakSet, depth: number): unknown => * are stringified, functions are dropped, Buffers and streams render as sentinel strings, * and recursion is capped at a fixed depth (`'[Truncated]'`). Non-Error throws (strings, * numbers, etc.) are wrapped as `{ name: 'NonError', message: String(value) }`. + * + * Use {@link createErrorSerializer} to leave properties out or write shared objects once. */ -export const serializeError: ErrorSerializer = (error) => { - if (error === null || error === undefined || typeof error !== 'object') { - return { name: 'NonError', message: typeof error === 'function' ? '' : String(error) } - } - return walk(error, new WeakSet(), 0) as Record -} +export const serializeError: ErrorSerializer = createErrorSerializer() /** * Builds a JSON replacer that substitutes `Error` instances with the output of the supplied diff --git a/src/tests/winston-instrumentation.fixture.ts b/src/tests/winston-instrumentation.fixture.ts new file mode 100644 index 0000000..8d1c163 --- /dev/null +++ b/src/tests/winston-instrumentation.fixture.ts @@ -0,0 +1,53 @@ +/** + * Run in its own process by ../winston-instrumentation.spec.ts, because the instrumentation patches + * winston only when it is registered before winston loads. Set up as an app's tracing module is, + * then logs through `createLogger({ otel: true })` and prints what each side received as JSON. + */ +import { register } from 'node:module' +import { logs } from '@opentelemetry/api-logs' +import { WinstonInstrumentation } from '@opentelemetry/instrumentation-winston' +import { InMemoryLogRecordExporter, LoggerProvider, SimpleLogRecordProcessor } from '@opentelemetry/sdk-logs' + +const exporter = new InMemoryLogRecordExporter() +logs.setGlobalLoggerProvider(new LoggerProvider({ processors: [new SimpleLogRecordProcessor({ exporter })] })) +new WinstonInstrumentation() +// This package is ESM, so winston is loaded by `import`, which only this hook can patch. `include` +// limits the hook to winston, so it does not try to wrap this package's TypeScript source. +register('@opentelemetry/instrumentation/hook.mjs', import.meta.url, { data: { include: ['winston'] } }) + +// Loaded after the instrumentation, so winston loads after it too. +const { CallbackTransport, createLogger } = await import('../index') + +class ProviderError extends Error { + readonly name = 'ProviderError' + readonly statusCode = 413 +} + +const sibling: Record[] = [] +const logger = createLogger({ + otel: true, + consoleOptions: { silent: true }, + transports: [ + new CallbackTransport( + async ({ level, meta }) => void sibling.push({ level, ...meta }), + () => undefined, + ), + ], +}) + +logger.audit('audit line', { actor: 'user-1' }) +logger.error('error line', { error: new ProviderError('Request too large'), request: { route: '/chat' } }) +await new Promise((resolve) => setImmediate(resolve)) + +process.stdout.write( + JSON.stringify({ + transports: (logger as unknown as { transports: object[] }).transports.map((transport) => transport.constructor.name), + records: exporter.getFinishedLogRecords().map(({ body, severityNumber, severityText, attributes }) => ({ + body, + severityNumber, + severityText, + attributes, + })), + sibling, + }), +) diff --git a/src/winston-instrumentation.spec.ts b/src/winston-instrumentation.spec.ts new file mode 100644 index 0000000..5a0696f --- /dev/null +++ b/src/winston-instrumentation.spec.ts @@ -0,0 +1,51 @@ +/** + * The README's setup end to end: `WinstonInstrumentation` adds the OpenTelemetry transport to the + * logger, and `createLogger({ otel: true })` gives that transport the format. The fixture runs in its + * own process, because the instrumentation must be registered before winston loads. + */ +import { execFileSync } from 'node:child_process' +import { fileURLToPath } from 'node:url' +import { beforeAll, describe, expect, it } from 'vitest' + +interface Exported { + transports: string[] + records: { body: string; severityNumber: number; severityText: string; attributes: Record }[] + sibling: Record[] +} + +const fixture = fileURLToPath(new URL('./tests/winston-instrumentation.fixture.ts', import.meta.url)) + +let exported: Exported + +beforeAll(() => { + const stdout = execFileSync(process.execPath, ['--import', 'tsx', fixture], { encoding: 'utf8' }) + exported = JSON.parse(stdout) as Exported +}, 60_000) + +describe('createLogger({ otel: true }) with WinstonInstrumentation', () => { + it('finds the transport the instrumentation adds', () => { + expect(exported.transports).toContain('OpenTelemetryTransportV3') + }) + + it('exports an audit record at INFO severity, with logLevel audit', () => { + const audit = exported.records.find((record) => record.body === 'audit line') + expect(audit).toMatchObject({ severityNumber: 9, attributes: { actor: 'user-1', logLevel: 'audit' } }) + }) + + it('records the error as the exception, with the rest of it under errorDetail', () => { + const error = exported.records.find((record) => record.body === 'error line') + expect(error?.attributes).toMatchObject({ + 'exception.type': 'ProviderError', + 'exception.message': 'Request too large', + errorDetail: '{"statusCode":413}', + request: '{"route":"/chat"}', + }) + }) + + it('leaves other transports nested, at their own level', () => { + expect(exported.sibling).toEqual([ + { level: 'audit', actor: 'user-1' }, + expect.objectContaining({ level: 'error', error: expect.objectContaining({ statusCode: 413 }), request: { route: '/chat' } }), + ]) + }) +})