test_runner: run global after() hook earlier

[cjihrig]

This commit moves the global after() hook execution from the 'beforeExit' event to the point where all tests have finished running. This gives the global after() a chance to clean up handles that would otherwise prevent the 'beforeExit' event from being emitted.

Fixes: #49056

[nodejs-github-bot]

Review requested:

• @nodejs/test_runner

[MoLow]

can you please also add this test? https://github.com/MoLow/node/blob/test-runner-only/test/fixtures/test-runner/output/async-test-scheduling.mjs

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/53154/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/53159/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/53164/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/53165/ 🟡

[atlowChemi]

@cjihrig would it be worth ensuring the after hook also waits for cb?

Suggested change

	server.close();
	server.close(common.mustCall());

[cjihrig]

That's not a bad idea. Honestly though, the CI was a pain to get passing yesterday and I would prefer not to start over for that change.

[mcollina]

lgtm

[nodejs-github-bot]

Commit Queue failed

- Loading data for nodejs/node/pull/49059 ✔ Done loading data for nodejs/node/pull/49059 ----------------------------------- PR info ------------------------------------ Title test_runner: run global after() hook earlier (#49059) Author Colin Ihrig (@cjihrig) Branch cjihrig:after-handles -> nodejs:main Labels commit-queue-squash, test_runner Commits 3 - test_runner: run global after() hook earlier - test and feedback - other test Committers 1 - cjihrig PR-URL: https://github.com/nodejs/node/pull/49059 Fixes: https://github.com/nodejs/node/issues/49056 Reviewed-By: Chemi Atlow Reviewed-By: Moshe Atlow Reviewed-By: Matteo Collina Reviewed-By: Benjamin Gruenbaum ------------------------------ Generated metadata ------------------------------ PR-URL: https://github.com/nodejs/node/pull/49059 Fixes: https://github.com/nodejs/node/issues/49056 Reviewed-By: Chemi Atlow Reviewed-By: Moshe Atlow Reviewed-By: Matteo Collina Reviewed-By: Benjamin Gruenbaum -------------------------------------------------------------------------------- ℹ This PR was created on Mon, 07 Aug 2023 22:03:17 GMT ✔ Approvals: 4 ✔ - Chemi Atlow (@atlowChemi): https://github.com/nodejs/node/pull/49059#pullrequestreview-1573038132 ✔ - Moshe Atlow (@MoLow) (TSC): https://github.com/nodejs/node/pull/49059#pullrequestreview-1573061500 ✔ - Matteo Collina (@mcollina) (TSC): https://github.com/nodejs/node/pull/49059#pullrequestreview-1573130592 ✔ - Benjamin Gruenbaum (@benjamingr) (TSC): https://github.com/nodejs/node/pull/49059#pullrequestreview-1573170558 ✘ Last GitHub CI failed ℹ Last Full PR CI on 2023-08-11T03:28:19Z: https://ci.nodejs.org/job/node-test-pull-request/53165/ - Querying data for job/node-test-pull-request/53165/ ✔ Last Jenkins CI successful -------------------------------------------------------------------------------- ✔ Aborted `git node land` session in /home/runner/work/node/node/.ncu

https://github.com/nodejs/node/actions/runs/5832906334

[cjihrig]

Landed in 6346bdc.

[joyeecheung]

Not sure why but I am now constantly failing test-runner-output.mjs locally after pulling in this change. It passed again if I revert this commit.

See stack trace

▶ test runner output ✔ test-runner/output/abort.js (1080.035875ms) ✔ test-runner/output/abort_suite.js (1100.539375ms) ✔ test-runner/output/abort_hooks.js (170.884375ms) ✔ test-runner/output/describe_it.js (725.507334ms) ✔ test-runner/output/describe_nested.js (119.515875ms) ✔ test-runner/output/hooks.js (177.523667ms) ✔ test-runner/output/timeout_in_before_each_should_not_affect_further_tests.js (1320.205417ms) ✔ test-runner/output/hooks-with-no-global-test.js (168.12325ms) ✔ test-runner/output/before-and-after-each-too-many-listeners.js (164.051292ms) ✔ test-runner/output/before-and-after-each-with-timeout-too-many-listeners.js (165.916292ms) ✖ test-runner/output/global_after_should_fail_the_test.js (171.50075ms) AssertionError [ERR_ASSERTION]: Expected values to be strictly equal: + actual - expected ... Lines skipped 'this is a test\n' + 'TAP version 13\n' + ... ' ---\n' + ' duration_ms: *\n' + - ' ...\n' + - 'not ok 2 - /test/fixtures/test-runner/output/global_after_should_fail_the_test.js\n' + - ' ---\n' + - ' duration_ms: *\n' + - " location: '/test/fixtures/test-runner/output/global_after_should_fail_the_test.js:(LINE):1'\n" + - " failureType: 'hookFailed'\n" + - " error: 'this should fail the test'\n" + - " code: 'ERR_TEST_FAILURE'\n" + - ' stack: |-\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + ' ...\n' + ... '# skipped 0\n' + '# todo 0\n' + '# duration_ms *\n' at assertSnapshot (/Users/joyee/projects/node/test/common/assertSnapshot.js:52:12) at async Module.spawnAndAssert (/Users/joyee/projects/node/test/common/assertSnapshot.js:80:3) at async TestContext.<anonymous> (file:///Users/joyee/projects/node/test/parallel/test-runner-output.mjs:95:5) at async Test.run (node:internal/test_runner/test:632:9) at async Promise.all (index 10) at async Suite.run (node:internal/test_runner/test:948:7) at async startSubtest (node:internal/test_runner/harness:208:3){generatedMessage: true, code: 'ERR_ASSERTION', actual: 'this is a test\nTAP version 13\n# Subtest: this is a test\nok 1 - this is a test\n ---\n duration_ms: *\n ...\n1..1\n# tests 1\n# suites 0\n...', expected: 'this is a test\nTAP version 13\n# Subtest: this is a test\nok 1 - this is a test\n ---\n duration_ms: *\n ...\nnot ok 2 - /test/fixtures/test-runner/output/global_after_should_fail_the_test.js\n ---\n duration_ms: *\n...', operator: 'strictEqual' } ✔ test-runner/output/no_refs.js (149.993708ms) ✔ test-runner/output/no_tests.js (154.464834ms) ✔ test-runner/output/only_tests.js (169.572709ms) ✔ test-runner/output/dot_reporter.js (620.084375ms) ✔ test-runner/output/spec_reporter_successful.js (159.8035ms) ✔ test-runner/output/spec_reporter.js (625.975708ms) ✔ test-runner/output/spec_reporter_cli.js (663.377458ms) ✔ test-runner/output/output.js (541.202459ms) ✔ test-runner/output/output_cli.js (620.8815ms) ✔ test-runner/output/name_pattern.js (121.049417ms) ✔ test-runner/output/name_pattern_with_only.js (148.999583ms) ✔ test-runner/output/unresolved_promise.js (154.180542ms) ✔ test-runner/output/default_output.js (201.822875ms) ✔ test-runner/output/arbitrary-output.js (182.5105ms) ✔ test-runner/output/async-test-scheduling.mjs (156.54525ms) ✔ test-runner/output/arbitrary-output-colored.js (342.718166ms) ✔ test-runner/output/dot_output_custom_columns.js (207.744791ms) ✔ test-runner/output/tap_escape.js (130.406458ms) ▶ test runner output (1326.1695ms) ℹ tests 29 ℹ suites 1 ℹ pass 28 ℹ fail 1 ℹ cancelled 0 ℹ skipped 0 ℹ todo 0 ℹ duration_ms 1328.780583 ✖ failing tests: test at file:/Users/joyee/projects/node/test/parallel/test-runner-output.mjs:101:5 ✖ test-runner/output/global_after_should_fail_the_test.js (171.50075ms) AssertionError [ERR_ASSERTION]: Expected values to be strictly equal: + actual - expected ... Lines skipped 'this is a test\n' + 'TAP version 13\n' + ... ' ---\n' + ' duration_ms: *\n' + - ' ...\n' + - 'not ok 2 - /test/fixtures/test-runner/output/global_after_should_fail_the_test.js\n' + - ' ---\n' + - ' duration_ms: *\n' + - " location: '/test/fixtures/test-runner/output/global_after_should_fail_the_test.js:(LINE):1'\n" + - " failureType: 'hookFailed'\n" + - " error: 'this should fail the test'\n" + - " code: 'ERR_TEST_FAILURE'\n" + - ' stack: |-\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + - ' *\n' + ' ...\n' + ... '# skipped 0\n' + '# todo 0\n' + '# duration_ms *\n' at assertSnapshot (/Users/joyee/projects/node/test/common/assertSnapshot.js:52:12) at async Module.spawnAndAssert (/Users/joyee/projects/node/test/common/assertSnapshot.js:80:3) at async TestContext.<anonymous> (file:///Users/joyee/projects/node/test/parallel/test-runner-output.mjs:95:5) at async Test.run (node:internal/test_runner/test:632:9) at async Promise.all (index 10) at async Suite.run (node:internal/test_runner/test:948:7) at async startSubtest (node:internal/test_runner/harness:208:3){generatedMessage: true, code: 'ERR_ASSERTION', actual: 'this is a test\nTAP version 13\n# Subtest: this is a test\nok 1 - this is a test\n ---\n duration_ms: *\n ...\n1..1\n# tests 1\n# suites 0\n...', expected: 'this is a test\nTAP version 13\n# Subtest: this is a test\nok 1 - this is a test\n ---\n duration_ms: *\n ...\nnot ok 2 - /test/fixtures/test-runner/output/global_after_should_fail_the_test.js\n ---\n duration_ms: *\n...', operator: 'strictEqual' } 

I am on Apple M2 Max with macOS 13.4 though not sure how relevant that is.

[cjihrig]

FWIW, here is the fix before the revert:

diff --git a/lib/internal/test_runner/test.js b/lib/internal/test_runner/test.js index f8c9087f6c..975ad4ac08 100644 --- a/lib/internal/test_runner/test.js+++ b/lib/internal/test_runner/test.js@@ -662,7 +662,7 @@ class Test extends AsyncResource{} } - if (this.parent !== null){+ if (this.parent !== null || typeof this.hookType === 'string'){ // Clean up the test. Then, try to report the results and execute any // tests that were pending due to available concurrency. //