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