Skip to content

parallel/test-runner-output is flaky #49853

Closed
@joyeecheung

Description

@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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    flaky-testIssues and PRs related to the tests with unstable failures on the CI.test_runnerIssues and PRs related to the test runner subsystem.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions