test:start events are not emitted correctly

[connor4312]

Version

21.6.2

Platform

windows x64

Subsystem

test_runner

What steps will reproduce the bug?

1. Have a test file like

test.js

const { describe, it } = require('node:test');
const { strictEqual } = require('node:assert');

describe('math', () => {
  it('addition', async () => {
    await new Promise((resolve) => setTimeout(resolve, 5000));
    strictEqual(1 + 1, 2);
  });

  it(`subtraction`, async () => {
    strictEqual(1 - 1, 0);
  });
});

and a reporter.js

module.exports = async function* reporter(stream) {
  for await (const evt of stream) {
    console.log(new Date().toISOString(), evt.type, evt.data);
  }
};

2. Run node --test-reporter=./reporter.js test.js

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

100%

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

test:start should be fired before math addition is run

What do you see instead?

test:start is fired only after the test finishes. Here's an example log, notice that test:started is fired only after the 5 second delay, which is in fact after the tests already finished.

log.txt

Additional information

I originally requested this in #46727 which resulted in test:queued and test:dequeued events being added. (Maybe this should be titled instead a general "I (still) cannot tell when a test is started")

However these are not useful because the tests are just enqueued event when they're not running: subtraction is enqueued alongside addition and based on the results it 'takes' 5 seconds to run, but in reality is instant.

[connor4312]

I looked into enqueue and dequeue a bit more. I thought I could use them and just say "the top of the queue is currently running", but it that doesn't work with a more complex case. Take a file like:

  describe('math', () => {
    it('addition', async () => {
      await new Promise((resolve) => setTimeout(resolve, 5000));
      strictEqual(1 + 1, 2);
    });

    it(`subtraction`, async () => {
      strictEqual(1 - 1, 0);
    });
  });
  describe('math2', () => {
    it('addition', async () => {
      await new Promise((resolve) => setTimeout(resolve, 5000));
      strictEqual(1 + 1, 2);
    });

    it(`subtraction`, async () => {
      strictEqual(1 - 1, 0);
    });
  });

The order of enqueues and dequeues seems pretty inscrutable. I was hoping it would be an order of enqueues and dequeues matching how they're declared in the file, but this isn't the case. For example the test cases inside math are enqueued while math2 is on the 'stack', so I have no idea how a consumer would be able to interpret them as there's no "parent pointer". Is this a separate bug?

2024-02-28T05:37:52.974Z test:enqueue {"nesting":0,"name":"math","line":4,"column":1,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:52.975Z test:dequeue {"nesting":0,"name":"math","line":4,"column":1,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:52.975Z test:enqueue {"nesting":0,"name":"math2","line":15,"column":1,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:52.975Z test:enqueue {"nesting":1,"name":"addition","line":5,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:52.975Z test:dequeue {"nesting":1,"name":"addition","line":5,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:52.976Z test:enqueue {"nesting":1,"name":"subtraction","line":10,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:57.977Z test:dequeue {"nesting":1,"name":"subtraction","line":10,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:57.978Z test:dequeue {"nesting":0,"name":"math2","line":15,"column":1,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:57.978Z test:enqueue {"nesting":1,"name":"addition","line":16,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:57.978Z test:dequeue {"nesting":1,"name":"addition","line":16,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:37:57.978Z test:enqueue {"nesting":1,"name":"subtraction","line":21,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}
2024-02-28T05:38:02.991Z test:dequeue {"nesting":1,"name":"subtraction","line":21,"column":3,"file":"C:\\Users\\conno\\Downloads\\repo\\test.js"}

[rluvaton]

Thanks for opening the issue. I'll try to take a look later this week

[MoLow]

@connor4312 I am not sure what is the bug here
it might help to mention that there is not a single stack - each suite/test manages its own subtests queue. (since each each suite can have different concurrency).
this means that when there is a concurrency of 1/ no concurrency, the tests run in bfs order

[MoLow]

the timing of different events are:
test:enqueue: emitted the first time the test is seen/encountered
test:dequeue: emitted once the test is removed from the queue and starts running
test:start: this is indeed a bit confusing - the test runner internally enforces the order of test:start events to be fired in the order the tests were declared in code, so this can indeed fire after a test has been completed. if you want to know when the test has actually started use test:dequeue
test:pass/test:fail: same here. this is enforced to run in the order of declaration so it will fire when completed AND all tests declared before the emitted one are completed

the reason the events are designed this way is there was originally only the tap reporter which needed things in order (and it is convenient for other reporters to not have to maintain the order themselves).
unfortunately, it will be a breaking change to rename these events but we can and should do the following

• add an event fired immediately when the test completes
• improve the documentation for the events that are reported in order of declaration (test:start, test:plan, test:pass, test:fail, test:diagnostic), which arent (test:enqueue,test:dequeue), and distinguish which events to use when you want them ordered, and which events to use when you want them immediate

@connor4312 will these items resolve your issue?

[connor4312]

Ahh, I see! The dequeued events makes sense now. It looks like the order is also preserved even when tests run in parallel, so I think that would solve my use case.

add an event fired immediately when the test completes

This would be a nice to have just to report results more quickly to users.

improve the documentation for the events that are reported in order of declaration

This would be handy!

I'll play with these some more this evening and close out the issue unless I run into any further difficulty 🙂

[electerious]

@MoLow Thanks for the explanation. Naming and execution of these events is highly confusing.

I think it's also worth mentioning that you can listen for test:dequeue. Yes, it will run before the test executes and the event can also contain async code, but the test won't wait for the event listener to finish. Upcoming tests will continue to run in the background and you might not be aware of it, because 'test:stderr' logs are delayed.

If you need logging in real-time, because you want to debug timing-sensitive code, then Node.js Tests aren't a solution, because execution and events/logging might not be in sync.