Built-in test module only report ouput of the first top level describe

[piranna]

Version

v19.4.0

Platform

Linux AVRAST1790 5.19.0-30-generic #31-Ubuntu SMP PREEMPT_DYNAMIC Fri Jan 6 15:40:20 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

test

What steps will reproduce the bug?

On a test file with multiple top level describe, report output only show the first one of them that got run. Any other describe gets no reported nor counted, both passing or failing. In fact, final report don't provide correct statistics at all:

TAP version 13
# Subtest: /home/piranna/Trabajo/Avrioc/EsDiPi/test/cli.js
    # longestStatic:  36
    # length:  85917
    # Subtest: clean-sdp
    ok 1 - clean-sdp # SKIP
      ---
      duration_ms: 2.336453
      ...
    # Subtest: compress
    ok 2 - compress # SKIP
      ---
      duration_ms: 0.057482
      ...
    # Subtest: empty esdipi
    ok 3 - empty esdipi
      ---
      duration_ms: 5.970628
      ...
    # Subtest: Offer esdipi
    ok 4 - Offer esdipi
      ---
      duration_ms: 21.166008
      ...
    # Subtest: Answer esdipi
    ok 5 - Answer esdipi
      ---
      duration_ms: 9.956793
      ...
    1..8
ok 1 - /home/piranna/Trabajo/Avrioc/EsDiPi/test/cli.js
  ---
  duration_ms: 104.264871
  ...
1..1
# tests 1
# pass 1
# fail 0
# cancelled 0
# skipped 0
# todo 0
# duration_ms 106.675893

It should be showing 11 total tests, passing 4 (3 from "empty esdipi" describe and another top level one not shown), 6 skipped ones from the "clean-sdp" and "compress" describes, and 1 failed top level one not shown.

If there are other skipped describes, they are shown as skipped, but there's no info of any other describe or test defined it. In fact, if I have tests after that describe, they get run (checked with c8 coverage, code being tested by that tests gets covered) but their status is not reported at all, both failed or sucessful. If I move one of that test that's passing to be executed before the describes, lefting one test that's failing to execute after the describes, then the first test and all the describes (including the skipped ones) fails with the next error and don't get executed at all:

   not ok 2 - clean-sdp # SKIP
       ---
      duration_ms: 0
      failureType: 'cancelledByParent'
      error: 'Promise resolution is still pending but the event loop has already resolved'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        process.emit (node:events:512:28)
      ...

It seems like the test module has been tested or is more indented to have a single top level describe or test entry, not allowing to have several ones.

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

Always.

What is the expected behavior?

All describes and tests are being executed and reported, both passing and failing ones, no matter of their order of if they are inside describe / sub-tests.

What do you see instead?

Only first describe / sub-test is being reported, any other top level test or describe are excluded from reports.

Additional information

It seems there are several inter-related errors on this issue.

[MoLow]

please include the file you are running and the cli command

[piranna]

please include the file you are running and the cli command

I have uploaded my project to https://github.com/piranna/ESDiPi, and the actual file with the tests are at https://github.com/piranna/ESDiPi/blob/main/test/cli.js, you can play with them reordering or skipping them and will have the same behaviour I have. Module itself is working properly, so tests should not give you problems, just only the Node.js test tests runner module.

[MoLow]

@piranna the issue is the usage of describe with test. describe is supposed to be used with it only - which I hope will be fixed/changed,
but in the meanwhile you can change you code from test to it

[piranna]

@piranna the issue is the usage of describe with test. describe is supposed to be used with it only - which I hope will be fixed/changed,

Aren't they aliases between them? At least it's the feel it gives on the docs (not that it says it, it's just a feeling) and the same for describe()...

[MoLow]

Aren't they aliases between them? At least it's the feel it gives on the docs (not that it says it, it's just a feeling) and the same for describe()...

they are not aliases, but I agree it is a fair expectation for test to work the same way it does, thus I opened a PR to change the behavior #46544

[piranna]

thus I opened a PR to change the behavior #46544

Thank you :-)

[piranna]

thus I opened a PR to change the behavior #46544

Thank you :-)

[piranna]

in the meanwhile you can change you code from test to it

I confirm that with it instead of test, all tests and describes runned :-) Just only, the global metrics are still wrong:

TAP version 13
# Subtest: /home/piranna/Trabajo/Avrioc/ESDiPi/test/cli.js
    # Subtest: clean-sdp
        # Subtest: empty SDP
        ok 1 - empty SDP
          ---
          duration_ms: 6.303494
          ...
        # Subtest: Offer SDP
        ok 2 - Offer SDP
          ---
          duration_ms: 12.954568
          ...
        # Subtest: Answer SDP
        ok 3 - Answer SDP
          ---
          duration_ms: 5.798613
          ...
        1..3
    ok 1 - clean-sdp
      ---
      duration_ms: 26.163698
      ...
    # Subtest: compress
        # Subtest: empty SDP
        ok 1 - empty SDP
          ---
          duration_ms: 0.579423
          ...
        # Subtest: Offer SDP
        ok 2 - Offer SDP
          ---
          duration_ms: 74.314906
          ...
        # Subtest: Answer SDP
        ok 3 - Answer SDP
          ---
          duration_ms: 54.413326
          ...
        1..3
    ok 2 - compress
      ---
      duration_ms: 129.464455
      ...
    # Subtest: decompress
        # Subtest: empty esdipi
        ok 1 - empty esdipi
          ---
          duration_ms: 1.232121
          ...
        # Subtest: Offer esdipi
        ok 2 - Offer esdipi
          ---
          duration_ms: 8.018468
          ...
        # Subtest: Answer esdipi
        ok 3 - Answer esdipi
          ---
          duration_ms: 7.692408
          ...
        1..3
    ok 3 - decompress
      ---
      duration_ms: 17.10319
      ...
    # Subtest: prefix
    not ok 4 - prefix
      ---
      duration_ms: 0.843434
      failureType: 'cancelledByParent'
      error: 'Promise resolution is still pending but the event loop has already resolved'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        process.emit (node:events:512:28)
      ...
    # Subtest: unknown command
    not ok 5 - unknown command
      ---
      duration_ms: 0
      failureType: 'cancelledByParent'
      error: 'Promise resolution is still pending but the event loop has already resolved'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        process.emit (node:events:512:28)
      ...
    1..5
not ok 1 - /home/piranna/Trabajo/Avrioc/ESDiPi/test/cli.js
  ---
  duration_ms: 238.9463
  failureType: 'subtestsFailed'
  exitCode: 1
  error: 'test failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1
# tests 1
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 243.316294

I think with these tests output report they should be

# tests 11
# pass 9
# fail 0
# cancelled 2
# skipped 0
# todo 0

Maybe that should be another issue?

[cjihrig]

Maybe that should be another issue?

That's being handled in #46440.

[piranna]

That's being handled in #46440.

Cool, thank you for the pointer :-)