From e24d081e0186d225cc78ad06ad53ac1892fb8591 Mon Sep 17 00:00:00 2001 From: Moshe Atlow Date: Thu, 9 Jul 2026 12:14:26 +0300 Subject: [PATCH] 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 --- doc/api/test.md | 81 +++++++++++++++++++ lib/internal/test_runner/reporter/junit.js | 3 +- lib/internal/test_runner/reporter/spec.js | 5 +- lib/internal/test_runner/reporter/tap.js | 1 + lib/internal/test_runner/reporter/utils.js | 4 + lib/internal/test_runner/runner.js | 2 +- lib/internal/test_runner/test.js | 15 ++++ lib/internal/test_runner/tests_stream.js | 13 +++ .../execution-ordered-bypass/fast-fail.mjs | 3 +- .../fixtures/test-runner/log-events/basic.mjs | 19 +++++ .../test-runner-execution-ordered-bypass.mjs | 12 +++ test/parallel/test-runner-log.mjs | 80 ++++++++++++++++++ 12 files changed, 233 insertions(+), 5 deletions(-) create mode 100644 test/fixtures/test-runner/log-events/basic.mjs create mode 100644 test/parallel/test-runner-log.mjs diff --git a/doc/api/test.md b/doc/api/test.md index 4a44fa91e8ea..94f35abd03a0 100644 --- a/doc/api/test.md +++ b/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'` + + + +* `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])` + + + +* `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` + +* `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 diff --git a/lib/internal/test_runner/reporter/junit.js b/lib/internal/test_runner/reporter/junit.js index 130ff60af405..ed25a4bd5fbd 100644 --- a/lib/internal/test_runner/reporter/junit.js +++ b/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, diff --git a/lib/internal/test_runner/reporter/spec.js b/lib/internal/test_runner/reporter/spec.js index fce0754e2506..7f5920c7b38a 100644 --- a/lib/internal/test_runner/reporter/spec.js +++ b/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': diff --git a/lib/internal/test_runner/reporter/tap.js b/lib/internal/test_runner/reporter/tap.js index c3bbd1d144eb..2bacba167570 100644 --- a/lib/internal/test_runner/reporter/tap.js +++ b/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': diff --git a/lib/internal/test_runner/reporter/utils.js b/lib/internal/test_runner/reporter/utils.js index 670306800198..995155c533c5 100644 --- a/lib/internal/test_runner/reporter/utils.js +++ b/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; }, diff --git a/lib/internal/test_runner/runner.js b/lib/internal/test_runner/runner.js index 7f50cc8521bc..dc6529c22053 100644 --- a/lib/internal/test_runner/runner.js +++ b/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; diff --git a/lib/internal/test_runner/test.js b/lib/internal/test_runner/test.js index d19d6349f104..1b9faad58a68 100644 --- a/lib/internal/test_runner/test.js +++ b/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(); diff --git a/lib/internal/test_runner/tests_stream.js b/lib/internal/test_runner/tests_stream.js index 8be33f90dfa0..7fb514fb99e2 100644 --- a/lib/internal/test_runner/tests_stream.js +++ b/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, diff --git a/test/fixtures/test-runner/execution-ordered-bypass/fast-fail.mjs b/test/fixtures/test-runner/execution-ordered-bypass/fast-fail.mjs index 74b77682b682..6c99569e1153 100644 --- a/test/fixtures/test-runner/execution-ordered-bypass/fast-fail.mjs +++ b/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'); }); diff --git a/test/fixtures/test-runner/log-events/basic.mjs b/test/fixtures/test-runner/log-events/basic.mjs new file mode 100644 index 000000000000..f19a951b9829 --- /dev/null +++ b/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 }); + }), + ]); +}); diff --git a/test/parallel/test-runner-execution-ordered-bypass.mjs b/test/parallel/test-runner-execution-ordered-bypass.mjs index 85b468cae2a7..ac1c97ee007d 100644 --- a/test/parallel/test-runner-execution-ordered-bypass.mjs +++ b/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(', ')}`, + ); }); diff --git a/test/parallel/test-runner-log.mjs b/test/parallel/test-runner-log.mjs new file mode 100644 index 000000000000..8e767e0f903c --- /dev/null +++ b/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(), //); +}); + +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(', ')}`, + ); +});