test_runner: automatically wait for subtests to finish

lib/internal/test_runner/harness.js

@@ -28,6 +28,8 @@ const {
 } = require('internal/test_runner/utils');
 const { queueMicrotask } = require('internal/process/task_queues');
 const { bigint: hrtime } = process.hrtime;
+const { TIMEOUT_MAX } = require('internal/timers');
+const { clearInterval, setInterval } = require('timers');
 
 const testResources = new SafeMap();
 
@@ -165,6 +167,15 @@ function setup(root) {
       // Run global before/after hooks in case there are no tests
       await root.run();
     }
+
+    if (root.subtestsPromise) {
+      // 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));

lib/internal/test_runner/test.js

@@ -499,6 +499,8 @@ class Test extends AsyncResource {
     this.readySubtests = new SafeMap();
     this.subtests = [];
     this.waitingOn = 0;
+    this.subtestsPromise = null;
+    this.ranSubtests = new SafeSet();
     this.finished = false;
 
     if (!testOnlyFlag && (only || this.runOnlySubtests)) {
@@ -638,6 +640,7 @@ class Test extends AsyncResource {
     const test = new Factory({ __proto__: null, fn, name, parent, ...options, ...overrides });
 
     if (parent.waitingOn === 0) {
+      parent.subtestsPromise = createDeferredPromise();
       parent.waitingOn = test.childNumber;
     }
 
@@ -648,6 +651,7 @@ class Test extends AsyncResource {
           kParentAlreadyFinished,
         ),
       );
+      test.postRun();
     }
 
     ArrayPrototypePush(parent.subtests, test);
@@ -743,7 +747,7 @@ class Test extends AsyncResource {
       this.reporter = noopTestStream;
       this.run = this.filteredRun;
     } else {
-      this.testNumber = ++this.parent.outputSubtestCount;
+      this.testNumber ||= ++this.parent.outputSubtestCount;
     }
 
     // If there is enough available concurrency to run the test now, then do
@@ -870,6 +874,11 @@ class Test extends AsyncResource {
         this.postRun();
         return;
       }
+
+      if (this.subtestsPromise) {
+        await SafePromiseRace([this.subtestsPromise.promise, stopPromise]);
+      }
+
       this.plan?.check();
       this.pass();
       await afterEach();
@@ -962,6 +971,10 @@ class Test extends AsyncResource {
       this.parent.addReadySubtest(this);
       this.parent.processReadySubtestRange(false);
       this.parent.processPendingSubtests();
+      this.parent.ranSubtests.add(this);
+      if (this.parent.ranSubtests.size === this.parent.subtests.length) {
+        this.parent.subtestsPromise.resolve();
+      }
     } else if (!this.reported) {
       const {
         diagnostics,

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

@@ -11,7 +11,7 @@ test('should fail', () => { throw new Error('fail'); });
 test('should skip', { skip: true }, () => {});
 test('parent', (t) => {
   t.test('should fail', () => { throw new Error('fail'); });
-  t.test('should pass but parent fail', (t, done) => {
+  t.test('should pass because parent waits', (t, done) => {
     setImmediate(done);
   });
 });

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

@@ -24,15 +24,13 @@
     *[39m
     *[39m
 
-  [31m✖ should pass but parent fail [90m(*ms)[39m[39m
-    [32m'test did not finish before its parent and was cancelled'[39m
-
+  [32m✔ should pass because parent waits [90m(*ms)[39m[39m
 [31m▶ [39mparent [90m(*ms)[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
@@ -63,7 +61,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/describe_it.snapshot

@@ -404,9 +404,13 @@ not ok 44 - callback called twice
     *
   ...
 # Subtest: callback called twice in different ticks
-ok 45 - callback called twice in different ticks
+not ok 45 - callback called twice in different ticks
   ---
   duration_ms: *
+  location: '/test/fixtures/test-runner/output/describe_it.js:(LINE):1'
+  failureType: 'uncaughtException'
+  error: 'callback invoked multiple times'
+  code: 'ERR_TEST_FAILURE'
   ...
 # Subtest: callback called twice in future tick
 not ok 46 - callback called twice in future tick
@@ -432,9 +436,16 @@ not ok 47 - callback async throw
     *
   ...
 # Subtest: callback async throw after done
-ok 48 - callback async throw after done
+not ok 48 - callback async throw after done
   ---
   duration_ms: *
+  location: '/test/fixtures/test-runner/output/describe_it.js:(LINE):1'
+  failureType: 'uncaughtException'
+  error: 'thrown from callback async throw after done'
+  code: 'ERR_TEST_FAILURE'
+  stack: |-
+    *
+    *
   ...
 # Subtest: custom inspect symbol fail
 not ok 49 - custom inspect symbol fail
@@ -695,12 +706,10 @@ not ok 58 - invalid subtest fail
 # Error: Test "async unhandled rejection - passes but warns" at test/fixtures/test-runner/output/describe_it.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from async unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.
 # Error: Test "immediate throw - passes but warns" at test/fixtures/test-runner/output/describe_it.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: thrown from immediate throw fail" and would have caused the test to fail, but instead triggered an uncaughtException event.
 # Error: Test "immediate reject - passes but warns" at test/fixtures/test-runner/output/describe_it.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from immediate reject fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.
-# Error: Test "callback called twice in different ticks" at test/fixtures/test-runner/output/describe_it.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error [ERR_TEST_FAILURE]: callback invoked multiple times" and would have caused the test to fail, but instead triggered an uncaughtException event.
-# Error: Test "callback async throw after done" at test/fixtures/test-runner/output/describe_it.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 67
 # suites 11
-# pass 31
-# fail 19
+# pass 29
+# fail 21
 # cancelled 4
 # skipped 9
 # todo 4

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
       *
@@ -160,6 +156,8 @@ Failed tests:
       *
       *
       *
+      *
+      *
 ✖ subtest sync throw fails (*ms)
   '2 subtests failed'
 ✖ timed out async test (*ms)
@@ -221,5 +219,5 @@ Failed tests:
     expected: [Object],
     operator: 'deepEqual'
   }
-✖ invalid subtest fail (*ms)
+✖ invalid subtest fail
   'test could not be started because its parent finished'

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>
@@ -372,6 +368,8 @@ Error [ERR_TEST_FAILURE]: thrown from subtest sync throw fails at second
       *
       *
       *
+      *
+      *
 }
 			</failure>
 		</testcase>
@@ -523,9 +521,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 76 -->
 	<!-- suites 0 -->
-	<!-- pass 35 -->
-	<!-- fail 25 -->
-	<!-- cancelled 3 -->
+	<!-- pass 37 -->
+	<!-- fail 24 -->
+	<!-- cancelled 2 -->
 	<!-- skipped 9 -->
 	<!-- todo 4 -->
 	<!-- duration_ms * -->

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

@@ -1,33 +1,21 @@
 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: *
-      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: *
-  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

@@ -260,13 +260,9 @@ ok 23 - level 0a
   ...
 # Subtest: top level
     # Subtest: +long running
-    not ok 1 - +long running
+    ok 1 - +long running
       ---
       duration_ms: *
-      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
@@ -280,13 +276,9 @@ ok 23 - level 0a
       duration_ms: *
       ...
     1..2
-not ok 24 - top level
+ok 24 - top level
   ---
   duration_ms: *
-  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
@@ -552,6 +544,8 @@ not ok 51 - custom inspect symbol that throws fail
         *
         *
         *
+        *
+        *
       ...
     1..2
 not ok 52 - subtest sync throw fails
@@ -720,9 +714,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 76
 # suites 0
-# pass 35
-# fail 25
-# cancelled 3
+# pass 37
+# fail 24
+# cancelled 2
 # skipped 9
 # todo 4
 # duration_ms *

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

@@ -260,13 +260,9 @@ ok 23 - level 0a
   ...
 # Subtest: top level
     # Subtest: +long running
-    not ok 1 - +long running
+    ok 1 - +long running
       ---
       duration_ms: *
-      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
@@ -280,13 +276,9 @@ ok 23 - level 0a
       duration_ms: *
       ...
     1..2
-not ok 24 - top level
+ok 24 - top level
   ---
   duration_ms: *
-  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
@@ -552,6 +544,8 @@ not ok 51 - custom inspect symbol that throws fail
         *
         *
         *
+        *
+        *
       ...
     1..2
 not ok 52 - subtest sync throw fails
@@ -725,9 +719,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 *