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 <jasnell@gmail.com>
Assisted-by: Opencode

Author: jasnell

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');
+}

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);
+  }
+}

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);
+  }
+}

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');
+}

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`
+
+<!-- YAML
+added: REPLACEME
+-->
+
+> Stability: 1.1 - Active development
+
+Enable the experimental [`node:logger`][] module.
+
 ### `--experimental-network-inspection`
 
 <!-- YAML
@@ -4276,6 +4286,7 @@ one is included in the list below.
 * `--experimental-import-text`
 * `--experimental-json-modules`
 * `--experimental-loader`
+* `--experimental-logger`
 * `--experimental-modules`
 * `--experimental-package-map`
 * `--experimental-print-required-tla`
@@ -4961,6 +4972,7 @@ node --stack-trace-limit=12 -p -e "Error.stackTraceLimit" # prints 12
 [`inspector.open()`]: inspector.md#inspectoropenport-host-wait
 [`net.getDefaultAutoSelectFamilyAttemptTimeout()`]: net.md#netgetdefaultautoselectfamilyattempttimeout
 [`node:ffi`]: ffi.md
+[`node:logger`]: logger.md
 [`node:sqlite`]: sqlite.md
 [`node:stream/iter`]: stream_iter.md
 [`node:vfs`]: vfs.md

doc/api/fs.md

@@ -8563,12 +8563,13 @@ Close the stream gracefully, flushing the internal buffer before closing.
 * `callback` {Function}
   * `err` {Error|null} An error if the flush failed, otherwise `null`.
 
-Writes the current buffer to the file if a write was not in progress. Do
-nothing if `minLength` is zero or if it is already writing.
+Writes the current buffer to the file. The callback is invoked after pending
+writes complete.
 
 #### `utf8Stream.flushSync()`
 
-Flushes the buffered data synchronously. This is a costly operation.
+Flushes the buffered data synchronously. This is a costly operation. An
+`ERR_INVALID_STATE` error is thrown if the stream is currently writing.
 
 #### `utf8Stream.fsync`
 

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)