parallel/test-runner-output is flaky

[joyeecheung]

Test

parallel/test-runner-output

Platform

everywhere

Console output

see output

00:08:02 not ok 2637 parallel/test-runner-output
00:08:02 ---
00:08:02 duration_ms: 4127.06600
00:08:02 severity: fail
00:08:02 exitcode: 1
00:08:02 stack: |-
00:08:02 TAP version 13
00:08:02 # Subtest: test runner output
00:08:02 # Subtest: test-runner/output/abort.js
00:08:02 ok 1 - test-runner/output/abort.js
00:08:02 ---
00:08:02 duration_ms: 1434.181734
00:08:02 ...
00:08:02 # Subtest: test-runner/output/abort_suite.js
00:08:02 not ok 2 - test-runner/output/abort_suite.js
00:08:02 ---
00:08:02 duration_ms: 1811.835637
00:08:02 location: 'file:///home/iojs/build/workspace/node-test-commit-custom-suites-freestyle/test/parallel/test-runner-output.mjs:118:5'
00:08:02 failureType: 'testCodeFailure'
00:08:02 error: |-
00:08:02 Expected values to be strictly equal:
00:08:02 + actual - expected ... Lines skipped
00:08:02 
00:08:02 'TAP version 13\n' +
00:08:02 '# Subtest: describe timeout signal\n' +
00:08:02 ...
00:08:02 'not ok 2 - describe abort signal\n' +
00:08:02 ' ---\n' +
00:08:02 + ' duration_ms: ZERO\n' +
00:08:02 - ' duration_ms: *\n' +
00:08:02 " type: 'suite'\n" +
00:08:02 ...
00:08:02 '# skipped 0\n' +
00:08:02 '# todo 0\n' +
00:08:02 '# duration_ms *\n'
00:08:02 code: 'ERR_ASSERTION'
00:08:02 name: 'AssertionError'
00:08:02 expected: |-
00:08:02 TAP version 13
00:08:02 # Subtest: describe timeout signal
00:08:02 # Subtest: ok 1
00:08:02 ok 1 - ok 1
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 2
00:08:02 ok 2 - ok 2
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 3
00:08:02 ok 3 - ok 3
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 4
00:08:02 ok 4 - ok 4
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: not ok 1
00:08:02 not ok 5 - not ok 1
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'cancelledByParent'
00:08:02 error: 'test did not finish before its parent and was cancelled'
00:08:02 code: 'ERR_TEST_FAILURE'
00:08:02 ...
00:08:02 # Subtest: not ok 2
00:08:02 not ok 6 - not ok 2
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'cancelledByParent'
00:08:02 error: 'test did not finish before its parent and was cancelled'
00:08:02 code: 'ERR_TEST_FAILURE'
00:08:02 ...
00:08:02 # Subtest: not ok 3
00:08:02 not ok 7 - not ok 3
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: not ok 4
00:08:02 not ok 8 - not ok 4
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: not ok 5
00:08:02 not ok 9 - not ok 5
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 1..9
00:08:02 not ok 1 - describe timeout signal
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 type: 'suite'
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):1'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'The operation was aborted due to timeout'
00:08:02 code: 23
00:08:02 name: 'TimeoutError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: describe abort signal
00:08:02 not ok 2 - describe abort signal
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 type: 'suite'
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):1'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 1..2
00:08:02 # tests 9
00:08:02 # suites 2
00:08:02 # pass 4
00:08:02 # fail 0
00:08:02 # cancelled 5
00:08:02 # skipped 0
00:08:02 # todo 0
00:08:02 # duration_ms *
00:08:02 
00:08:02 actual: |-
00:08:02 TAP version 13
00:08:02 # Subtest: describe timeout signal
00:08:02 # Subtest: ok 1
00:08:02 ok 1 - ok 1
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 2
00:08:02 ok 2 - ok 2
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 3
00:08:02 ok 3 - ok 3
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: ok 4
00:08:02 ok 4 - ok 4
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 ...
00:08:02 # Subtest: not ok 1
00:08:02 not ok 5 - not ok 1
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'cancelledByParent'
00:08:02 error: 'test did not finish before its parent and was cancelled'
00:08:02 code: 'ERR_TEST_FAILURE'
00:08:02 ...
00:08:02 # Subtest: not ok 2
00:08:02 not ok 6 - not ok 2
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'cancelledByParent'
00:08:02 error: 'test did not finish before its parent and was cancelled'
00:08:02 code: 'ERR_TEST_FAILURE'
00:08:02 ...
00:08:02 # Subtest: not ok 3
00:08:02 not ok 7 - not ok 3
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: not ok 4
00:08:02 not ok 8 - not ok 4
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: not ok 5
00:08:02 not ok 9 - not ok 5
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):3'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 1..9
00:08:02 not ok 1 - describe timeout signal
00:08:02 ---
00:08:02 duration_ms: *
00:08:02 type: 'suite'
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):1'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'The operation was aborted due to timeout'
00:08:02 code: 23
00:08:02 name: 'TimeoutError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 # Subtest: describe abort signal
00:08:02 not ok 2 - describe abort signal
00:08:02 ---
00:08:02 duration_ms: ZERO
00:08:02 type: 'suite'
00:08:02 location: '/test/fixtures/test-runner/output/abort_suite.js:(LINE):1'
00:08:02 failureType: 'testAborted'
00:08:02 error: 'This operation was aborted'
00:08:02 code: 20
00:08:02 name: 'AbortError'
00:08:02 stack: |-
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 *
00:08:02 ...
00:08:02 1..2
00:08:02 # tests 9
00:08:02 # suites 2
00:08:02 # pass 4
00:08:02 # fail 0
00:08:02 # cancelled 5
00:08:02 # skipped 0
00:08:02 # todo 0
00:08:02 # duration_ms *
00:08:02 
00:08:02 operator: 'strictEqual'
00:08:02 stack: |-
00:08:02 assertSnapshot (/home/iojs/build/workspace/node-test-commit-custom-suites-freestyle/test/common/assertSnapshot.js:56:12)
00:08:02 async Module.spawnAndAssert (/home/iojs/build/workspace/node-test-commit-custom-suites-freestyle/test/common/assertSnapshot.js:84:3)
00:08:02 async TestContext.<anonymous> (file:///home/iojs/build/workspace/node-test-commit-custom-suites-freestyle/test/parallel/test-runner-output.mjs:112:5)
00:08:02 async Test.run (node:internal/test_runner/test:632:9)
00:08:02 async Promise.all (index 1)
00:08:02 async Suite.run (node:internal/test_runner/test:948:7)
00:08:02 async startSubtest (node:internal/test_runner/harness:216:3)
00:08:02 ...

Build links

Reason	parallel/test-runner-output
Type	JS_TEST_FAILURE
Failed PR	3 (#48655, #49762, #49313)
Appeared	undefined, test-nearform-macos10.15-x64-3, test-softlayer-debian10-x64-1, test-digitalocean-fedora32-x64-1, test-digitalocean-fedora38-x64-1, test-ibm-rhel8-x64-3, test-osuosl-rhel8-ppc64_le-2, test-ibm-rhel8-s390x-1, test-equinix-ubuntu2004_sharedlibs_container-arm64-6, test-osuosl-aix72-ppc64_be-2, test-equinix-rhel8_container-arm64-2, test-equinix-ubuntu1804_sharedlibs_container-arm64-1, test-equinix-ubuntu2004_sharedlibs_container-arm64-4, test-macstadium-macos11.0-arm64-3, test-equinix-debian10_container-armv7l-2, test-equinix-ubuntu2004_container-armv7l-1, test-rackspace-win2012r2_vs2019-x64-1, test-rackspace-win2022_vs2022-x64-6, test-ibm-alpine315_container-x64-1, test-ibm-alpine318_container-x64-1, test-rackspace-fedora32-x64-1, test-digitalocean-rhel8-x64-1, test-equinix-ubuntu1804_container-arm64-2, test-digitalocean-ubi81_container-x64-2, test-ibm-rhel8-s390x-4, test-equinix-ubuntu2004_sharedlibs_container-arm64-3, test-rackspace-win2012r2_vs2015-x64-1, test-equinix-debian10_container-armv7l-1, test-equinix-ubuntu2004_container-armv7l-2, test-orka-macos10.15-x64-2, test-digitalocean-alpine315_container-x64-1, test-digitalocean-alpine318_container-x64-2, test-rackspace-debian10-x64-1, test-ibm-rhel8-x64-2, test-digitalocean-ubuntu1804-x64-1, test-equinix_mnx-smartos20-x64-4, test-equinix-rhel8_container-arm64-1, test-equinix-ubuntu2004_container-arm64-2, test-osuosl-ubuntu2004_container-armv7l-1, test-digitalocean-ubi81_container-x64-1, test-digitalocean-ubuntu1804_sharedlibs_container-x64-10, test-digitalocean-ubuntu1804_sharedlibs_container-x64-5, test-osuosl-aix72-ppc64_be-3, test-ibm-rhel8-s390x-2, test-nearform-macos11.0-arm64-1, test-osuosl-rhel8-ppc64_le-1, test-rackspace-win2012r2_vs2019-x64-2, test-rackspace-win2022_vs2022-x64-2, test-digitalocean-freebsd12-x64-2, test-digitalocean-fedora37-x64-1, test-orka-macos11-x64-1, test-digitalocean-ubuntu1804_sharedlibs_container-x64-3, test-digitalocean-ubuntu1804_sharedlibs_container-x64-2, test-digitalocean-ubuntu1804_sharedlibs_container-x64-8, test-equinix_mnx-smartos20-x64-3
First CI	https://ci.nodejs.org/job/node-test-pull-request/54130/
Last CI	https://ci.nodejs.org/job/node-test-pull-request/54184/

Additional information

This actually has been flaky for quite some time and fails on many different platforms. The latest report comes from nodejs/reliability#675. It looks like at least in the case shown here the duration should've duration_ms: * instead of duration_ms: ZERO. But there can be other kind of differences on other platforms.

[joyeecheung]

cc @nodejs/test_runner I think we should mark this and test-runner-watch-mode (#49605) as flaky for now since they've been flaking the CI for months

[joyeecheung]

The report listed in the OP contains a PR related to test runner. Here is another report from 3 days ago without PRs related to test runner: nodejs/reliability#673 (still many different platforms, so I'll just mark it as "flaky on all platforms")

[MoLow]

• regarding module: bootstrap module loaders in shadow realm #48655 - this PR introduces a bug causing tests duration being a negative time:

+ ' callback called twice in future tick (-*ms)\n' +
- ' callback called twice in future tick (*ms)\n' +

+ '\t<testsuite name="level 0a" time="-3.984146" disabled="0" errors="0" tests="4" failures="0" skipped="0" hostname="HOSTNAME">\n' +
+ '\t\t<testcase name="level 1a" time="-4.190686" classname="test"/>\n' +
- '\t<testsuite name="level 0a" time="*" disabled="0" errors="0" tests="4" failures="0" skipped="0" hostname="HOSTNAME">\n' +
- '\t\t<testcase name="level 1a" time="*" classname="test"/>\n' +

• regarding errors: improve performance of NodeError instantiation #49654 - this PR caused the stack trace of some errors reported by the test runner to break:

+ " code: 'ERR_TEST_FAILURE',\n" +
+ " failureType: 'testCodeFailure',\n" +
+ ' cause: Error: thrown from sync fail todo with message\n' +
- " failureType: 'testCodeFailure',\n" +
- ' cause: Error: thrown from sync fail todo with message\n' +
- ' *\n' +
 ' *\n' +
 ' *\n' +
 ' *\n' +
 ' *\n' +
 ' *\n' +
+ ' *\n' +
+ ' *\n' +
- ' at async Test.processPendingSubtests (node:internal/test_runner/test:374:7),\n' +
- " code: 'ERR_TEST_FAILURE'\n" +

• [v18.x backport] test_runner: add shards support #49762 had a bug causing all test runner tests to fail
• test,crypto: update WebCryptoAPI WPT #49714 and node-api: enable uncaught exceptions policy by default #49313 - have the issue described with ZERO replaced with *. I will go ahead and fix that