diff --git a/benchmark/logger/console-provider.js b/benchmark/logger/console-provider.js new file mode 100644 index 000000000000..499c17048589 --- /dev/null +++ b/benchmark/logger/console-provider.js @@ -0,0 +1,45 @@ +'use strict'; + +// End-to-end cost of logging through ConsoleProvider with the default JSON +// serializer. The provider's stream write() is replaced to avoid I/O latency. + +const common = require('../common.js'); + +const bench = common.createBenchmark(main, { + n: [5e5], + variant: ['json', 'flatten-pid', 'error'], +}, { + flags: ['--experimental-logger', '--no-warnings'], +}); + +function main({ n, variant }) { + const { ConsoleProvider, create } = require('node:logger'); + + const provider = new ConsoleProvider({ + flatten: variant === 'flatten-pid', + pid: variant === 'flatten-pid', + }); + let bytes = 0; + provider.stream.write = (data) => { + bytes += data.length; + return true; + }; + const logger = create(provider, { + name: 'bench', + bindings: { service: 'api' }, + }); + + if (variant === 'error') { + const err = new Error('boom'); + err.code = 'E_BOOM'; + bench.start(); + for (let i = 0; i < n; i++) logger.error('failed', { err }); + bench.end(n); + } else { + bench.start(); + for (let i = 0; i < n; i++) logger.info('hello', { i, user: 'x' }); + bench.end(n); + } + + if (bytes === 0) throw new Error('nothing was serialized'); +} diff --git a/benchmark/logger/creation.js b/benchmark/logger/creation.js new file mode 100644 index 000000000000..8823778c2db4 --- /dev/null +++ b/benchmark/logger/creation.js @@ -0,0 +1,34 @@ +'use strict'; + +// Cost of creating loggers and child loggers. + +const common = require('../common.js'); + +const bench = common.createBenchmark(main, { + n: [1e6], + type: ['create', 'child'], +}, { + flags: ['--experimental-logger', '--no-warnings'], +}); + +function main({ n, type }) { + const { ConsoleProvider, create } = require('node:logger'); + + const provider = new ConsoleProvider(); + const parent = create(provider, { name: 'bench' }); + const loggers = new Array(1024); + + if (type === 'child') { + bench.start(); + for (let i = 0; i < n; i++) { + loggers[i & 1023] = parent.child({ requestId: i }); + } + bench.end(n); + } else { + bench.start(); + for (let i = 0; i < n; i++) { + loggers[i & 1023] = create(provider, { name: 'bench' }); + } + bench.end(n); + } +} diff --git a/benchmark/logger/disabled.js b/benchmark/logger/disabled.js new file mode 100644 index 000000000000..db07a3a0606c --- /dev/null +++ b/benchmark/logger/disabled.js @@ -0,0 +1,36 @@ +'use strict'; + +// Calls to level methods for a level the provider has disabled. + +const common = require('../common.js'); + +const bench = common.createBenchmark(main, { + n: [1e8], + provider: ['console', 'custom'], + attributes: ['none', 'object'], + child: [0, 1], +}, { + flags: ['--experimental-logger', '--no-warnings'], +}); + +function main({ n, provider, attributes, child }) { + const { ConsoleProvider, create } = require('node:logger'); + + let logger = create(provider === 'console' ? + new ConsoleProvider({ level: 'info' }) : + { + isEnabled(level) { return level.value >= 30; }, + log() {}, + }); + if (child) logger = logger.child({ requestId: 1 }); + + if (attributes === 'object') { + bench.start(); + for (let i = 0; i < n; i++) logger.debug('hello', { i }); + bench.end(n); + } else { + bench.start(); + for (let i = 0; i < n; i++) logger.debug('hello'); + bench.end(n); + } +} diff --git a/benchmark/logger/enabled.js b/benchmark/logger/enabled.js new file mode 100644 index 000000000000..a4771ca39c15 --- /dev/null +++ b/benchmark/logger/enabled.js @@ -0,0 +1,50 @@ +'use strict'; + +// Cost of composing an enabled log event, with a provider that does no work. + +const common = require('../common.js'); + +const bench = common.createBenchmark(main, { + n: [1e6], + provider: ['minimal', 'custom'], + variant: ['no-attributes', 'attributes', 'function-binding'], +}, { + flags: ['--experimental-logger', '--no-warnings'], +}); + +function main({ n, provider, variant }) { + const { create } = require('node:logger'); + const { AsyncLocalStorage } = require('node:async_hooks'); + + let last; + const log = (event) => { last = event; }; + const als = new AsyncLocalStorage(); + const bindings = variant === 'function-binding' ? + { service: 'api', request: () => als.getStore() } : + { service: 'api' }; + const logger = create(provider === 'minimal' ? { log } : { + isEnabled(level) { return level.value >= 30; }, + log, + }, { name: 'bench', bindings }); + + switch (variant) { + case 'no-attributes': + bench.start(); + for (let i = 0; i < n; i++) logger.info('hello'); + bench.end(n); + break; + case 'attributes': + bench.start(); + for (let i = 0; i < n; i++) logger.info('hello', { i, user: 'x' }); + bench.end(n); + break; + case 'function-binding': + als.enterWith(1); + bench.start(); + for (let i = 0; i < n; i++) logger.info('hello', { i }); + bench.end(n); + break; + } + + if (last === undefined) throw new Error('no event was logged'); +} diff --git a/benchmark/logger/request.js b/benchmark/logger/request.js new file mode 100644 index 000000000000..75f627b9ab9c --- /dev/null +++ b/benchmark/logger/request.js @@ -0,0 +1,43 @@ +'use strict'; + +// A child logger per request, logging a few lines through ConsoleProvider. +// The provider's stream write() is replaced to avoid I/O latency. + +const common = require('../common.js'); + +const bench = common.createBenchmark(main, { + n: [5e5], + lines: [0, 1, 3], + level: ['info', 'debug'], +}, { + flags: ['--experimental-logger', '--no-warnings'], +}); + +function main({ n, lines, level }) { + const { ConsoleProvider, create } = require('node:logger'); + + // With level 'debug' the lines are disabled (the provider is at 'info'). + const provider = new ConsoleProvider({ level: 'info' }); + let bytes = 0; + provider.stream.write = (data) => { + bytes += data.length; + return true; + }; + const logger = create(provider, { + name: 'bench', + bindings: { service: 'api' }, + }); + + bench.start(); + for (let i = 0; i < n; i++) { + const child = logger.child({ requestId: i }); + for (let j = 0; j < lines; j++) { + child[level]('handled', { step: j }); + } + } + bench.end(n); + + if (lines > 0 && level === 'info' && bytes === 0) { + throw new Error('nothing was serialized'); + } +} diff --git a/doc/api/cli.md b/doc/api/cli.md index b57714a0bfa2..e8fe47010d6a 100644 --- a/doc/api/cli.md +++ b/doc/api/cli.md @@ -1545,6 +1545,16 @@ Specify the `module` containing exported [asynchronous module customization hook This feature requires `--allow-worker` if used with the [Permission Model][]. +### `--experimental-logger` + + + +> Stability: 1.1 - Active development + +Enable the experimental [`node:logger`][] module. + ### `--experimental-network-inspection` + + + +> Stability: 1.1 - Active development + + + +The `node:logger` module provides a structured logging facade. A logger composes +log events and passes them to a provider. Providers control filtering, encoding, +buffering, and output. + +```mjs +import create from 'node:logger'; + +const logger = create({ name: 'example' }); +logger.info('server started', { port: 3000 }); +``` + +```cjs +const create = require('node:logger'); + +const logger = create({ name: 'example' }); +logger.info('server started', { port: 3000 }); +``` + +The module is only available under the `node:` scheme, and only when Node.js is +started with the [`--experimental-logger`][] flag. + +## Log events + +Providers receive a log event with the following properties: + +* `timestamp` {number} Milliseconds since the Unix epoch. +* `level` {Object} + * `name` {string} The level name. + * `value` {number} The numeric level value. Larger values are more severe. +* `name` {string|undefined} The logger name. +* `message` {any} The log message value. +* `bindings` {Object} Attributes associated with the logger and its parents. +* `attributes` {Object} Attributes supplied for this event. + +A new event object is created for each log call and is not frozen. The +`attributes` object is a shallow copy of the attributes supplied for the event +and is not frozen. Built-in levels and the logger's bindings are shared between +events and are shallowly frozen. When a direct value of the bindings is a +function, `bindings` is instead a new, unfrozen copy. The message value is +retained as provided and is not cloned or frozen. Nested values are not cloned +or frozen. Providers should treat the entire event as read-only, since an +[`AggregateProvider`][] passes the same event to each of its providers, and +must copy nested values before retaining or modifying them asynchronously. + +If a direct value of `bindings` or `attributes` is a function, the logger invokes +it for every event and replaces it in the event with the returned value. Nested +functions are not invoked. + +## `logger.getDefaultProvider()` + + + +* Returns: {Object} + +Returns the provider used when a logger is created without an explicit provider. +Until set, the first call or logger creation lazily creates a +[`ConsoleProvider`][]. The same default provider is reused by subsequent loggers. + +## `logger.setDefaultProvider(provider)` + + + +* `provider` {Object} The provider to use by default. + +Sets the provider used when a logger is created without an explicit provider. +Existing loggers retain their provider. + +```cjs +const create = require('node:logger'); + +create.setDefaultProvider(new create.EventProvider()); +const logger = create(); +``` + +When `provider` differs from the current default, the process emits the +[`'defaultLoggerProviderChanged'`][] event with `provider` and the current +default provider. This event allows an application to detect when a dependency +changes the default provider. If the application does not wish to allow the +default provider to be changed, it can throw an error synchronously which will +be propagated up to the code that called `setDefaultProvider()`. + +## `logger.create([provider][, options])` + + + +* `provider` {Object} The provider that receives log events. **Default:** + The value returned by [`logger.getDefaultProvider()`][]. +* `options` {Object} + * `name` {string} The logger name. + * `bindings` {Object} Attributes included in every event from the logger. + **Default:** `{}`. +* Returns: {Logger} + +Creates a logger. If the first argument does not implement the provider +contract, it is treated as `options`. + +```cjs +const { create, EventProvider } = require('node:logger'); + +const defaultLogger = create(); + +const provider = new EventProvider(); +provider.on('log', (event) => { + // Handle the structured event. +}); +const eventLogger = create(provider, { + name: 'api', + bindings: { service: 'users' }, +}); +``` + +## Provider contract + +A provider is an object with a synchronous `log(event, context)` method. It may also +implement `isEnabled(level, context)` to prevent events from being composed: + +```cjs +class CustomProvider { + isEnabled(level, context) { + return level.value >= 30; + } + + log(event, context) { + // Handle the structured event. + } +} +``` + +The `level` passed to `isEnabled()` is a level descriptor, which is frozen for +built-in levels. The same `context` object is passed to both methods for every +event from a logger and contains the logger's `name` and `bindings`. Providers +should not modify it. Only an exact `false` return value disables the event. A +provider without `isEnabled()` receives every event. + +Provider methods run synchronously in the logging call. Exceptions propagate to +the caller. A provider that performs asynchronous work must enqueue or copy the +event synchronously. + +## Class: `Logger` + + + +### `new Logger([provider][, options])` + + + +* `provider` {Object} The provider that receives log events. **Default:** + The value returned by [`logger.getDefaultProvider()`][]. +* `options` {Object} + * `name` {string} The logger name. + * `bindings` {Object} Attributes included in every event from the logger. + +Equivalent to [`logger.create()`][]. + +### `logger.provider` + + + +* {Object} + +The provider used by the logger. The property is read-only. + +### `logger.name` + + + +* {string|undefined} + +The logger name. + +### `logger.bindings` + + + +* {Object} + +The shallowly frozen bindings associated with the logger. + +### `logger.trace(message[, attributes])` + +### `logger.debug(message[, attributes])` + +### `logger.info(message[, attributes])` + +### `logger.warn(message[, attributes])` + +### `logger.error(message[, attributes])` + +### `logger.fatal(message[, attributes])` + + + +* `message` {any} The log message value. +* `attributes` {Object} Attributes associated with this event. **Default:** `{}`. + +Creates a structured event at the corresponding level and passes it to the +provider if the provider enables that level. + +When the provider is a [`ConsoleProvider`][], an [`EventProvider`][], or an +[`AggregateProvider`][] made up only of those providers and providers without +`isEnabled()`, these methods are resolved when the logger is created and again +whenever a provider's `level` changes. Methods for disabled levels are then a +shared no-op function, so calling them does not consult the provider. The +JavaScript engine can usually optimize such calls away entirely. Because of +this, methods for disabled levels do not validate their receiver or arguments. +For other providers, including providers that override `isEnabled()`, each call +checks `isEnabled()`. + +```cjs +const { ConsoleProvider, create } = require('node:logger'); + +const provider = new ConsoleProvider({ level: 'info' }); +const logger = create(provider); +logger.debug('not logged'); // No-op. +provider.level = 'debug'; +logger.debug('logged'); +``` + +```cjs +logger.info('request completed', { + method: 'GET', + statusCode: 200, +}); +``` + +### `logger.log(level, message[, attributes])` + + + +* `level` {string|Object} A built-in level name or an object containing a + `name` {string} and integer `value` {number}. +* `message` {any} The log message value. +* `attributes` {Object} Attributes associated with this event. **Default:** `{}`. + +Creates an event at a built-in or custom level. + +```cjs +logger.log({ name: 'notice', value: 35 }, 'configuration reloaded'); +``` + +### `logger.isEnabled(level)` + + + +* `level` {string|Object} A built-in level name or custom level descriptor. +* Returns: {boolean} + +Returns whether the provider enables the level for this logger. + +### `logger.child(bindings[, options])` + + + +* `bindings` {Object} Additional logger bindings. +* `options` {Object} + * `name` {string} A name for the child. **Default:** The parent logger's name. +* Returns: {Logger} + +Creates a logger that uses the same provider and adds to the parent's bindings. +Child bindings with the same key replace parent bindings. + +## Class: `AggregateProvider` + + + +The `AggregateProvider` delivers log events to a fixed list of providers. It +enables an event when at least one provider enables it. Each provider's +`isEnabled()` method is checked again immediately before delivery, and a +provider that returns `false` does not receive the event. Providers are called +in list order. Exceptions propagate immediately and prevent later providers +from being called. + +### `new AggregateProvider(providers)` + + + +* `providers` {Object\[]} The providers that receive log events. + +The array may be empty. The providers are copied and validated during +construction. Duplicate and nested aggregate providers are supported. + +### `aggregateProvider.providers` + + + +* {Object\[]} + +The frozen provider list. The provider objects themselves are not frozen. + +## Class: `ConsoleProvider` + + + +The `ConsoleProvider` serializes each event and writes it followed by a newline +using [`fs.Utf8Stream`][]. Events are serialized as JSON by default. + +### `new ConsoleProvider([options])` + + + +* `options` {Object} + * `destination` {string} Either `'stdout'` or `'stderr'`. **Default:** + `'stdout'`. + * `flatten` {boolean} Whether to copy bindings and attributes into the + top-level serialized record. **Default:** `false`. + * `level` {string|Object} The minimum enabled level. **Default:** `'info'`. + * `maxLength` {number} The maximum internal buffer length. Writes that would + exceed this value are dropped. **Default:** `0`, for no limit. + * `minLength` {number} The minimum internal buffer length before an automatic + flush. **Default:** `0`. + * `periodicFlush` {number} The interval in milliseconds at which the stream + is flushed. **Default:** `0`, for no periodic flush. + * `pid` {boolean} Whether to add the process ID as a top-level `pid` property + to serialized records. **Default:** `false`. + * `serializer` {Function} A function that receives a log record and returns + a string. **Default:** A JSON serializer. + * `sync` {boolean} Whether writes are synchronous. **Default:** `false`. + +When `flatten` is `true`, bindings are copied into the top-level record first, +followed by attributes. Attributes therefore replace bindings with the same +property name. The level descriptor is emitted as a numeric `level` property and +a string `levelName` property. The `level`, `levelName`, `message`, `name`, and +`timestamp` event properties, along with `pid` when enabled, take precedence +over both. The original `bindings` and `attributes` containers are not included +in the record. + +The default serializer follows [`JSON.stringify()`][] semantics, including +calling `toJSON()` methods, with these additions: + +* `BigInt` values are serialized as decimal strings. +* `Error` objects include their `name`, `message`, and `stack`, along with + `code`, `cause`, `errors`, and enumerable properties when present. +* Circular references are serialized as the string `'[Circular]'`. + +Values that [`JSON.stringify()`][] normally omits, such as `undefined`, +functions, and symbols used as object properties, are still omitted. + +[`util.inspect()`][] can be used when JavaScript-style diagnostic output is +preferred over JSON: + +```cjs +const { ConsoleProvider, create } = require('node:logger'); +const { inspect } = require('node:util'); + +const logger = create(new ConsoleProvider({ serializer: inspect })); +logger.info('started', { processId: 1n }); +``` + +### `consoleProvider.destination` + + + +* {string} + +The configured destination. + +### `consoleProvider.flatten` + + + +* {boolean} + +Whether bindings and attributes are flattened into the serialized record. + +### `consoleProvider.level` + + + +* {Object} + +The minimum level descriptor. Set this property to a built-in level name or a +custom level descriptor to update the minimum level. + +### `consoleProvider.pid` + + + +* {boolean} + +Whether serialized records include the process ID. + +### `consoleProvider.serializer` + + + +* {Function} + +The configured serializer. + +### `consoleProvider.stream` + + + +* {fs.Utf8Stream} + +The underlying stream. Its `'drop'` event reports records dropped because of +`maxLength`. + +### `consoleProvider.flush([callback])` + + + +* `callback` {Function} Called when pending writes have completed. + +Flushes pending writes. + +### `consoleProvider.flushSync()` + + + +Synchronously flushes pending writes. An `ERR_INVALID_STATE` error is thrown if +the provider's stream is currently writing. + +## Class: `DiagnosticsProvider` + + + +The `DiagnosticsProvider` publishes enabled log events to +[`diagnostics_channel`][] channels. Events are only enabled for channels that +have subscribers. + +### `new DiagnosticsProvider(channels)` + + + +* `channels` {Object|Function} A channel mapping or routing function. + +When `channels` is an object, each own string or symbol property is a channel +name and its value is a selector function that receives a level descriptor. The +event is published to every subscribed channel whose selector returns a truthy +value. + +When `channels` is a function, it receives a level descriptor and returns the +string or symbol name of the channel to publish to. Returning `undefined` +disables the event. The selected channel must have subscribers for the event to +be enabled. + +`DiagnosticsProvider.isEnabled()` invokes the routing function to resolve its +channel. For a channel mapping, it invokes selectors only for channels that +currently have subscribers and stops after the first matching selector. When an +event is enabled, the applicable routing function or selectors are invoked +again immediately before publishing it. These functions must not rely on being +called exactly once. + +```cjs +const { DiagnosticsProvider, create, levels } = require('node:logger'); + +const provider = new DiagnosticsProvider({ + 'application:log': () => true, + 'application:error': (level) => level.value >= levels.error.value, +}); +const logger = create(provider); +``` + +## Class: `EventProvider` + + + +* Extends: {EventEmitter} + +For each enabled log event, the `EventProvider` first checks for listeners whose +event name exactly matches the level name. If any exist, it emits the event using +the level name. Otherwise, it emits a `'log'` event. Event selection is based +only on the level name, not its numeric value. The provider does not buffer log +events, so events emitted without a matching or fallback listener are discarded. + +### `new EventProvider([options])` + + + +* `options` {Object} + * `level` {string|Object} The minimum enabled level. **Default:** `'trace'`. + +### Event: `''` + + + +* `event` {Object} The structured log event. + +Emitted synchronously when the provider has a listener for the exact level name. +This event takes precedence over the `'log'` event. + +```mjs +import { create, EventProvider } from 'node:logger'; + +const ep = new EventProvider(); + +ep.on('warn', (event) => { + // Receives all warn logs +}); + +ep.on('log', (event) => { + // Receives all other logs +}); + +const logger = create(ep); +logger.warn('warning!'); +logger.info('info!'); +``` + +### Event: `'log'` + + + +* `event` {Object} The structured log event. + +Emitted synchronously when the provider has no listener for the event's level +name. + +### `eventProvider.level` + + + +* {Object} + +The minimum level descriptor. Set this property to a built-in level name or a +custom level descriptor to update the minimum level. + +## `logger.levels` + + + +* {Object} + +Immutable descriptors for the built-in levels: + +| Name | Value | +| ------- | ----: | +| `trace` | 10 | +| `debug` | 20 | +| `info` | 30 | +| `warn` | 40 | +| `error` | 50 | +| `fatal` | 60 | + +[`'defaultLoggerProviderChanged'`]: process.md#event-defaultloggerproviderchanged +[`--experimental-logger`]: cli.md#--experimental-logger +[`AggregateProvider`]: #class-aggregateprovider +[`ConsoleProvider`]: #class-consoleprovider +[`EventProvider`]: #class-eventprovider +[`JSON.stringify()`]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify +[`diagnostics_channel`]: diagnostics_channel.md +[`fs.Utf8Stream`]: fs.md#class-fsutf8stream +[`logger.create()`]: #loggercreateprovider-options +[`logger.getDefaultProvider()`]: #loggergetdefaultprovider +[`util.inspect()`]: util.md#utilinspectobject-options diff --git a/doc/api/process.md b/doc/api/process.md index 8b210a1e7c06..6fd4b53701eb 100644 --- a/doc/api/process.md +++ b/doc/api/process.md @@ -80,6 +80,20 @@ console.log('This message is displayed first.'); // Process exit event with code: 0 ``` +### Event: `'defaultLoggerProviderChanged'` + + + +* `provider` {Object} The new default logger provider. +* `defaultProvider` {Object|undefined} The default logger provider at the time + the event is emitted. + +The `'defaultLoggerProviderChanged'` event is emitted synchronously when +[`logger.setDefaultProvider()`][] is called with a provider that differs from +the current default provider. + ### Event: `'disconnect'`