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

[alcuadrado]

trafficstars

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

[alcuadrado]

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

[avivkeller]

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?

[cjihrig]

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.

[alcuadrado]

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.

[alcuadrado]

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.

[cjihrig]

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.

[cjihrig]

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)

[alcuadrado]

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

[cjihrig]

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.

[cjihrig]

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.

[MoLow]

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

[alcuadrado]

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.

[oldium]

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.