test_runner: add context.log() and test:log event

Add a log(message[, data]) method to TestContext and SuiteContext that
emits a new test:log event. Unlike test:diagnostic, which is buffered
so it is emitted in the order tests are defined, test:log is emitted
immediately, in the order tests execute, including under process
isolation where it bypasses the per-file declaration order buffer.
This gives reporters that render the test tree unbuffered a live,
attributed logging channel that captured stdout cannot provide under
concurrency.

The event carries the message, an optional opaque structured payload
that the runner passes through untouched, and the emitting test's
name, testId, parentId, nesting, and location. Built-in reporters
render it the same way they render test:diagnostic.

Signed-off-by: Moses Atlow <moshe@atlow.co.il>
PR-URL: #64389
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>

Author: MoLow

doc/api/test.md

@@ -3478,6 +3478,10 @@ ordered events, emitted immediately as the tests execute.
 | [`'test:fail'`][]              | [`'test:complete'`][] (`details.passed` is `false`)   |
 | [`'test:plan'`][]              |                                                       |
 | [`'test:diagnostic'`][]        |                                                       |
+|                                | [`'test:log'`][]                                      |
+
+[`'test:log'`][] is deliberately execution ordered only: it is the live
+counterpart of [`'test:diagnostic'`][]'s buffered reporting.
 
 File scoped and global events are always emitted immediately, in execution
 order.
@@ -3747,6 +3751,38 @@ When using process isolation (the default), the test name will be the file path
 since the parent runner only knows about file-level tests. When using
 `--test-isolation=none`, the actual test name is shown.
 
+### Event: `'test:log'`
+
+<!-- YAML
+added: REPLACEME
+-->
+
+* `data` {Object}
+  * `column` {number|undefined} The column number where the test is defined, or
+    `undefined` if the test was run through the REPL.
+  * `data` {any} The structured payload passed to [`context.log`][], or
+    `undefined` if none was provided. The test runner does not interpret this
+    value.
+  * `entryFile` {string|undefined} The path of the test file that was
+    executed as the entry point of the child process that emitted this event.
+    Only present when tests run with process isolation. May differ from
+    `file` when the test is defined in a module imported by the entry file.
+  * `file` {string|undefined} The path of the test file,
+    `undefined` if test was run through the REPL.
+  * `line` {number|undefined} The line number where the test is defined, or
+    `undefined` if the test was run through the REPL.
+  * `message` {string} The log message.
+  * `name` {string} The test name.
+  * `nesting` {number} The nesting level of the test.
+  * `parentId` {number|undefined} The `testId` of the enclosing test, or
+    `undefined` for top-level tests.
+  * `testId` {number} A numeric identifier for the test instance that emitted
+    the log message.
+
+Emitted when [`context.log`][] is called. Unlike [`'test:diagnostic'`][],
+this event is emitted immediately, in the order that the tests execute,
+making it suitable for reporters that render test output unbuffered.
+
 ### Event: `'test:pass'`
 
 * `data` {Object}
@@ -4272,6 +4308,29 @@ test('top level test', (t) => {
 });
 ```
 
+### `context.log(message[, data])`
+
+<!-- YAML
+added: REPLACEME
+-->
+
+* `message` {string} Message to be reported.
+* `data` {any} Optional structured payload attached to the message. The test
+  runner passes it through untouched. When tests run with process isolation,
+  this value must be compatible with the [HTML structured clone algorithm][].
+
+This function is used to write a log message to the output. Unlike
+[`context.diagnostic`][], the resulting [`'test:log'`][] event is emitted
+immediately, in the order that the tests execute, rather than being buffered
+until the test reports its results. This function does not return a value.
+
+```js
+test('top level test', (t) => {
+  t.log('fetched user', { userId: 42 });
+  t.log('retrying flaky endpoint', { attempt: 3 });
+});
+```
+
 ### `context.filePath`
 
 <!-- YAML
@@ -4761,6 +4820,26 @@ test.describe('my suite', (suite) => {
 });
 ```
 
+### `context.log(message[, data])`
+
+<!-- YAML
+added: REPLACEME
+-->
+
+* `message` {string} Message to be reported.
+* `data` {any} Optional structured payload attached to the message. The test
+  runner passes it through untouched.
+
+Write a log message to the output. The resulting [`'test:log'`][] event is
+emitted immediately, in the order that the tests execute.
+
+```js
+test.describe('my suite', (suite) => {
+  suite.log('Suite log message');
+});
+```
+
+[HTML structured clone algorithm]: https://developer.mozilla.org/en-US/docs/Web/API/Web_Workers_API/Structured_clone_algorithm
 [TAP]: https://testanything.org/
 [Test tags]: #test-tags
 [`'test:complete'`]: #event-testcomplete
@@ -4770,6 +4849,7 @@ test.describe('my suite', (suite) => {
 [`'test:enqueue'`]: #event-testenqueue
 [`'test:fail'`]: #event-testfail
 [`'test:interrupted'`]: #event-testinterrupted
+[`'test:log'`]: #event-testlog
 [`'test:pass'`]: #event-testpass
 [`'test:plan'`]: #event-testplan
 [`'test:start'`]: #event-teststart
@@ -4805,6 +4885,7 @@ test.describe('my suite', (suite) => {
 [`TracingChannel`]: diagnostics_channel.md#class-tracingchannel
 [`assert.throws`]: assert.md#assertthrowsfn-error-message
 [`context.diagnostic`]: #contextdiagnosticmessage
+[`context.log`]: #contextlogmessage-data
 [`context.skip`]: #contextskipmessage
 [`context.tags`]: #contexttags
 [`context.todo`]: #contexttodomessage

lib/internal/test_runner/reporter/junit.js

@@ -154,7 +154,8 @@ module.exports = async function* junitReporter(source) {
         }
         break;
       }
-      case 'test:diagnostic': {
+      case 'test:diagnostic':
+      case 'test:log': {
         const parent = currentSuite?.children ?? roots;
         ArrayPrototypePush(parent, {
           __proto__: null, nesting: event.data.nesting, comment: event.data.message,

lib/internal/test_runner/reporter/spec.js

@@ -91,8 +91,9 @@ class SpecReporter extends Transform {
       case 'test:stderr':
       case 'test:stdout':
         return data.message;
-      case 'test:diagnostic':{
-        const diagnosticColor = reporterColorMap[data.level] || reporterColorMap['test:diagnostic'];
+      case 'test:diagnostic':
+      case 'test:log': {
+        const diagnosticColor = reporterColorMap[data.level] || reporterColorMap[type];
         return `${diagnosticColor}${indent(data.nesting)}${reporterUnicodeSymbolMap[type]}${data.message}${colors.white}\n`;
       }
       case 'test:coverage':

lib/internal/test_runner/reporter/tap.js

@@ -56,6 +56,7 @@ async function * tapReporter(source) {
         }
         break;
       } case 'test:diagnostic':
+      case 'test:log':
         yield `${indent(data.nesting)}# ${tapEscape(data.message)}\n`;
         break;
       case 'test:coverage':

lib/internal/test_runner/reporter/utils.js

@@ -21,6 +21,7 @@ const reporterUnicodeSymbolMap = {
   'test:fail': '\u2716 ',
   'test:pass': '\u2714 ',
   'test:diagnostic': '\u2139 ',
+  'test:log': '\u2139 ',
   'test:coverage': '\u2139 ',
   'arrow:right': '\u25B6 ',
   'hyphen:minus': '\uFE63 ',
@@ -38,6 +39,9 @@ const reporterColorMap = {
   get 'test:diagnostic'() {
     return colors.blue;
   },
+  get 'test:log'() {
+    return colors.blue;
+  },
   get 'info'() {
     return colors.blue;
   },

lib/internal/test_runner/runner.js

@@ -130,7 +130,7 @@ const kCanceledTests = new SafeSet()
 // Execution-ordered events are forwarded immediately, bypassing the
 // per-file declaration-order buffer.
 const kExecutionOrderedEvents = new SafeSet()
-  .add('test:enqueue').add('test:dequeue').add('test:complete');
+  .add('test:enqueue').add('test:dequeue').add('test:complete').add('test:log');
 
 let kResistStopPropagation;
 

lib/internal/test_runner/test.js

@@ -80,6 +80,7 @@ const {
   validateNumber,
   validateObject,
   validateOneOf,
+  validateString,
   validateUint32,
 } = require('internal/validators');
 const {
@@ -315,6 +316,10 @@ class TestContext {
     this.#test.diagnostic(message);
   }
 
+  log(message, data) {
+    this.#test.log(message, data);
+  }
+
   plan(count, options = kEmptyObject) {
     if (this.#test.plan !== null) {
       throw new ERR_TEST_FAILURE(
@@ -523,6 +528,10 @@ class SuiteContext {
   diagnostic(message) {
     this.#suite.diagnostic(message);
   }
+
+  log(message, data) {
+    this.#suite.log(message, data);
+  }
 }
 
 function parseExpectFailure(expectFailure) {
@@ -1198,6 +1207,12 @@ class Test extends AsyncResource {
     ArrayPrototypePush(this.diagnostics, message);
   }
 
+  log(message, data) {
+    validateString(message, 'message');
+    this.reporter.log(this.nesting, this.loc, message, data,
+                      this.name, this.testId, this.parent?.testId);
+  }
+
   start() {
     this.applyFilters();
 

lib/internal/test_runner/tests_stream.js

@@ -139,6 +139,19 @@ class TestsStream extends Readable {
     });
   }
 
+  log(nesting, loc, message, data, name, testId, parentId) {
+    this[kEmitMessage]('test:log', {
+      __proto__: null,
+      name,
+      nesting,
+      testId,
+      parentId,
+      message,
+      data,
+      ...loc,
+    });
+  }
+
   diagnostic(nesting, loc, message, level = 'info') {
     this[kEmitMessage]('test:diagnostic', {
       __proto__: null,

test/fixtures/test-runner/execution-ordered-bypass/fast-fail.mjs

@@ -1,6 +1,7 @@
 import { test } from 'node:test';
 import assert from 'node:assert';
 
-test('fast-fail', () => {
+test('fast-fail', (t) => {
+  t.log('live');
   assert.fail('fast');
 });

test/fixtures/test-runner/log-events/basic.mjs

@@ -0,0 +1,19 @@
+import { suite, test } from 'node:test';
+import { setTimeout } from 'node:timers/promises';
+
+suite('my suite', (s) => {
+  s.log('suite message');
+  test('in suite', () => {});
+});
+
+test('parent', { concurrency: 2 }, async (t) => {
+  await Promise.all([
+    t.test('slow', async () => {
+      await setTimeout(200);
+    }),
+    t.test('logger', (t) => {
+      t.log('hello', { foo: 1 });
+      t.log('warned', { level: 'warn', attempt: 2 });
+    }),
+  ]);
+});