node:test custom reporters get test:stdout and test:stderr events before test:dequeue

Version

v22.2.0

Platform

Linux 6a770f0f664c 6.6.26-linuxkit #1 SMP Sat Apr 27 04:13:19 UTC 2024 aarch64 GNU/Linux

Subsystem

test_runner

What steps will reproduce the bug?

Create a folder with these files:

index.test.mjs:

import { it } from "node:test";

it("test", () => {
  console.log("message from the test");
});

reporter.mjs:

import util from "node:util";

export default async (source) => {
  for await (const event of source) {
    if (event.type === "test:stdout") {
      console.log(event.type, util.inspect(event.data.message));
    }

    if (event.type === "test:dequeue") {
      console.log(event.type, event.data.name);
    }
  }
};

and run

node --test --test-reporter=./reporter.mjs

which will print

test:dequeue index.test.mjs
test:stdout 'message from the test\n'
test:dequeue test

How often does it reproduce? Is there a required condition?

It always does the same

What is the expected behavior? Why is that the expected behavior?

I expected test:dequeue test to be printed before test:stdout 'message from the test\n' as the documentation states "Emitted when a test is dequeued, right before it is executed."

What do you see instead?

The test:stdout event is emitted before the test:dequeue, which makes it impossible to understand which test was running when the message was written to stdout.

Additional information

No response

Also, when there are multiple tests, you can get all of their test:stdout events before the first test:dequeue. For example:

import { it } from "node:test";

it("test", () => {
  console.log("message from the test");
});

it("test2", () => {
  console.log("message from the test");
});

would generate this with the reported presented above

test:dequeue index.test.mjs
test:stdout 'message from the test\n'
test:stdout 'message from the test\n'
test:dequeue test
test:dequeue test2

Based on what I can tell, the event for dequeue is sync, and your function is async (but I might be wrong).

@nodejs/test_runner is this working as intended, or a bug?

There are a few things going on here:

First, I think the docs are wrong for the 'test:stdout' and 'test:stderr' events. We currently do not know the line and column for those events (the file itself can also be wrong in certain cases). But also notice that those two events make no mention of the test itself - they are not bound to a specific test like 'test:dequeue', for example.
Second, the race condition is that the test runner events go through the test reporter stream in a child process before being sent back to the orchestration process. The stdout and stderr events don't go through this stream. The orchestration process just picks up the output as it comes from the child process. Notice that stdout and stderr events only show up when running with --test. You should be able to verify this by adding a setTimeout() around the console.log().

Someone could try binding the events to specific tests, but I don't think it will work correctly in all cases - for example if the logging happens from native code, process._rawDebug(), etc.

I think I could have provided more context. I'm working on a custom reporter. I like to mimic Mocha's default reporter. Part of its behavior is that it prints any console.log in a test right before printing its title and result.

Currently, that's not possible. If I could get test:dequeue before the tests's own output, I could implement it. It'd be ok if the test info is not present in the test:stdout event, as I don't really need it; all want it to print is its event.data.message, but ideally after printing the name of any suite that is being run.

First, I think the docs are wrong for the 'test:stdout' and 'test:stderr' events. We currently do not know the line and column for those events (the file itself can also be wrong in certain cases). But also notice that those two events make no mention of the test itself - they are not bound to a specific test like 'test:dequeue', for example.

I think that's fair. I also noticed test:stdout coming from top-level console.log calls, so I wasn't expecting them to be associated with a test.

Second, the race condition is that the test runner events go through the test reporter stream in a child process before being sent back to the orchestration process

Do you mean race condition as in "this is not intentional" or that it is racy by design? Following your recommendation, I also tried

import { it } from "node:test";

it("test", async () => {
  await new Promise((resolve) =>
    setImmediate(() => {
      console.log(new Error().stack);
      resolve();
    })
  );
});

which emits test:dequeue before test:stdout.

for example if the logging happens from native code, process._rawDebug(), etc.

~~Would this cases still emit test:stdout?~~ Self-answer: process._rawDebug, and writeSync(1, ...) still emit the event.

Based on what I can tell, the event for dequeue is sync, and your function is async (but I might be wrong).

Not entirely sure what you meant here, as I'm not familiar with the test runner internals. I'm just following (almost copy-pasting tbh) the docs.

Do you mean race condition as in "this is not intentional" or that it is racy by design?

It is working as designed because (as far as I know) no major effort has been made to try to tie logs to individual tests. There are a few things that could be tried such as async hooks, monkey patching, etc. However, like I said before, I don't think it will work in all cases.

Would this cases still emit test:stdout? Self-answer: process._rawDebug, and writeSync(1, ...) still emit the event.

Yes, you still get the events because the orchestration process is just scraping stdout/stderr from a child process. But, the file on those events can potentially be wrong, and the line and column numbers are definitely not valid. An example where the file would be wrong is if your main file imports another file containing tests.

Not entirely sure what you meant here, as I'm not familiar with the test runner internals.

That wasn't a response to my comment, but I think the original comment is irrelevant.

Regarding mocha - I'm not a mocha user, but it doesn't seem like it necessarily binds the output to tests either (maybe I'm missing something):

it('test 1', () => {
  console.log('message 1');
  setTimeout(() => {
    console.log('message 2');
  });
});

it('test 2', () => {
  console.log('message 3');
  setTimeout(() => {
    console.log('message 4');
  });
});

I see the following output:

$ npx mocha index.test.mjs 
message 1
  ✔ test 1
message 3
  ✔ test 2

  2 passing (2ms)

message 2
message 4

If I run the mocha binary directly, I see even different output:

$ node ./node_modules/.bin/mocha index.test.mjs


message 1
  ✔ test 1
message 3
  ✔ test 2
message 2
message 4

  2 passing (2ms)

Or sometimes:

$ node ./node_modules/.bin/mocha index.test.mjs


message 1
  ✔ test 1
message 2
message 3
  ✔ test 2

  2 passing (1ms)

message 4

And:

$ node ./node_modules/.bin/mocha index.test.mjs


message 1
  ✔ test 1
message 3
  ✔ test 2
message 2
message 4

  2 passing (2ms)

You are correct in that mocha doesn't associate output to a test. But it notifies the reporter that a suite has started running before running the tests, hence its title gets printed before the test is run. Here's a different example, where this is more clear:

describe("main describe", () => {
  describe("nested describe", () => {
    it("doubly nested test", () => {
      console.log("message from doubly nested test");

      setTimeout(() => {
        console.log("unbounded message"); // gets printed after the tests finish running
      }, 1000);
    });
  });

  it("nested test", () => {
    console.log("message from nested test");
  });
});

it("unnested test", async () => {
  console.log("message from unnested test");
});

Which prints:

$ npx mocha                                 


message from unnested test
  ✔ unnested test
  main describe
message from nested test
    ✔ nested test
    nested describe
message from doubly nested test
      ✔ doubly nested test


  3 passing (4ms)

unbounded message

Here, the output of a test is always printed after the test's describe's title and usually right before its test name. The exception is if you do something like setTimeout and your test doesn't await it. This is helpful as you get to know approximately which test printed each message.

With my node:test reporter from above the output would be:

test:dequeue index.test.mjs
test:stdout message from doubly nested test

test:stdout message from nested test

test:stdout message from unnested test

test:dequeue main describe
test:dequeue nested describe
test:dequeue doubly nested test
test:dequeue nested test
test:dequeue unnested test
test:stdout unbounded message

So, the suite and test names are printed after the console logs, which can make it difficult to understand what's going on, especially if the messages were repeated.

My expected output would be:

test:dequeue index.test.mjs
test:dequeue main describe
test:dequeue nested describe
test:dequeue doubly nested test
test:stdout message from doubly nested test

test:dequeue nested test
test:stdout message from nested test

test:dequeue unnested test
test:stdout message from unnested test

test:stdout unbounded message

I think the only real alternative is to bypass the delay associated with the reporter interface. The events are emitted in the correct order by the test runner, but the events such as 'test:dequeue' go through the reporter, while stdout/stderr do not. Maybe something can be better optimized in the way the test runner sets up its reporter streams.

I've thought about this some more and I think we should support patching Console such that we can intercept logs and associate them with the correct test in the output.

I've thought about this some more and I think we should support patching Console such that we can intercept logs and associate them with the correct test in the output.

sounds like a great idea

I've thought about this some more and I think we should support patching Console such that we can intercept logs and associate them with the correct test in the output.

Quiet late here, but I'd appreciate this a ton tbh. Would lead to a much better DX.

FYI Jest is associating logs with tests, it is a very useful feature. I can see logs related to each test case just by navigating to the test case in the test result in WebStorm IDE (at least WebStorm is able to do this somehow). But Jest uses a vm isolation to run tests. Calling vm.runInContext has caveats, though, that the built-in classes are not the same, so the instanceof does not work for them, but there is a workaround.

I've thought about this some more and I think we should support patching Console such that we can intercept logs and associate them with the correct test in the output.

The second-order function stdout2diag below is a workaround/hack that effects such patching (though it patches process.stdout.write not console for a more complete solution). The hoped-for native solution would pass it on as a "test:stdout" event rather than "test:diagnostic" as I do here.

stdout2diag.ts:

import type {TestFn, TestContext} from 'node:test'
import logInterceptor from 'log-interceptor'

export function stdout2diag(fn: TestFn): TestFn {
    return async (t: TestContext) => {
        logInterceptor() // capture all stdout writes

        const r = fn(t)
        if (r instanceof Promise) {
            await r
        }

        const log = logInterceptor.end() as string[]
        if (log.length > 0) {
            // push as diagnostic event, which node:test does
            // associate with the owning test context 
            t.diagnostic('stdout: ' + log.join('\n'))
        }
    }
}

Below is the output of node --test for the three test files and test target given further below.

Because SuiteContext does not have TestContext's diagnostic method, I can't apply stdout2diag to suites and thus the report for B.test.ts is non-optimal. For C.test.ts, I replaced B's the suite-suite-test-subtest tree with an identical test-subtest-subtest-subtest tree. Note the report difference. I think for the hoped-for native solution, the reports for B and C should be identical. (It does make me wonder why SuiteContext does not support diagnostic, or even other TestContext elements such as fullname, runOnly, skip and todo.)

Also, I would expect most reporters to only print stdout and diagnostics for failed nodes, and think the built-in reporters should behave that way.

✔ A1 test (0.654125ms)
ℹ stdout: A1 test message

✔ A2 test (0.058625ms)
ℹ stdout: A2 test message

A1 test async message
A2 test async message
B main suite message
B nested suite message
▶ B main suite
  ▶ B nested suite
    ▶ B doubly nested test
      ✔ B triply nested test (0.284417ms)
      ℹ stdout: B triply nested test message

    ✔ B doubly nested test (0.892042ms)
    ℹ stdout: B doubly nested test message

  ✔ B nested suite (1.036292ms)
  ✔ B nested test (0.058ms)
  ℹ stdout: B nested test message

✔ B main suite (1.284333ms)
✔ B unnested test (0.061416ms)
ℹ stdout: B unnested test message

B main suite async message
B nested suite async message
B doubly nested test async message
B triply nested test async message
B nested test async message
B unnested test async message
▶ C main suite
  ▶ C nested suite
    ▶ C doubly nested test
      ✔ C triply nested test (0.355458ms)
      ℹ stdout: C triply nested test message

    ✔ C doubly nested test (0.578125ms)
    ℹ stdout: C doubly nested test message

  ✔ C nested suite (0.680209ms)
  ℹ stdout: C nested suite message

  ✔ C nested test (0.057708ms)
  ℹ stdout: C nested test message

✔ C main suite (1.301333ms)
ℹ stdout: C main suite message

✔ C unnested test (0.055666ms)
ℹ stdout: C unnested test message

C main suite async message
C nested suite async message
C doubly nested test async message
C triply nested test async message
C nested test async message
C unnested test async message
ℹ tests 12
ℹ suites 2
ℹ pass 12
ℹ fail 0
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 1087.747375

A.test.ts:

import {foo} from './foo.ts'
import {test} from 'node:test'
import {stdout2diag} from './stdout2diag.ts'

test('A1 test', stdout2diag(() => {
    foo('A1 test')
}))

test('A2 test', stdout2diag(() => {
    foo('A2 test')
}))

B.test.ts:

import {foo} from './foo.ts'
import {test, suite, type TestContext} from 'node:test'
import {stdout2diag} from './stdout2diag.ts'

suite('B main suite', () => {
    foo('B main suite')
    suite('B nested suite', () => {
        foo('B nested suite')
        test('B doubly nested test', stdout2diag((t: TestContext) => {
            foo('B doubly nested test')
            t.test('B triply nested test', stdout2diag(() => {
                foo('B triply nested test')
            }))
        }))
    })

    test('B nested test', stdout2diag(() => {
        foo('B nested test')
    }))
})

test('B unnested test', stdout2diag(async () => {
    foo('B unnested test')
}))

C.test.ts:

import {foo} from './foo.ts'
import {test, type TestContext} from 'node:test'
import {stdout2diag} from './stdout2diag.ts'

test('C main suite', stdout2diag((t: TestContext) => {
    foo('C main suite')
    t.test('C nested suite', stdout2diag((t: TestContext) => {
        foo('C nested suite')
        t.test('C doubly nested test', stdout2diag((t: TestContext) => {
            foo('C doubly nested test')
            t.test('C triply nested test', stdout2diag(() => {
                foo('C triply nested test')
            }))
        }))
    }))

    t.test('C nested test', stdout2diag(() => {
        foo('C nested test')
    }))
}))

test('C unnested test', stdout2diag(async () => {
    foo('C unnested test')
}))

foo.ts:

export function foo(name: string) {
    console.log(name + ' message')

    setTimeout(() => {
        console.log(name + ' async message')
    }, 1000)
}

This isnt a bug. if you need output assosiated with a specific test use test.diagnostic

@MoLow

@MoLow that isn't possible for code being tested, e.g. the function foo in my example. And as I mentioned SuiteContext does not support diagnostic messages.

Other test frameworks support filtering stdout to test failures only, either directly or thru plugins, e.g. mocha-suppress-logs.

ViTest: vitest-dev/vitest#7530 which closed vitest-dev/vitest#6272.

The ability to link output to test cases is fundamental feature for test frameworks, especially when having larger test base where tests are run in parallel. Either built-in or with a library, that is not important. But I think the absence of this feature is a no-go for many teams, including ours.

So if fixing this will lead to the final goal of being able to link output to test cases, please fix it. Thanks for reopening this.

This comment from a Node TSC discussion about the use of node:test seems relevant:

IIUC if the tests cases are async and you console.log() in them, the logs would be mixed up when there are multiple test cases logging. It encourage a test pattern where one has to comment stuff out of the test to get any meaningful logs, which makes working on test failures harder and is not always practical e.g. when trying to decypher logs in the CI especially when investigating old flakes.

#56027 (comment)

Relevant, but doesn't really contribute anything here. I proposed a solution in #53103 (comment). Someone just needs to try implementing it.

This issue has been marked as stale due to 90 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.

this has been categorized as high impact. see above.

test_runner: report console output as test events

Navigation Menu

Repository navigation

`node:test` custom reporters get `test:stdout` and `test:stderr` events before `test:dequeue` #53103

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior? Why is that the expected behavior?

What do you see instead?

Additional information

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

node:test custom reporters get test:stdout and test:stderr events before test:dequeue #53103

Description

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior? Why is that the expected behavior?

What do you see instead?

Additional information

Activity

alcuadrado commented on May 22, 2024

avivkeller commented on May 22, 2024

cjihrig commented on May 22, 2024

alcuadrado commented on May 22, 2024

alcuadrado commented on May 22, 2024

cjihrig commented on May 22, 2024

cjihrig commented on May 22, 2024

alcuadrado commented on May 22, 2024

cjihrig commented on May 23, 2024

cjihrig commented on Mar 7, 2025

MoLow commented on Mar 9, 2025

alcuadrado commented on Apr 7, 2025

oldium commented on Apr 13, 2025

vassudanagunta commented on Jul 26, 2025

MoLow commented on Aug 11, 2025

vassudanagunta commented on Aug 11, 2025

vassudanagunta commented on Aug 11, 2025

oldium commented on Aug 12, 2025

vassudanagunta commented on Mar 6, 2026

cjihrig commented on Mar 6, 2026

github-actions commented on Jul 20, 2026

vassudanagunta commented on Jul 20, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

`node:test` custom reporters get `test:stdout` and `test:stderr` events before `test:dequeue` #53103