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