From f04ec12d66ddd4abfbb6bd2620ae8d664e0d049f Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sun, 6 Sep 2026 06:42:45 +0000 Subject: [PATCH] lib: implement node:logger A simpler attempt to add a structured logging API. Uses a provider model similar to VFS. This implements two providers out of the box, ConsoleProvider and ReadableProvider. ConsoleProvider is the default and uses Utf8Stream to emit to either stdout or stderr. ```js const { create } = require('node:logger'); const logger = create(); // default logger to console logger.info('foo'); // ... const als = new AsyncLocalStorage(); const logger2 = create(new ConsoleProvider({ pid: true }), { name: 'foo', bindings: { 'abc': 'included in every log line', 'xyz': als, // current als.getStore() included in // every log line } }); logger2.info('foo', { baz: 1 }); ``` The `Logger` keeps things as simple as possible, leaving actual handling of the log events to the providers, which can be fully customized. Easy to adapt to other loggers like pino or extend capabilities without directly touching the facade. Signed-off-by: James M Snell Assisted-by: Opencode --- doc/api/index.md | 1 + doc/api/logger.md | 409 ++++++++++++++++++ lib/internal/bootstrap/realm.js | 1 + lib/logger.js | 408 +++++++++++++++++ .../test-module-hooks-builtin-require.js | 1 + .../test-module-hooks-load-builtin-require.js | 1 + test/parallel/test-logger-console-provider.js | 140 ++++++ test/parallel/test-logger.js | 223 ++++++++++ 8 files changed, 1184 insertions(+) create mode 100644 doc/api/logger.md create mode 100644 lib/logger.js create mode 100644 test/parallel/test-logger-console-provider.js create mode 100644 test/parallel/test-logger.js diff --git a/doc/api/index.md b/doc/api/index.md index a30724c064e1..b3533dbd9f2e 100644 --- a/doc/api/index.md +++ b/doc/api/index.md @@ -36,6 +36,7 @@ * [Inspector](inspector.md) * [Internationalization](intl.md) * [Iterable Streams API](stream_iter.md) +* [Logger](logger.md) * [Modules: CommonJS modules](modules.md) * [Modules: ECMAScript modules](esm.md) * [Modules: `node:module` API](module.md) diff --git a/doc/api/logger.md b/doc/api/logger.md new file mode 100644 index 000000000000..1c182edea305 --- /dev/null +++ b/doc/api/logger.md @@ -0,0 +1,409 @@ +# Logger + + + + + +> 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 can only be imported using the `node:` scheme. + +## 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` {string} The log message. +* `bindings` {Object} Attributes associated with the logger and its parents. +* `attributes` {Object} Attributes supplied for this event. + +The event, level, bindings, and attributes objects are shallowly frozen. Nested +values are not cloned or frozen. Providers must treat the entire event as +read-only and must copy nested values before retaining or modifying them +asynchronously. + +If a direct value of `bindings` or `attributes` is an +[`AsyncLocalStorage`][] instance, the logger replaces it in the event with the +value returned by `asyncLocalStorage.getStore()`. Bound instances are evaluated +for every event, allowing a logger to include the store for the current async +context. Nested `AsyncLocalStorage` instances are not resolved. + +## `logger.create([provider][, options])` + + + +* `provider` {Object} The provider that receives log events. **Default:** A new + [`ConsoleProvider`][]. +* `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, ReadableProvider } = require('node:logger'); + +const defaultLogger = create(); + +const events = new ReadableProvider(); +const streamLogger = create(events, { + name: 'api', + bindings: { service: 'users' }, +}); +``` + +Each call without an explicit provider creates a distinct default provider. + +## Provider contract + +A provider is an object with a synchronous `log(event)` 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) { + // Handle the structured event. + } +} +``` + +The `level` passed to `isEnabled()` is an immutable level descriptor. `context` +contains the logger's `name` and `bindings`. 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:** A new + [`ConsoleProvider`][]. +* `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` {string} The log message. +* `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. + +```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` {string} The log message. +* `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: `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'`. + * `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 event and returns a + string. **Default:** [`JSON.stringify()`][]. + * `sync` {boolean} Whether writes are synchronous. **Default:** `false`. + +[`util.inspect()`][] can be used to serialize values that JSON does not support, +including circular references and `BigInt` values: + +```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.level` + + + +* {Object} + +The minimum level descriptor. + +### `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. + +## Class: `ReadableProvider` + + + +* Extends: {stream.Readable} + +An object-mode [`stream.Readable`][] that emits each enabled log event as a +chunk. + +### `new ReadableProvider([options])` + + + +* `options` {Object} + * `level` {string|Object} The minimum enabled level. **Default:** `'trace'`. + * `highWaterMark` {number} The readable stream high water mark. + +### `readableProvider.level` + + + +* {Object} + +The minimum level descriptor. + +### `readableProvider.close()` + + + +Ends the readable stream. Loggers using the provider stop composing events. + +## `logger.levels` + + + +* {Object} + +Immutable descriptors for the built-in levels: + +| Name | Value | +| ------- | ----: | +| `trace` | 10 | +| `debug` | 20 | +| `info` | 30 | +| `warn` | 40 | +| `error` | 50 | +| `fatal` | 60 | + +[`AsyncLocalStorage`]: async_context.md#class-asynclocalstorage +[`ConsoleProvider`]: #class-consoleprovider +[`JSON.stringify()`]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify +[`fs.Utf8Stream`]: fs.md#class-fsutf8stream +[`logger.create()`]: #loggercreateprovider-options +[`stream.Readable`]: stream.md#class-streamreadable +[`util.inspect()`]: util.md#utilinspectobject-options diff --git a/lib/internal/bootstrap/realm.js b/lib/internal/bootstrap/realm.js index 81ac2a0e398e..2ab1714f6eac 100644 --- a/lib/internal/bootstrap/realm.js +++ b/lib/internal/bootstrap/realm.js @@ -128,6 +128,7 @@ const schemelessBlockList = new SafeSet([ 'bench/reporters', 'dtls', 'ffi', + 'logger', 'sea', 'sqlite', 'quic', diff --git a/lib/logger.js b/lib/logger.js new file mode 100644 index 000000000000..01b9110f8cb2 --- /dev/null +++ b/lib/logger.js @@ -0,0 +1,408 @@ +'use strict'; + +const { + DateNow, + FunctionPrototypeCall, + FunctionPrototypeSymbolHasInstance, + JSONStringify, + ObjectAssign, + ObjectFreeze, + ObjectKeys, + ReflectOwnKeys, +} = primordials; + +const { + codes: { + ERR_INVALID_ARG_TYPE, + ERR_INVALID_RETURN_VALUE, + }, +} = require('internal/errors'); +const { + validateBoolean, + validateFunction, + validateInteger, + validateObject, + validateOneOf, + validateString, +} = require('internal/validators'); +const { emitExperimentalWarning, kEmptyObject } = require('internal/util'); +const Utf8Stream = require('internal/streams/fast-utf8-stream'); +const Readable = require('internal/streams/readable'); +const { AsyncLocalStorage } = require('async_hooks'); + +const kDestinations = ['stdout', 'stderr']; +const kEmptyAttributes = ObjectFreeze({ __proto__: null }); +const kEmptyBindings = ObjectFreeze({ __proto__: null }); + +function createLevel(name, value) { + return ObjectFreeze({ __proto__: null, name, value }); +} + +const levels = ObjectFreeze({ + __proto__: null, + trace: createLevel('trace', 10), + debug: createLevel('debug', 20), + info: createLevel('info', 30), + warn: createLevel('warn', 40), + error: createLevel('error', 50), + fatal: createLevel('fatal', 60), +}); +const kLevelNames = ObjectKeys(levels); + +function normalizeLevel(level, name = 'level') { + if (typeof level === 'string') { + validateOneOf(level, name, kLevelNames); + return levels[level]; + } + + validateObject(level, name); + const { name: levelName, value } = level; + validateString(levelName, `${name}.name`); + validateInteger(value, `${name}.value`); + return createLevel(levelName, value); +} + +function isAsyncLocalStorage(value) { + return value !== null && typeof value === 'object' && + FunctionPrototypeSymbolHasInstance(AsyncLocalStorage, value); +} + +function copyObject(value, resolveStores = false) { + const copy = ObjectAssign({ __proto__: null }, value); + if (resolveStores) { + const keys = ReflectOwnKeys(copy); + for (let i = 0; i < keys.length; i++) { + const key = keys[i]; + const entry = copy[key]; + if (isAsyncLocalStorage(entry)) { + copy[key] = FunctionPrototypeCall(entry.getStore, entry); + } + } + } + return ObjectFreeze(copy); +} + +function hasAsyncLocalStorage(value) { + const keys = ReflectOwnKeys(value); + for (let i = 0; i < keys.length; i++) { + if (isAsyncLocalStorage(value[keys[i]])) { + return true; + } + } + return false; +} + +function isProvider(value) { + return value !== null && + (typeof value === 'object' || typeof value === 'function') && + typeof value.log === 'function'; +} + +function validateProvider(provider) { + if (provider === null || + (typeof provider !== 'object' && typeof provider !== 'function')) { + throw new ERR_INVALID_ARG_TYPE('provider', 'Provider', provider); + } + + validateFunction(provider.log, 'provider.log'); + if (provider.isEnabled !== undefined) { + validateFunction(provider.isEnabled, 'provider.isEnabled'); + } +} + +/** + * A provider that writes newline-delimited JSON to stdout or stderr. + */ +class ConsoleProvider { + #destination; + #level; + #pid; + #serializer; + #stream; + + constructor(options = kEmptyObject) { + validateObject(options, 'options'); + const { + destination = 'stdout', + level = 'info', + maxLength, + minLength, + periodicFlush, + pid = false, + serializer = JSONStringify, + sync, + } = options; + + validateOneOf(destination, 'options.destination', kDestinations); + validateBoolean(pid, 'options.pid'); + validateFunction(serializer, 'options.serializer'); + this.#destination = destination; + this.#level = normalizeLevel(level, 'options.level'); + this.#pid = pid; + this.#serializer = serializer; + this.#stream = new Utf8Stream({ + __proto__: null, + fd: destination === 'stdout' ? 1 : 2, + maxLength, + minLength, + periodicFlush, + sync, + }); + } + + get destination() { + return this.#destination; + } + + get level() { + return this.#level; + } + + get pid() { + return this.#pid; + } + + get serializer() { + return this.#serializer; + } + + get stream() { + return this.#stream; + } + + isEnabled(level) { + return level.value >= this.#level.value; + } + + log(event) { + if (this.isEnabled(event.level)) { + const record = this.#pid ? ObjectFreeze(ObjectAssign( + { __proto__: null }, + event, + { __proto__: null, pid: process.pid }, + )) : event; + const serialized = FunctionPrototypeCall( + this.#serializer, + undefined, + record, + ); + if (typeof serialized !== 'string') { + throw new ERR_INVALID_RETURN_VALUE( + 'a string', + 'serializer', + serialized, + ); + } + this.#stream.write(`${serialized}\n`); + } + } + + flush(callback) { + this.#stream.flush(callback); + } + + flushSync() { + this.#stream.flushSync(); + } +} + +/** + * An object-mode Readable that receives structured log events. + */ +class ReadableProvider extends Readable { + #closed = false; + #level; + + constructor(options = kEmptyObject) { + validateObject(options, 'options'); + const { + highWaterMark, + level = 'trace', + } = options; + const normalizedLevel = normalizeLevel(level, 'options.level'); + + super({ + __proto__: null, + highWaterMark, + objectMode: true, + }); + this.#level = normalizedLevel; + } + + get level() { + return this.#level; + } + + isEnabled(level) { + return !this.#closed && !this.destroyed && + level.value >= this.#level.value; + } + + log(event) { + if (this.isEnabled(event.level)) { + this.push(event); + } + } + + close() { + if (!this.#closed) { + this.#closed = true; + this.push(null); + } + } + + _read() {} +} + +class Logger { + #bindings; + #context; + #hasAsyncLocalStorage; + #name; + #provider; + + constructor(providerOrOptions, options) { + emitExperimentalWarning('Logger'); + + let provider = providerOrOptions; + if (provider === undefined || provider === null) { + provider = new ConsoleProvider(); + } else if (options === undefined && + typeof provider === 'object' && + !isProvider(provider)) { + options = provider; + provider = new ConsoleProvider(); + } + + options ??= kEmptyObject; + validateProvider(provider); + validateObject(options, 'options'); + + const { + bindings = kEmptyBindings, + name, + } = options; + validateObject(bindings, 'options.bindings'); + if (name !== undefined) { + validateString(name, 'options.name'); + } + + this.#provider = provider; + this.#name = name; + this.#bindings = copyObject(bindings); + this.#hasAsyncLocalStorage = hasAsyncLocalStorage(this.#bindings); + this.#context = ObjectFreeze({ + __proto__: null, + bindings: this.#bindings, + name: this.#name, + }); + } + + get provider() { + return this.#provider; + } + + get name() { + return this.#name; + } + + get bindings() { + return this.#bindings; + } + + isEnabled(level) { + return this.#isEnabled(normalizeLevel(level)); + } + + log(level, message, attributes = kEmptyAttributes) { + this.#log(normalizeLevel(level), message, attributes); + } + + trace(message, attributes = kEmptyAttributes) { + this.#log(levels.trace, message, attributes); + } + + debug(message, attributes = kEmptyAttributes) { + this.#log(levels.debug, message, attributes); + } + + info(message, attributes = kEmptyAttributes) { + this.#log(levels.info, message, attributes); + } + + warn(message, attributes = kEmptyAttributes) { + this.#log(levels.warn, message, attributes); + } + + error(message, attributes = kEmptyAttributes) { + this.#log(levels.error, message, attributes); + } + + fatal(message, attributes = kEmptyAttributes) { + this.#log(levels.fatal, message, attributes); + } + + child(bindings, options = kEmptyObject) { + validateObject(bindings, 'bindings'); + validateObject(options, 'options'); + + const { name = this.#name } = options; + if (name !== undefined) { + validateString(name, 'options.name'); + } + + return new Logger(this.#provider, { + __proto__: null, + bindings: ObjectAssign({ __proto__: null }, this.#bindings, bindings), + name, + }); + } + + #isEnabled(level) { + if (this.#provider.isEnabled === undefined) { + return true; + } + return FunctionPrototypeCall( + this.#provider.isEnabled, + this.#provider, + level, + this.#context, + ) !== false; + } + + #log(level, message, attributes) { + if (!this.#isEnabled(level)) { + return; + } + + validateString(message, 'message'); + validateObject(attributes, 'attributes'); + + const event = ObjectFreeze({ + __proto__: null, + attributes: attributes === kEmptyAttributes ? + attributes : copyObject(attributes, true), + bindings: this.#hasAsyncLocalStorage ? + copyObject(this.#bindings, true) : this.#bindings, + level, + message, + name: this.#name, + timestamp: DateNow(), + }); + + FunctionPrototypeCall(this.#provider.log, this.#provider, event); + } +} + +function create(provider, options) { + return new Logger(provider, options); +} + +module.exports = { + __proto__: null, + ConsoleProvider, + Logger, + ReadableProvider, + create, + levels, +}; diff --git a/test/module-hooks/test-module-hooks-builtin-require.js b/test/module-hooks/test-module-hooks-builtin-require.js index e1e137ce1169..3c973e53d641 100644 --- a/test/module-hooks/test-module-hooks-builtin-require.js +++ b/test/module-hooks/test-module-hooks-builtin-require.js @@ -13,6 +13,7 @@ const { registerHooks } = require('module'); const schemelessBlockList = new Set([ 'bench', 'bench/reporters', + 'logger', 'sea', 'test', 'test/reporters', diff --git a/test/module-hooks/test-module-hooks-load-builtin-require.js b/test/module-hooks/test-module-hooks-load-builtin-require.js index 946fc1e48766..00c5678afbe1 100644 --- a/test/module-hooks/test-module-hooks-load-builtin-require.js +++ b/test/module-hooks/test-module-hooks-load-builtin-require.js @@ -37,6 +37,7 @@ hook.deregister(); const schemelessBlockList = new Set([ 'bench', 'bench/reporters', + 'logger', 'sea', 'test', 'test/reporters', diff --git a/test/parallel/test-logger-console-provider.js b/test/parallel/test-logger-console-provider.js new file mode 100644 index 000000000000..65e166998961 --- /dev/null +++ b/test/parallel/test-logger-console-provider.js @@ -0,0 +1,140 @@ +'use strict'; + +require('../common'); +const assert = require('node:assert'); +const { spawnSync } = require('node:child_process'); +const { ConsoleProvider } = require('node:logger'); +const { inspect } = require('node:util'); + +function run(destination, level, statement) { + const script = ` + const { ConsoleProvider, create } = require('node:logger'); + const provider = new ConsoleProvider({ + destination: ${JSON.stringify(destination)}, + level: ${JSON.stringify(level)}, + sync: true, + }); + const logger = create(provider, { + name: 'example', + bindings: { service: 'api' }, + }); + ${statement} + provider.flushSync(); + `; + + return spawnSync(process.execPath, ['--no-warnings', '-e', script], { + encoding: 'utf8', + }); +} + +{ + const result = run( + 'stdout', + 'debug', + "logger.trace('filtered'); logger.info('started', { port: 3000 });", + ); + + assert.strictEqual(result.status, 0); + assert.strictEqual(result.stderr, ''); + const event = JSON.parse(result.stdout); + assert.strictEqual(event.message, 'started'); + assert.strictEqual(event.name, 'example'); + assert.deepStrictEqual(event.level, { name: 'info', value: 30 }); + assert.deepStrictEqual(event.bindings, { service: 'api' }); + assert.deepStrictEqual(event.attributes, { port: 3000 }); + assert.strictEqual(typeof event.timestamp, 'number'); + assert.strictEqual('pid' in event, false); +} + +{ + const script = ` + const { ConsoleProvider, create } = require('node:logger'); + const provider = new ConsoleProvider({ pid: true, sync: true }); + const logger = create(provider); + logger.info('with pid'); + provider.flushSync(); + `; + const result = spawnSync(process.execPath, [ + '--no-warnings', + '-e', + script, + ], { encoding: 'utf8' }); + + assert.strictEqual(result.status, 0); + assert.strictEqual(result.stderr, ''); + const event = JSON.parse(result.stdout); + assert.strictEqual(event.message, 'with pid'); + assert.ok(Number.isInteger(event.pid)); + assert.ok(event.pid > 0); +} + +{ + const result = run( + 'stderr', + 'error', + "logger.warn('filtered'); logger.error('failed');", + ); + + assert.strictEqual(result.status, 0); + assert.strictEqual(result.stdout, ''); + const event = JSON.parse(result.stderr); + assert.strictEqual(event.message, 'failed'); + assert.deepStrictEqual(event.level, { name: 'error', value: 50 }); +} + +{ + const result = run( + 'stdout', + 'trace', + "const value = {}; value.self = value; logger.info('cyclic', value);", + ); + + assert.notStrictEqual(result.status, 0); + assert.match(result.stderr, /circular structure/i); +} + +{ + const script = ` + const { ConsoleProvider, create } = require('node:logger'); + const { inspect } = require('node:util'); + const provider = new ConsoleProvider({ serializer: inspect, sync: true }); + const logger = create(provider); + const cyclic = { value: 1n }; + cyclic.self = cyclic; + logger.info('inspected', { cyclic }); + provider.flushSync(); + `; + const result = spawnSync(process.execPath, [ + '--no-warnings', + '-e', + script, + ], { encoding: 'utf8' }); + + assert.strictEqual(result.status, 0); + assert.strictEqual(result.stderr, ''); + assert.match(result.stdout, /message: 'inspected'/); + assert.match(result.stdout, /value: 1n/); + assert.match(result.stdout, /\[Circular \*\d+\]/); +} + +{ + const provider = new ConsoleProvider({ serializer: inspect }); + assert.strictEqual(provider.serializer, inspect); +} + +assert.throws( + () => new ConsoleProvider({ serializer: 'json' }), + { code: 'ERR_INVALID_ARG_TYPE' }, +); +assert.throws( + () => new ConsoleProvider({ pid: 1 }), + { code: 'ERR_INVALID_ARG_TYPE' }, +); + +{ + const provider = new ConsoleProvider({ serializer: () => null }); + assert.throws( + () => provider.log({ level: { value: 30 } }), + { code: 'ERR_INVALID_RETURN_VALUE' }, + ); +} diff --git a/test/parallel/test-logger.js b/test/parallel/test-logger.js new file mode 100644 index 000000000000..78588f2ab6bf --- /dev/null +++ b/test/parallel/test-logger.js @@ -0,0 +1,223 @@ +'use strict'; + +const common = require('../common'); +const assert = require('node:assert'); +const { AsyncLocalStorage } = require('node:async_hooks'); +const { isBuiltin } = require('node:module'); +const { Readable } = require('node:stream'); +const { + ConsoleProvider, + Logger, + ReadableProvider, + create, + levels, +} = require('node:logger'); + +common.expectWarning( + 'ExperimentalWarning', + 'Logger is an experimental feature and might change at any time', +); + +assert.strictEqual(isBuiltin('node:logger'), true); +assert.strictEqual(isBuiltin('logger'), false); + +{ + const first = create(); + const second = create(); + + assert.ok(first instanceof Logger); + assert.ok(first.provider instanceof ConsoleProvider); + assert.notStrictEqual(first.provider, second.provider); +} + +{ + const events = []; + const contexts = []; + const provider = { + isEnabled(level, context) { + contexts.push(context); + return level.value >= levels.debug.value; + }, + log: common.mustCall(function log(event) { + assert.strictEqual(this, provider); + events.push(event); + }, 2), + }; + const inputBindings = { service: 'api' }; + const logger = create(provider, { + name: 'root', + bindings: inputBindings, + }); + + inputBindings.service = 'changed'; + + assert.strictEqual(logger.provider, provider); + assert.strictEqual(logger.name, 'root'); + assert.deepStrictEqual(logger.bindings, { + __proto__: null, + service: 'api', + }); + assert.strictEqual(Object.isFrozen(logger.bindings), true); + assert.strictEqual(logger.isEnabled('trace'), false); + assert.strictEqual(logger.isEnabled('debug'), true); + + logger.trace('filtered'); + + const inputAttributes = { requestId: 1 }; + logger.info('request received', inputAttributes); + inputAttributes.requestId = 2; + + assert.strictEqual(events.length, 1); + const event = events[0]; + assert.strictEqual(event.message, 'request received'); + assert.strictEqual(event.name, 'root'); + assert.strictEqual(event.level, levels.info); + assert.strictEqual(typeof event.timestamp, 'number'); + assert.deepStrictEqual(event.bindings, { + __proto__: null, + service: 'api', + }); + assert.deepStrictEqual(event.attributes, { + __proto__: null, + requestId: 1, + }); + assert.strictEqual(Object.isFrozen(event), true); + assert.strictEqual(Object.isFrozen(event.attributes), true); + assert.strictEqual(contexts.at(-1).name, 'root'); + + const child = logger.child({ service: 'worker', workerId: 2 }); + assert.strictEqual(child.provider, provider); + assert.strictEqual(child.name, 'root'); + assert.deepStrictEqual(child.bindings, { + __proto__: null, + service: 'worker', + workerId: 2, + }); + + child.log({ name: 'notice', value: 35 }, 'custom level'); + assert.strictEqual(events.length, 2); + assert.deepStrictEqual(events[1].level, { + __proto__: null, + name: 'notice', + value: 35, + }); +} + +{ + const events = []; + const provider = { + log(event) { + events.push(event); + }, + }; + const logger = new Logger(provider); + + logger.fatal('fatal message'); + assert.strictEqual(events.length, 1); + assert.strictEqual(logger.isEnabled('trace'), true); +} + +{ + const bindingStorage = new AsyncLocalStorage(); + const attributeStorage = new AsyncLocalStorage(); + const events = []; + const logger = create({ + log(event) { + events.push(event); + }, + }, { + bindings: { request: bindingStorage }, + }); + + logger.info('outside', { operation: attributeStorage }); + bindingStorage.run({ requestId: 1 }, () => { + attributeStorage.run('create', () => { + logger.info('inside', { operation: attributeStorage }); + }); + }); + bindingStorage.run({ requestId: 2 }, () => { + logger.info('second request'); + }); + + assert.strictEqual(logger.bindings.request, bindingStorage); + assert.strictEqual(events[0].bindings.request, undefined); + assert.strictEqual(events[0].attributes.operation, undefined); + assert.deepStrictEqual(events[1].bindings.request, { requestId: 1 }); + assert.strictEqual(events[1].attributes.operation, 'create'); + assert.deepStrictEqual(events[2].bindings.request, { requestId: 2 }); +} + +{ + const logger = create({ name: 'options-only' }); + assert.strictEqual(logger.name, 'options-only'); + assert.ok(logger.provider instanceof ConsoleProvider); +} + +{ + const provider = new ReadableProvider({ + highWaterMark: 4, + level: 'debug', + }); + const logger = create(provider, { name: 'stream' }); + const events = []; + + assert.ok(provider instanceof Readable); + assert.strictEqual(provider.readableObjectMode, true); + assert.strictEqual(provider.readableHighWaterMark, 4); + + provider.on('data', common.mustCall((event) => { + events.push(event); + }, 2)); + provider.on('end', common.mustCall(() => { + assert.strictEqual(events.length, 2); + assert.strictEqual(events[0].level, levels.debug); + assert.strictEqual(events[1].level, levels.error); + })); + + logger.trace('filtered'); + logger.debug('debug message'); + logger.error('error message'); + provider.close(); + assert.strictEqual(logger.isEnabled('fatal'), false); +} + +assert.throws( + () => create(1), + { code: 'ERR_INVALID_ARG_TYPE' }, +); +assert.throws( + () => create({ log: 'not a function' }, {}), + { code: 'ERR_INVALID_ARG_TYPE' }, +); +assert.throws( + () => create({ log() {}, isEnabled: true }), + { code: 'ERR_INVALID_ARG_TYPE' }, +); +assert.throws( + () => create({ bindings: [] }), + { code: 'ERR_INVALID_ARG_TYPE' }, +); + +{ + const logger = create({ log() {} }); + + assert.throws( + () => logger.info(1), + { code: 'ERR_INVALID_ARG_TYPE' }, + ); + assert.throws( + () => logger.info('message', []), + { code: 'ERR_INVALID_ARG_TYPE' }, + ); + assert.throws( + () => logger.log('unknown', 'message'), + { code: 'ERR_INVALID_ARG_VALUE' }, + ); + assert.throws( + () => logger.log({ name: 'custom', value: 1.5 }, 'message'), + { code: 'ERR_OUT_OF_RANGE' }, + ); +} + +assert.strictEqual(Object.isFrozen(levels), true); +assert.strictEqual(Object.isFrozen(levels.info), true);