From 645ad450751b45e73b7c6e4e85c4b87ee3b5c3ed 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 | 78 ++++++++++++++++++ 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, 230 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 3b1ea94eff9781..8be7e150bbfd7c 100644 --- a/doc/api/test.md +++ b/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'` + + + +* `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])` + + + +* `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: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 diff --git a/lib/internal/test_runner/reporter/junit.js b/lib/internal/test_runner/reporter/junit.js index 130ff60af405ad..ed25a4bd5fbd7c 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 fce0754e25061a..7f5920c7b38a30 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 c3bbd1d144eb35..2bacba167570a8 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 67030680019838..995155c533c51d 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 7f50cc8521bcda..dc6529c220539a 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 d19d6349f104bf..1b9faad58a68b5 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 8be33f90dfa0f2..7fb514fb99e2f5 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 74b77682b6821d..6c99569e11533c 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 00000000000000..f19a951b982980 --- /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 85b468cae2a7e1..ac1c97ee007d68 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 00000000000000..8e767e0f903c8e --- /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(', ')}`, + ); +});