Skip to content

Commit

Permalink
test_runner: add stack on unhandled rejections
Browse files Browse the repository at this point in the history 
Fixes: #51714
  • Loading branch information
@atlowChemi
atlowChemi committed Apr 16, 2024
1 parent 468fe9e commit 1681786
Show file tree
Hide file tree
Showing 7 changed files with 120 additions and 29 deletions.
8 changes: 6 additions & 2 deletions lib/internal/test_runner/harness.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,10 +15,12 @@ const {
codes: {
ERR_TEST_FAILURE,
},
inspectWithNoCustomRetry,
} = require('internal/errors');
const { exitCodes: { kGenericUserError } } = internalBinding('errors');

const { kEmptyObject } = require('internal/util');
const colors = require('internal/util/colors');
const { kCancelledByParent, Test, Suite } = require('internal/test_runner/test');
const {
parseCommandLine,
Expand Down Expand Up @@ -58,6 +60,8 @@ function createProcessEventHandler(eventName, rootTest) {
// If the test is already finished or the resource that created the error
// is not mapped to a Test, report this as a top level diagnostic.
let msg;
const inspectOptions = { __proto__: null, colors: colors.shouldColorize(process.stdout), breakLength: Infinity };
const inspectedErr = inspectWithNoCustomRetry(err, inspectOptions);

if (test) {
const name = test.hookType ? `Test hook "${test.hookType}"` : `Test "${test.name}"`;
Expand All @@ -70,11 +74,11 @@ function createProcessEventHandler(eventName, rootTest) {
msg = `Error: ${name}${locInfo} generated asynchronous ` +
'activity after the test ended. This activity created the error ' +
`"${err}" and would have caused the test to fail, but instead ` +
`triggered an ${eventName} event.`;
`triggered an ${eventName} event.\n${inspectedErr}`;
} else {
msg = 'Error: A resource generated asynchronous activity after ' +
`the test ended. This activity created the error "${err}" which ` +
`triggered an ${eventName} event, caught by the test runner.`;
`triggered an ${eventName} event, caught by the test runner.\n${inspectedErr}`;
}

rootTest.diagnostic(msg);
Expand Down
12 changes: 6 additions & 6 deletions test/fixtures/test-runner/output/describe_it.snapshot
View file
Original file line number Diff line number Diff line change
Expand Up @@ -691,12 +691,12 @@ not ok 58 - invalid subtest fail
*
...
1..58
# Error: Test "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 unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.
# 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.
# Error: Test "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 unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.\\nError: rejected from unhandled rejection fail\\n at TestContext.<anonymous> (/test/fixtures/test-runner/output/describe_it.js:(LINE):18)\\n at Test.runInAsyncScope (node:async_hooks:206:9)\\n at Test.run (node:internal/test_runner/test:736:25)\\n at Test.processPendingSubtests (node:internal/test_runner/test:450:18)\\n at Test.postRun (node:internal/test_runner/test:835:19)\\n at Test.run (node:internal/test_runner/test:778:12)\\n at async Test.processPendingSubtests (node:internal/test_runner/test:450:7)
# 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.\\nError: rejected from async unhandled rejection fail\\n at TestContext.<anonymous> (/test/fixtures/test-runner/output/describe_it.js:(LINE):18)\\n at Test.runInAsyncScope (node:async_hooks:206:9)\\n at Test.run (node:internal/test_runner/test:736:25)\\n at Test.processPendingSubtests (node:internal/test_runner/test:450:18)\\n at Test.postRun (node:internal/test_runner/test:835:19)\\n at Test.run (node:internal/test_runner/test:778:12)\\n at async Test.processPendingSubtests (node:internal/test_runner/test:450:7)
# 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.\\nError: thrown from immediate throw fail\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/describe_it.js:(LINE):11)\\n at process.processImmediate (node:internal/timers:478:21)
# 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.\\nError: rejected from immediate reject fail\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/describe_it.js:(LINE):20)\\n at process.processImmediate (node:internal/timers:478:21)
# 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.\\n[Error [ERR_TEST_FAILURE]: callback invoked multiple times] { code: 'ERR_TEST_FAILURE', failureType: 'multipleCallbackInvocations', cause: 'callback invoked multiple times' }
# 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.\\nError: thrown from callback async throw after done\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/describe_it.js:(LINE):11)\\n at process.processImmediate (node:internal/timers:478:21)
# tests 67
# suites 11
# pass 31
Expand Down
43 changes: 36 additions & 7 deletions test/fixtures/test-runner/output/junit_reporter.snapshot
View file
Original file line number Diff line number Diff line change
Expand Up @@ -514,13 +514,42 @@ Error [ERR_TEST_FAILURE]: test could not be started because its parent finished
}
</failure>
</testcase>
<!-- Error: Test "unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:72:1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. -->
<!-- Error: Test "async unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:76: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: A resource generated asynchronous activity after the test ended. This activity created the error "Error: uncaught from outside of a test" which triggered an uncaughtException event, caught by the test runner. -->
<!-- Error: Test "immediate throw - passes but warns" at test/fixtures/test-runner/output/output.js:80: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/output.js:86: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/output.js:251: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/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. -->
<!-- Error: Test "unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:72:1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.
Error: rejected from unhandled rejection fail
*
*
*
*
*
*
at async Test.processPendingSubtests (node:internal/test_runner/test:450:7) -->
<!-- Error: Test "async unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:76: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: rejected from async unhandled rejection fail
*
*
*
*
*
*
at async Test.processPendingSubtests (node:internal/test_runner/test:450:7) -->
<!-- Error: A resource generated asynchronous activity after the test ended. This activity created the error "Error: uncaught from outside of a test" which triggered an uncaughtException event, caught by the test runner.
Error: uncaught from outside of a test
*
at process.processImmediate (node:internal/timers:478:21) -->
<!-- Error: Test "immediate throw - passes but warns" at test/fixtures/test-runner/output/output.js:80: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: thrown from immediate throw fail
*
at process.processImmediate (node:internal/timers:478:21) -->
<!-- Error: Test "immediate reject - passes but warns" at test/fixtures/test-runner/output/output.js:86: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: rejected from immediate reject fail
*
at process.processImmediate (node:internal/timers:478:21) -->
<!-- Error: Test "callback called twice in different ticks" at test/fixtures/test-runner/output/output.js:251: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 [ERR_TEST_FAILURE]: callback invoked multiple times] { code: 'ERR_TEST_FAILURE', failureType: 'multipleCallbackInvocations', cause: 'callback invoked multiple times' } -->
<!-- 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.
Error: thrown from callback async throw after done
*
at process.processImmediate (node:internal/timers:478:21) -->
<!-- tests 76 -->
<!-- suites 0 -->
<!-- pass 35 -->
Expand Down
14 changes: 7 additions & 7 deletions test/fixtures/test-runner/output/output.snapshot
View file
Original file line number Diff line number Diff line change
Expand Up @@ -711,13 +711,13 @@ not ok 62 - invalid subtest fail
*
...
1..62
# Error: Test "unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.
# Error: Test "async unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.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: A resource generated asynchronous activity after the test ended. This activity created the error "Error: uncaught from outside of a test" which triggered an uncaughtException event, caught by the test runner.
# Error: Test "immediate throw - passes but warns" 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 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/output.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/output.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/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.
# Error: Test "unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.js:(LINE):1 generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event.\\nError: rejected from unhandled rejection fail\\n at TestContext.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):18)\\n at Test.runInAsyncScope (node:async_hooks:206:9)\\n at Test.run (node:internal/test_runner/test:736:25)\\n at Test.processPendingSubtests (node:internal/test_runner/test:450:18)\\n at Test.postRun (node:internal/test_runner/test:835:19)\\n at Test.run (node:internal/test_runner/test:778:12)\\n at async Test.processPendingSubtests (node:internal/test_runner/test:450:7)
# Error: Test "async unhandled rejection - passes but warns" at test/fixtures/test-runner/output/output.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.\\nError: rejected from async unhandled rejection fail\\n at TestContext.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):18)\\n at Test.runInAsyncScope (node:async_hooks:206:9)\\n at Test.run (node:internal/test_runner/test:736:25)\\n at Test.processPendingSubtests (node:internal/test_runner/test:450:18)\\n at Test.postRun (node:internal/test_runner/test:835:19)\\n at Test.run (node:internal/test_runner/test:778:12)\\n at async Test.processPendingSubtests (node:internal/test_runner/test:450:7)
# Error: A resource generated asynchronous activity after the test ended. This activity created the error "Error: uncaught from outside of a test" which triggered an uncaughtException event, caught by the test runner.\\nError: uncaught from outside of a test\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):9)\\n at process.processImmediate (node:internal/timers:478:21)
# Error: Test "immediate throw - passes but warns" 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 immediate throw fail" and would have caused the test to fail, but instead triggered an uncaughtException event.\\nError: thrown from immediate throw fail\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):11)\\n at process.processImmediate (node:internal/timers:478:21)
# Error: Test "immediate reject - passes but warns" at test/fixtures/test-runner/output/output.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.\\nError: rejected from immediate reject fail\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):20)\\n at process.processImmediate (node:internal/timers:478:21)
# Error: Test "callback called twice in different ticks" at test/fixtures/test-runner/output/output.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.\\n[Error [ERR_TEST_FAILURE]: callback invoked multiple times] { code: 'ERR_TEST_FAILURE', failureType: 'multipleCallbackInvocations', cause: 'callback invoked multiple times' }
# 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.\\nError: thrown from callback async throw after done\\n at Immediate.<anonymous> (/test/fixtures/test-runner/output/output.js:(LINE):11)\\n at process.processImmediate (node:internal/timers:478:21)
# tests 76
# suites 0
# pass 35
Expand Down
Loading

0 comments on commit 1681786

Please sign in to comment.