From 0767b79f580c7f78f35a33fa2cd7918b0e7c1cda Mon Sep 17 00:00:00 2001 From: cjihrig Date: Sun, 19 Jan 2025 17:46:37 -0500 Subject: [PATCH] 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. --- lib/internal/test_runner/harness.js | 17 +++++++++++++--- lib/internal/test_runner/test.js | 13 ++++++++++++ .../output/default_output.snapshot | 10 +++------- .../test-runner/output/dot_reporter.snapshot | 6 +----- .../output/junit_reporter.snapshot | 14 +++++-------- .../test-runner/output/no_refs.snapshot | 20 ++++--------------- .../test-runner/output/output.snapshot | 18 +++++------------ .../test-runner/output/output_cli.snapshot | 18 +++++------------ .../test-runner/output/spec_reporter.snapshot | 10 +++------- .../output/spec_reporter_cli.snapshot | 10 +++------- test/parallel/test-runner-output.mjs | 4 ---- 11 files changed, 56 insertions(+), 84 deletions(-) diff --git a/lib/internal/test_runner/harness.js b/lib/internal/test_runner/harness.js index 77791b7231d593..fe5915dec13483 100644 --- a/lib/internal/test_runner/harness.js +++ b/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(); }; diff --git a/lib/internal/test_runner/test.js b/lib/internal/test_runner/test.js index 6b3d087b67da66..14d9911ef4f62d 100644 --- a/lib/internal/test_runner/test.js +++ b/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 diff --git a/test/fixtures/test-runner/output/default_output.snapshot b/test/fixtures/test-runner/output/default_output.snapshot index d0a83395733924..a58e14346ec727 100644 --- a/test/fixtures/test-runner/output/default_output.snapshot +++ b/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 diff --git a/test/fixtures/test-runner/output/dot_reporter.snapshot b/test/fixtures/test-runner/output/dot_reporter.snapshot index fc2b58cfef8428..4ef804951dc99f 100644 --- a/test/fixtures/test-runner/output/dot_reporter.snapshot +++ b/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 * diff --git a/test/fixtures/test-runner/output/junit_reporter.snapshot b/test/fixtures/test-runner/output/junit_reporter.snapshot index aaa5dcd6ff9963..d1868bd4b6eaa9 100644 --- a/test/fixtures/test-runner/output/junit_reporter.snapshot +++ b/test/fixtures/test-runner/output/junit_reporter.snapshot @@ -186,12 +186,8 @@ Error [ERR_TEST_FAILURE]: thrown from subtest sync throw fail - - - -[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' } - - + + @@ -519,9 +515,9 @@ Error [ERR_TEST_FAILURE]: test could not be started because its parent finished - - - + + + diff --git a/test/fixtures/test-runner/output/no_refs.snapshot b/test/fixtures/test-runner/output/no_refs.snapshot index 310094947f9f96..8014b0343892f7 100644 --- a/test/fixtures/test-runner/output/no_refs.snapshot +++ b/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 * diff --git a/test/fixtures/test-runner/output/output.snapshot b/test/fixtures/test-runner/output/output.snapshot index 36d9c289fa1615..044ac4137fa78d 100644 --- a/test/fixtures/test-runner/output/output.snapshot +++ b/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 * diff --git a/test/fixtures/test-runner/output/output_cli.snapshot b/test/fixtures/test-runner/output/output_cli.snapshot index 4546269836e9ca..eaa085d97d06d1 100644 --- a/test/fixtures/test-runner/output/output_cli.snapshot +++ b/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 * diff --git a/test/fixtures/test-runner/output/spec_reporter.snapshot b/test/fixtures/test-runner/output/spec_reporter.snapshot index 1892069327f92d..17eb9d01451d32 100644 --- a/test/fixtures/test-runner/output/spec_reporter.snapshot +++ b/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 diff --git a/test/fixtures/test-runner/output/spec_reporter_cli.snapshot b/test/fixtures/test-runner/output/spec_reporter_cli.snapshot index 52dc40bb366e2c..2dd9e92deb1b38 100644 --- a/test/fixtures/test-runner/output/spec_reporter_cli.snapshot +++ b/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 diff --git a/test/parallel/test-runner-output.mjs b/test/parallel/test-runner-output.mjs index 7332f03b129c72..8adac4dfa72b94 100644 --- a/test/parallel/test-runner-output.mjs +++ b/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',