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

doc/api/test.md

@@ -3708,6 +3708,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}
@@ -4233,6 +4265,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
@@ -4722,8 +4777,30 @@ 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:diagnostic'`]: #event-testdiagnostic
+[`'test:log'`]: #event-testlog
 [`--experimental-test-coverage`]: cli.md#--experimental-test-coverage
 [`--experimental-test-module-mocks`]: cli.md#--experimental-test-module-mocks
 [`--experimental-test-tag-filter`]: cli.md#--experimental-test-tag-filterexpr
@@ -4751,6 +4828,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 });
+    }),
+  ]);
+});

test/parallel/test-runner-execution-ordered-bypass.mjs

@@ -35,6 +35,10 @@ test('execution-ordered events bypass FileTest declaration-order buffer', async
     }
   });
 
+  stream.on('test:log', (data) => {
+    events.push(`log:${data.message}`);
+  });
+
   // eslint-disable-next-line no-unused-vars
   for await (const _ of stream);
 
@@ -56,4 +60,12 @@ test('execution-ordered events bypass FileTest declaration-order buffer', async
     failFast > completeSlow,
     `test:fail for fast-fail should arrive after test:complete for slow; events=${events.join(', ')}`,
   );
+
+  // test:log is execution-ordered, so it must bypass the buffer too.
+  const logFast = events.indexOf('log:live');
+  assert.notStrictEqual(logFast, -1);
+  assert.ok(
+    logFast < completeSlow,
+    `test:log for fast-fail should arrive before slow's test:complete; events=${events.join(', ')}`,
+  );
 });

test/parallel/test-runner-log.mjs

@@ -0,0 +1,80 @@
+// Flags: --no-warnings
+import '../common/index.mjs';
+import * as fixtures from '../common/fixtures.mjs';
+import assert from 'node:assert';
+import { spawnSync } from 'node:child_process';
+import { test, run } from 'node:test';
+
+const fixture = fixtures.path('test-runner', 'log-events', 'basic.mjs');
+
+test('t.log() validates its arguments', (t) => {
+  assert.throws(() => t.log(123), { code: 'ERR_INVALID_ARG_TYPE' });
+});
+
+test('built-in reporters render test:log like diagnostics', () => {
+  const tap = spawnSync(process.execPath, ['--test', '--test-reporter=tap', fixture]);
+  assert.match(tap.stdout.toString(), /# hello/);
+  assert.match(tap.stdout.toString(), /# suite message/);
+
+  const spec = spawnSync(process.execPath, ['--test', '--test-reporter=spec', fixture]);
+  assert.match(spec.stdout.toString(), /ℹ hello/);
+  assert.match(spec.stdout.toString(), /ℹ warned/);
+
+  const junit = spawnSync(process.execPath, ['--test', '--test-reporter=junit', fixture]);
+  assert.match(junit.stdout.toString(), /<!-- hello -->/);
+});
+
+test('test:log is emitted immediately with the expected payload', async () => {
+  const stream = run({
+    files: [fixture],
+    isolation: 'none',
+  });
+
+  const logs = [];
+  const events = [];
+
+  stream.on('test:log', (data) => {
+    logs.push(data);
+    events.push(`log:${data.message}`);
+  });
+
+  stream.on('test:pass', (data) => {
+    events.push(`pass:${data.name}`);
+  });
+
+  // eslint-disable-next-line no-unused-vars
+  for await (const _ of stream);
+
+  assert.strictEqual(logs.length, 3);
+
+  const suiteLog = logs.find((log) => log.message === 'suite message');
+  assert.strictEqual(suiteLog.name, 'my suite');
+  assert.strictEqual(suiteLog.data, undefined);
+
+  const hello = logs.find((log) => log.message === 'hello');
+  assert.strictEqual(hello.name, 'logger');
+  assert.ok(!('level' in hello));
+  assert.deepStrictEqual(hello.data, { foo: 1 });
+  assert.strictEqual(typeof hello.nesting, 'number');
+  assert.strictEqual(typeof hello.testId, 'number');
+  assert.strictEqual(typeof hello.parentId, 'number');
+  assert.strictEqual(typeof hello.file, 'string');
+  assert.strictEqual(typeof hello.line, 'number');
+  assert.strictEqual(typeof hello.column, 'number');
+
+  // The runner does not interpret data; conventions like a level live there.
+  const warned = logs.find((log) => log.message === 'warned');
+  assert.ok(!('level' in warned));
+  assert.deepStrictEqual(warned.data, { level: 'warn', attempt: 2 });
+
+  // 'logger' logs immediately while its earlier-declared sibling 'slow' is
+  // still running, so the log must arrive before slow's buffered test:pass.
+  const logIndex = events.indexOf('log:hello');
+  const slowPassIndex = events.indexOf('pass:slow');
+  assert.notStrictEqual(logIndex, -1);
+  assert.notStrictEqual(slowPassIndex, -1);
+  assert.ok(
+    logIndex < slowPassIndex,
+    `test:log should arrive before slow's buffered test:pass; events=${events.join(', ')}`,
+  );
+});