test_runner: attribute global console output to active tests

doc/api/test.md

@@ -3456,6 +3456,10 @@ added:
   - v18.9.0
   - v16.19.0
 changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/65147
+    description: Added test and suite attribution to `test:stdout` and
+                 `test:stderr` events for built-in global `console` output.
   - version: v26.6.0
     pr-url: https://github.com/nodejs/node/pull/64309
     description: Added `entryFile` to events forwarded from child processes
@@ -3484,10 +3488,14 @@ are defined, while others are emitted in the order that the tests execute.
 
 The following tables summarize all events by scope.
 
-Test scoped events are emitted once per test or suite. Most of them come in
-pairs: a declaration ordered event, buffered so that events are emitted in the
-same order as the tests are defined, and one or more corresponding execution
-ordered events, emitted immediately as the tests execute.
+Test scoped events are associated with a test or suite. Lifecycle events are
+emitted once per test or suite, while [`'test:diagnostic'`][],
+[`'test:log'`][], and attributed [`'test:stdout'`][] and
+[`'test:stderr'`][] events may be emitted any number of times. Most lifecycle
+events come in pairs: a declaration ordered event, buffered so that events are
+emitted in the same order as the tests are defined,
+and one or more corresponding execution ordered events, emitted immediately as
+the tests execute.
 
 | Declaration ordered (buffered) | Execution ordered (immediate)                         |
 | ------------------------------ | ----------------------------------------------------- |
@@ -3497,19 +3505,33 @@ ordered events, emitted immediately as the tests execute.
 | [`'test:plan'`][]              |                                                       |
 | [`'test:diagnostic'`][]        |                                                       |
 |                                | [`'test:log'`][]                                      |
+|                                | [`'test:stderr'`][] (attributed console output)       |
+|                                | [`'test:stdout'`][] (attributed console output)       |
 
 [`'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.
+With process isolation, output written through the built-in global console
+during an active test or suite is associated with that test or suite and
+emitted in execution order. Other output, such as direct writes to the process
+streams, remains file scoped.
 
-File scoped events are emitted once per test file:
+Output from a hook is associated with the test or suite that owns the hook.
+For example, output from a suite's `beforeEach()` hook is associated with the
+suite rather than with the child test that triggered it. Output from
+root-level hooks remains file scoped.
+
+Global events are always emitted immediately, in execution order.
+
+File scoped events carry information about a test file rather than an
+individual test. [`'test:stdout'`][] and [`'test:stderr'`][] may be emitted
+any number of times for a file, while the remaining events are emitted once
+per test file:
 
 | Event                | Notes                                          |
 | -------------------- | ---------------------------------------------- |
-| [`'test:stderr'`][]  | Only emitted if the `--test` flag is passed.   |
-| [`'test:stdout'`][]  | Only emitted if the `--test` flag is passed.   |
+| [`'test:stderr'`][]  | Only emitted when process isolation is used.   |
+| [`'test:stdout'`][]  | Only emitted when process isolation is used.   |
 | [`'test:summary'`][] | Per file, only when process isolation is used. |
 
 Global events are emitted once per test run:
@@ -3895,30 +3917,78 @@ The corresponding execution ordered event is `'test:dequeue'`.
 ### Event: `'test:stderr'`
 
 * `data` {Object}
+  * `column` {number|undefined} The column number where the test or suite is
+    defined. Only present when the output is associated with a test or suite
+    and that test or suite has a known source location.
   * `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.
-  * `file` {string} The path of the test file.
+  * `file` {string} The path of the test file. When the output is associated
+    with a test or suite, this is the file where that test or suite is defined,
+    or the entry point of the child process if its source location is not
+    known.
+  * `line` {number|undefined} The line number where the test or suite is
+    defined. Only present when the output is associated with a test or suite
+    and that test or suite has a known source location.
   * `message` {string} The message written to `stderr`.
-
-Emitted when a running test writes to `stderr`.
-This event is only emitted if `--test` flag is passed.
-This event is not guaranteed to be emitted in the same order as the tests are
-defined.
+  * `name` {string|undefined} The test or suite name. Only present when the
+    output is associated with a test or suite.
+  * `nesting` {number|undefined} The nesting level of the test or suite. Only
+    present when the output is associated with a test or suite.
+  * `parentId` {number|undefined} The `testId` of the enclosing test or suite.
+    Only present when the output is associated with a test or suite.
+  * `testId` {number|undefined} A numeric identifier for the test or suite.
+    Only present when the output is associated with a test or suite.
+
+Emitted when the test runner observes output written to `stderr`. This event is
+only emitted when tests run with process isolation. Output written through the
+built-in global console during an active test or suite is associated with that
+test or suite and is emitted after its [`'test:dequeue'`][] event. Direct
+writes to `process.stderr`, native output, output written through separately
+constructed `Console` instances, top-level output outside an active test or
+suite, root-level hook output, output produced while suites are being defined,
+and asynchronous output after a test finishes are not associated with a test.
+Their ordering relative to test events is not guaranteed. Because associated and
+unassociated output reach the reporter through different paths, their relative
+order is not guaranteed either, even within a single test.
 
 ### Event: `'test:stdout'`
 
 * `data` {Object}
+  * `column` {number|undefined} The column number where the test or suite is
+    defined. Only present when the output is associated with a test or suite
+    and that test or suite has a known source location.
   * `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.
-  * `file` {string} The path of the test file.
+  * `file` {string} The path of the test file. When the output is associated
+    with a test or suite, this is the file where that test or suite is defined,
+    or the entry point of the child process if its source location is not
+    known.
+  * `line` {number|undefined} The line number where the test or suite is
+    defined. Only present when the output is associated with a test or suite
+    and that test or suite has a known source location.
   * `message` {string} The message written to `stdout`.
-
-Emitted when a running test writes to `stdout`.
-This event is only emitted if `--test` flag is passed.
-This event is not guaranteed to be emitted in the same order as the tests are
-defined.
+  * `name` {string|undefined} The test or suite name. Only present when the
+    output is associated with a test or suite.
+  * `nesting` {number|undefined} The nesting level of the test or suite. Only
+    present when the output is associated with a test or suite.
+  * `parentId` {number|undefined} The `testId` of the enclosing test or suite.
+    Only present when the output is associated with a test or suite.
+  * `testId` {number|undefined} A numeric identifier for the test or suite.
+    Only present when the output is associated with a test or suite.
+
+Emitted when the test runner observes output written to `stdout`. This event is
+only emitted when tests run with process isolation. Output written through the
+built-in global console during an active test or suite is associated with that
+test or suite and is emitted after its [`'test:dequeue'`][] event. Direct
+writes to `process.stdout`, native output, output written through separately
+constructed `Console` instances, top-level output outside an active test or
+suite, root-level hook output, output produced while suites are being defined,
+and asynchronous output after a test finishes are not associated with a test.
+Their ordering relative to test events is not guaranteed. Because associated and
+unassociated output reach the reporter through different paths, their relative
+order is not guaranteed either, even within a single test.
 
 ### Event: `'test:summary'`
 

lib/internal/console/constructor.js

@@ -12,6 +12,7 @@ const {
   Boolean,
   ErrorCaptureStackTrace,
   FunctionPrototypeBind,
+  FunctionPrototypeCall,
   MapPrototypeGet,
   MapPrototypeValues,
   ObjectDefineProperties,
@@ -97,6 +98,17 @@ const kUseStdout = Symbol('kUseStdout');
 const kUseStderr = Symbol('kUseStderr');
 
 const optionsMap = new SafeWeakMap();
+// Store hooks separately so installing one does not mutate the Console
+// instance, including when it has been frozen.
+const writeToConsoleHooks = new SafeWeakMap();
+
+// Registers a hook that runs just before a formatted string is written to the
+// underlying stream. Returning true means the hook handled the output and the
+// stream write is skipped. The hook must not throw.
+function setWriteToConsoleHook(console, hook) {
+  writeToConsoleHooks.set(console, hook);
+}
+
 function Console(options /* or: stdout, stderr, ignoreErrors = true */) {
   // We have to test new.target here to see if this function is called
   // with new, because we need to define a custom instanceof to accommodate
@@ -297,12 +309,26 @@ ObjectDefineProperties(Console.prototype, {
       }
       string += '\n';
 
-      if (ignoreErrors === false) return stream.write(string);
+      const hook = writeToConsoleHooks.get(this);
+
+      if (ignoreErrors === false) {
+        if (hook !== undefined &&
+            FunctionPrototypeCall(hook, this, useStdout, string)) {
+          return;
+        }
+        return stream.write(string);
+      }
 
       // There may be an error occurring synchronously (e.g. for files or TTYs
       // on POSIX systems) or asynchronously (e.g. pipes on POSIX systems), so
-      // handle both situations.
+      // handle both situations. Run the hook inside the same error boundary so
+      // it cannot make a console write throw while errors are being ignored.
       try {
+        if (hook !== undefined &&
+            FunctionPrototypeCall(hook, this, useStdout, string)) {
+          return;
+        }
+
         // Add and later remove a noop error handler to catch synchronous
         // errors.
         if (stream.listenerCount('error') === 0)
@@ -713,5 +739,6 @@ module.exports = {
   Console,
   kBindStreamsLazy,
   kBindProperties,
+  setWriteToConsoleHook,
   initializeGlobalConsole,
 };

lib/internal/test_runner/harness.js

@@ -14,6 +14,10 @@ const {
   createHook,
   executionAsyncId,
 } = require('async_hooks');
+const globalConsole = require('internal/console/global');
+const {
+  setWriteToConsoleHook,
+} = require('internal/console/constructor');
 const { relative } = require('path');
 const {
   codes: {
@@ -230,6 +234,48 @@ function setupFailureStateFile(rootTest, globalOptions) {
 }
 
 function setupProcessState(root, globalOptions) {
+  // Attribution only works when the child reports through the V8 serializer,
+  // which preserves the structured event. The 'child' value selects the TAP
+  // reporter, which cannot carry testId/parentId/line/column, so intercepting
+  // there would drop the write without emitting an equivalent event.
+  //
+  // The environment is inspected once, while the runner-provided value is
+  // still intact, and the hook is only installed for that case. Ordinary
+  // processes, runs without process isolation, and TAP children leave the
+  // global console untouched, and assigning to process.env.NODE_TEST_CONTEXT
+  // later cannot turn attribution on.
+  if (process.env.NODE_TEST_CONTEXT === 'child-v8') {
+    setWriteToConsoleHook(globalConsole, (useStdout, message) => {
+      let test = testResources.get(executionAsyncId());
+      if (test?.hookType !== undefined) {
+        test = test.parentTest;
+      }
+      if (test === undefined ||
+          test === reporterScope ||
+          test.parent === null ||
+          test.startTime === null ||
+          test.endTime !== null) {
+        return false;
+      }
+
+      const report = useStdout ?
+        test.reporter.stdout : test.reporter.stderr;
+      reporterScope.runInAsyncScope(
+        report,
+        test.reporter,
+        test.nesting,
+        // Tests defined without a known source location still report the file
+        // they were executed from, so that 'file' stays a string.
+        test.loc ?? { __proto__: null, file: test.entryFile },
+        message,
+        test.name,
+        test.testId,
+        test.parent.testId,
+      );
+      return true;
+    });
+  }
+
   const hook = createHook({
     __proto__: null,
     init(asyncId, type, triggerAsyncId, resource) {

lib/internal/test_runner/runner.js

@@ -343,7 +343,10 @@ class FileTest extends Test {
     }
   }
   addToReport(item) {
-    if (kExecutionOrderedEvents.has(item.type)) {
+    const isAttributedOutput =
+      (item.type === 'test:stdout' || item.type === 'test:stderr') &&
+      item.data.testId !== undefined;
+    if (kExecutionOrderedEvents.has(item.type) || isAttributedOutput) {
       this.#handleReportItem(item);
       return;
     }

lib/internal/test_runner/tests_stream.js

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

test/fixtures/test-runner/console-output-attribution-env-mutation.mjs

@@ -0,0 +1,17 @@
+import { run } from 'node:test';
+import { fileURLToPath } from 'node:url';
+
+const fixture = fileURLToPath(
+  new URL('./console-output-attribution-mutates-env.mjs', import.meta.url),
+);
+const stream = run({ files: [fixture], isolation: 'none' });
+let attributed = 0;
+
+for await (const event of stream) {
+  if ((event.type === 'test:stdout' || event.type === 'test:stderr') &&
+      'testId' in event.data) {
+    attributed++;
+  }
+}
+
+process.stdout.write(`__attributed_count__:${attributed}\n`);

test/fixtures/test-runner/console-output-attribution-frozen-console.mjs

@@ -0,0 +1,5 @@
+import { test } from 'node:test';
+
+test('runs with a frozen console', () => {
+  console.log('frozen-console-out-8a4f');
+});

test/fixtures/test-runner/console-output-attribution-mutates-env.mjs

@@ -0,0 +1,8 @@
+import { test } from 'node:test';
+
+test('mutates NODE_TEST_CONTEXT before writing', () => {
+  // Attribution is decided once, while the runner-provided environment is still
+  // intact. Assigning here must not turn it on for the write that follows.
+  process.env.NODE_TEST_CONTEXT = 'child-v8';
+  console.log('env-mutated-out-2d9c');
+});

test/fixtures/test-runner/console-output-attribution-no-isolation.mjs

@@ -0,0 +1,17 @@
+import { run } from 'node:test';
+import { fileURLToPath } from 'node:url';
+
+const fixture = fileURLToPath(
+  new URL('./console-output-attribution.mjs', import.meta.url),
+);
+const stream = run({ files: [fixture], isolation: 'none' });
+let attributed = 0;
+
+for await (const event of stream) {
+  if ((event.type === 'test:stdout' || event.type === 'test:stderr') &&
+      'testId' in event.data) {
+    attributed++;
+  }
+}
+
+process.stdout.write(`__attributed_count__:${attributed}\n`);