Repository navigation
test:start events are not emitted correctly #51907
Description
Activity
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
mathare enqueued whilemath2is 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"}Thanks for opening the issue. I'll try to take a look later this week
@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 orderthe 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 oftest:startevents 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 usetest: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 completedthe 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?
Reacted by Tobias ReichAhh, 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 🙂
- added a commit that references this issue
on Mar 1, 2024 - added a commit that references this issue
on May 2, 2024 @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.
Version
21.6.2
Platform
windows x64
Subsystem
test_runner
What steps will reproduce the bug?
test.js
and a reporter.js
node --test-reporter=./reporter.js test.jsHow often does it reproduce? Is there a required condition?
100%
What is the expected behavior? Why is that the expected behavior?
test:startshould be fired beforemath additionis runWhat do you see instead?
test:startis 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:
subtractionis enqueued alongsideadditionand based on the results it 'takes' 5 seconds to run, but in reality is instant.