test_runner: automatically wait for subtests to finish

This commit updates the test runner to automatically wait for
subtests to finish. This makes the experience more consistent
with suites and removes the need to await anything.

PR-URL: https://github.com/nodejs/node/pull/58800
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Pietro Marchini <pietro.marchini94@gmail.com>
Reviewed-By: Rafael Gonzaga <rafael.nunu@hotmail.com>

lib/internal/test_runner/harness.js

@@ -28,6 +28,8 @@ const {
   setupGlobalSetupTeardownFunctions,
 } = require('internal/test_runner/utils');
 const { queueMicrotask } = require('internal/process/task_queues');
+const { TIMEOUT_MAX } = require('internal/timers');
+const { clearInterval, setInterval } = require('timers');
 const { bigint: hrtime } = process.hrtime;
 const testResources = new SafeMap();
 let globalRoot;
@@ -228,11 +230,20 @@ function setupProcessState(root, globalOptions) {
   const rejectionHandler =
     createProcessEventHandler('unhandledRejection', root);
   const coverage = configureCoverage(root, globalOptions);
-  const exitHandler = async () => {
+  const exitHandler = async (kill) => {
     if (root.subtests.length === 0 && (root.hooks.before.length > 0 || root.hooks.after.length > 0)) {
       // Run global before/after hooks in case there are no tests
       await root.run();
     }
+
+    if (kill !== true && root.subtestsPromise !== null) {
+      // Wait for all subtests to finish, but keep the process alive in case
+      // there are no ref'ed handles left.
+      const keepAlive = setInterval(() => {}, TIMEOUT_MAX);
+      await root.subtestsPromise.promise;
+      clearInterval(keepAlive);
+    }
+
     root.postRun(new ERR_TEST_FAILURE(
       'Promise resolution is still pending but the event loop has already resolved',
       kCancelledByParent));
@@ -252,8 +263,8 @@ function setupProcessState(root, globalOptions) {
     }
   };
 
-  const terminationHandler = () => {
-    exitHandler();
+  const terminationHandler = async () => {
+    await exitHandler(true);
     process.exit();
   };
 

lib/internal/test_runner/test.js

@@ -651,6 +651,8 @@ class Test extends AsyncResource {
     this.activeSubtests = 0;
     this.pendingSubtests = [];
     this.readySubtests = new SafeMap();
+    this.unfinishedSubtests = new SafeSet();
+    this.subtestsPromise = null;
     this.subtests = [];
     this.waitingOn = 0;
     this.finished = false;
@@ -754,6 +756,11 @@ class Test extends AsyncResource {
 
   addReadySubtest(subtest) {
     this.readySubtests.set(subtest.childNumber, subtest);
+
+    if (this.unfinishedSubtests.delete(subtest) &&
+        this.unfinishedSubtests.size === 0) {
+      this.subtestsPromise.resolve();
+    }
   }
 
   processReadySubtestRange(canSend) {
@@ -815,6 +822,7 @@ class Test extends AsyncResource {
 
     if (parent.waitingOn === 0) {
       parent.waitingOn = test.childNumber;
+      parent.subtestsPromise = PromiseWithResolvers();
     }
 
     if (preventAddingSubtests) {
@@ -937,6 +945,7 @@ class Test extends AsyncResource {
     // If there is enough available concurrency to run the test now, then do
     // it. Otherwise, return a Promise to the caller and mark the test as
     // pending for later execution.
+    this.parent.unfinishedSubtests.add(this);
     this.reporter.enqueue(this.nesting, this.loc, this.name, this.reportedType);
     if (this.root.harness.buildPromise || !this.parent.hasConcurrency()) {
       const deferred = PromiseWithResolvers();
@@ -1061,6 +1070,10 @@ class Test extends AsyncResource {
 
       this[kShouldAbort]();
 
+      if (this.subtestsPromise !== null) {
+        await SafePromiseRace([this.subtestsPromise.promise, stopPromise]);
+      }
+
       if (this.plan !== null) {
         const planPromise = this.plan?.check();
         // If the plan returns a promise, it means that it is waiting for more assertions to be made before

test/fixtures/test-runner/output/default_output.snapshot

@@ -3,13 +3,13 @@
 [90m﹣ should skip [90m(*ms)[39m # SKIP[39m
 ▶ parent
   [31m✖ should fail [90m(*ms)[39m[39m
-  [31m✖ should pass but parent fail [90m(*ms)[39m[39m
+  [32m✔ should pass but parent fail [90m(*ms)[39m[39m
 [31m✖ parent [90m(*ms)[39m[39m
 [34mℹ tests 6[39m
 [34mℹ suites 0[39m
-[34mℹ pass 1[39m
+[34mℹ pass 2[39m
 [34mℹ fail 3[39m
-[34mℹ cancelled 1[39m
+[34mℹ cancelled 0[39m
 [34mℹ skipped 1[39m
 [34mℹ todo 0[39m
 [34mℹ duration_ms *[39m
@@ -40,7 +40,3 @@
   *[39m
   *[39m
   *[39m
-
-*
-[31m✖ should pass but parent fail [90m(*ms)[39m[39m
-  [32m'test did not finish before its parent and was cancelled'[39m

test/fixtures/test-runner/output/dot_reporter.snapshot

@@ -1,5 +1,5 @@
 ..XX...X..XXX.X.....
-XXX.....X..X...X....
+XXX............X....
 .....X...XXX.XX.....
 XXXXXXX...XXXXX
 
@@ -93,10 +93,6 @@ Failed tests:
   '1 subtest failed'
 ✖ sync throw non-error fail (*ms)
   Symbol(thrown symbol from sync throw non-error fail)
-✖ +long running (*ms)
-  'test did not finish before its parent and was cancelled'
-✖ top level (*ms)
-  '1 subtest failed'
 ✖ sync skip option is false fail (*ms)
   Error: this should be executed
       *

test/fixtures/test-runner/output/junit_reporter.snapshot

@@ -186,12 +186,8 @@ Error [ERR_TEST_FAILURE]: thrown from subtest sync throw fail
 		<testcase name="level 1c" time="*" classname="test"/>
 		<testcase name="level 1d" time="*" classname="test"/>
 	</testsuite>
-	<testsuite name="top level" time="*" disabled="0" errors="0" tests="2" failures="1" skipped="0" hostname="HOSTNAME">
-		<testcase name="+long running" time="*" classname="test" failure="test did not finish before its parent and was cancelled">
-			<failure type="cancelledByParent" message="test did not finish before its parent and was cancelled">
-[Error [ERR_TEST_FAILURE]: test did not finish before its parent and was cancelled] { code: 'ERR_TEST_FAILURE', failureType: 'cancelledByParent', cause: 'test did not finish before its parent and was cancelled' }
-			</failure>
-		</testcase>
+	<testsuite name="top level" time="*" disabled="0" errors="0" tests="2" failures="0" skipped="0" hostname="HOSTNAME">
+		<testcase name="+long running" time="*" classname="test"/>
 		<testsuite name="+short running" time="*" disabled="0" errors="0" tests="1" failures="0" skipped="0" hostname="HOSTNAME">
 			<testcase name="++short running" time="*" classname="test"/>
 		</testsuite>
@@ -519,9 +515,9 @@ Error [ERR_TEST_FAILURE]: test could not be started because its parent finished
 	<!-- Error: Test "callback async throw after done" at test/fixtures/test-runner/output/output.js:269:1 generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event. -->
 	<!-- tests 75 -->
 	<!-- suites 0 -->
-	<!-- pass 34 -->
-	<!-- fail 25 -->
-	<!-- cancelled 3 -->
+	<!-- pass 36 -->
+	<!-- fail 24 -->
+	<!-- cancelled 2 -->
 	<!-- skipped 9 -->
 	<!-- todo 4 -->
 	<!-- duration_ms * -->

test/fixtures/test-runner/output/no_refs.snapshot

@@ -1,35 +1,23 @@
 TAP version 13
 # Subtest: does not keep event loop alive
     # Subtest: +does not keep event loop alive
-    not ok 1 - +does not keep event loop alive
+    ok 1 - +does not keep event loop alive
       ---
       duration_ms: *
       type: 'test'
-      location: '/test/fixtures/test-runner/output/no_refs.js:(LINE):11'
-      failureType: 'cancelledByParent'
-      error: 'Promise resolution is still pending but the event loop has already resolved'
-      code: 'ERR_TEST_FAILURE'
-      stack: |-
-        *
       ...
     1..1
-not ok 1 - does not keep event loop alive
+ok 1 - does not keep event loop alive
   ---
   duration_ms: *
   type: 'test'
-  location: '/test/fixtures/test-runner/output/no_refs.js:(LINE):1'
-  failureType: 'cancelledByParent'
-  error: 'Promise resolution is still pending but the event loop has already resolved'
-  code: 'ERR_TEST_FAILURE'
-  stack: |-
-    *
   ...
 1..1
 # tests 2
 # suites 0
-# pass 0
+# pass 2
 # fail 0
-# cancelled 2
+# cancelled 0
 # skipped 0
 # todo 0
 # duration_ms *

test/fixtures/test-runner/output/output.snapshot

@@ -288,14 +288,10 @@ ok 23 - level 0a
   ...
 # Subtest: top level
     # Subtest: +long running
-    not ok 1 - +long running
+    ok 1 - +long running
       ---
       duration_ms: *
       type: 'test'
-      location: '/test/fixtures/test-runner/output/output.js:(LINE):5'
-      failureType: 'cancelledByParent'
-      error: 'test did not finish before its parent and was cancelled'
-      code: 'ERR_TEST_FAILURE'
       ...
     # Subtest: +short running
         # Subtest: ++short running
@@ -311,14 +307,10 @@ ok 23 - level 0a
       type: 'test'
       ...
     1..2
-not ok 24 - top level
+ok 24 - top level
   ---
   duration_ms: *
   type: 'test'
-  location: '/test/fixtures/test-runner/output/output.js:(LINE):1'
-  failureType: 'subtestsFailed'
-  error: '1 subtest failed'
-  code: 'ERR_TEST_FAILURE'
   ...
 # Subtest: invalid subtest - pass but subtest fails
 ok 25 - invalid subtest - pass but subtest fails
@@ -787,9 +779,9 @@ not ok 62 - invalid subtest fail
 # Error: Test "callback async throw after done" at test/fixtures/test-runner/output/output.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event.
 # tests 75
 # suites 0
-# pass 34
-# fail 25
-# cancelled 3
+# pass 36
+# fail 24
+# cancelled 2
 # skipped 9
 # todo 4
 # duration_ms *

test/fixtures/test-runner/output/output_cli.snapshot

@@ -288,14 +288,10 @@ ok 23 - level 0a
   ...
 # Subtest: top level
     # Subtest: +long running
-    not ok 1 - +long running
+    ok 1 - +long running
       ---
       duration_ms: *
       type: 'test'
-      location: '/test/fixtures/test-runner/output/output.js:(LINE):5'
-      failureType: 'cancelledByParent'
-      error: 'test did not finish before its parent and was cancelled'
-      code: 'ERR_TEST_FAILURE'
       ...
     # Subtest: +short running
         # Subtest: ++short running
@@ -311,14 +307,10 @@ ok 23 - level 0a
       type: 'test'
       ...
     1..2
-not ok 24 - top level
+ok 24 - top level
   ---
   duration_ms: *
   type: 'test'
-  location: '/test/fixtures/test-runner/output/output.js:(LINE):1'
-  failureType: 'subtestsFailed'
-  error: '1 subtest failed'
-  code: 'ERR_TEST_FAILURE'
   ...
 # Subtest: invalid subtest - pass but subtest fails
 ok 25 - invalid subtest - pass but subtest fails
@@ -801,9 +793,9 @@ ok 63 - last test
 1..63
 # tests 77
 # suites 0
-# pass 36
-# fail 25
-# cancelled 3
+# pass 38
+# fail 24
+# cancelled 2
 # skipped 9
 # todo 4
 # duration_ms *

test/fixtures/test-runner/output/spec_reporter.snapshot

@@ -90,9 +90,9 @@
  Error: Test "callback async throw after done" at test/fixtures/test-runner/output/output.js:269:1 generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event.
  tests 75
  suites 0
- pass 34
- fail 25
- cancelled 3
+ pass 36
+ fail 24
+ cancelled 2
  skipped 9
  todo 4
  duration_ms *
@@ -203,10 +203,6 @@
  sync throw non-error fail (*ms)
   Symbol(thrown symbol from sync throw non-error fail)
 
-*
- +long running (*ms)
-  'test did not finish before its parent and was cancelled'
-
 *
  sync skip option is false fail (*ms)
   Error: this should be executed

test/fixtures/test-runner/output/spec_reporter_cli.snapshot

@@ -93,9 +93,9 @@
  Error: Test "callback async throw after done" at test/fixtures/test-runner/output/output.js:269:1 generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event.
  tests 76
  suites 0
- pass 35
- fail 25
- cancelled 3
+ pass 37
+ fail 24
+ cancelled 2
  skipped 9
  todo 4
  duration_ms *
@@ -206,10 +206,6 @@
  sync throw non-error fail (*ms)
   Symbol(thrown symbol from sync throw non-error fail)
 
-*
- +long running (*ms)
-  'test did not finish before its parent and was cancelled'
-
 *
  sync skip option is false fail (*ms)
   Error: this should be executed

test/parallel/test-runner-output.mjs

@@ -215,10 +215,6 @@ const tests = [
     name: 'test-runner/output/unfinished-suite-async-error.js',
     flags: ['--test-reporter=tap'],
   },
-  {
-    name: 'test-runner/output/unresolved_promise.js',
-    flags: ['--test-reporter=tap'],
-  },
   { name: 'test-runner/output/default_output.js', transform: specTransform, tty: true },
   {
     name: 'test-runner/output/arbitrary-output.js',