From 1e13b9716cce086928a0ae74fb0a31c2bca29c70 Mon Sep 17 00:00:00 2001 From: Pulkit Gupta <76155456+pulkit-30@users.noreply.github.com> Date: Thu, 30 Mar 2023 00:31:00 +0530 Subject: [PATCH] test: fix test runner does not print error cause --- lib/internal/test_runner/reporter/spec.js | 7 +- lib/internal/test_runner/reporter/tap.js | 38 +++- test/message/test_runner_describe_it.out | 6 +- test/message/test_runner_output.js | 40 ++++ test/message/test_runner_output.out | 147 +++++++++++++- test/message/test_runner_output_cli.out | 147 +++++++++++++- .../test_runner_output_dot_reporter.out | 3 +- .../test_runner_output_spec_reporter.out | 192 +++++++++++++++++- 8 files changed, 557 insertions(+), 23 deletions(-) diff --git a/lib/internal/test_runner/reporter/spec.js b/lib/internal/test_runner/reporter/spec.js index 2e3ba834351970..e5cd4bc11c4bd9 100644 --- a/lib/internal/test_runner/reporter/spec.js +++ b/lib/internal/test_runner/reporter/spec.js @@ -71,7 +71,12 @@ class SpecReporter extends Transform { // If this test has had children - it was already reported, so slightly modify the output return `${prefix}${indent}${color}${symbols['arrow:right']}${white}${title}\n`; } - const error = this.#formatError(data.details?.error, indent); + let error = ''; + try { + error = this.#formatError(data.details?.error, indent); + } catch (err) { + error = this.#formatError(err, indent); + } if (skippedSubtest) { color = gray; symbol = symbols['hyphen:minus']; diff --git a/lib/internal/test_runner/reporter/tap.js b/lib/internal/test_runner/reporter/tap.js index c7d5dd9bdb037f..352dcd0d7fcdcc 100644 --- a/lib/internal/test_runner/reporter/tap.js +++ b/lib/internal/test_runner/reporter/tap.js @@ -3,23 +3,34 @@ const { ArrayPrototypeForEach, ArrayPrototypeJoin, ArrayPrototypePush, + ArrayPrototypeSome, NumberPrototypeToFixed, ObjectEntries, + ObjectPrototypeHasOwnProperty, RegExpPrototypeSymbolReplace, SafeMap, + StringPrototypeRepeat, StringPrototypeReplaceAll, StringPrototypeSplit, - StringPrototypeRepeat, + StringPrototypeStartsWith, } = primordials; const { inspectWithNoCustomRetry } = require('internal/errors'); const { isError, kEmptyObject } = require('internal/util'); +const { inspect } = require('internal/util/inspect'); const { relative } = require('path'); const kDefaultIndent = ' '; // 4 spaces -const kFrameStartRegExp = /^ {4}at /; +const kFrameStartRegExp = /[{}]/; const kLineBreakRegExp = /\n|\r\n/; const kDefaultTAPVersion = 13; const inspectOptions = { colors: false, breakLength: Infinity }; let testModule; // Lazy loaded due to circular dependency. +const keywords = [ + '...', + 'failureType', + 'cause', + 'code', + 'Error', +]; function lazyLoadTest() { testModule ??= require('internal/test_runner/test'); @@ -210,7 +221,7 @@ function jsToYaml(indent, name, value) { // If the ERR_TEST_FAILURE came from an error provided by user code, // then try to unwrap the original error message and stack. if (code === 'ERR_TEST_FAILURE' && kUnwrapErrors.has(failureType)) { - errStack = cause?.stack ?? errStack; + errStack = getErrorStack(cause, errStack); errCode = cause?.code ?? errCode; errName = cause?.name ?? errName; if (isAssertionLike(cause)) { @@ -249,11 +260,17 @@ function jsToYaml(indent, name, value) { (frame) => { const processed = RegExpPrototypeSymbolReplace( kFrameStartRegExp, - frame, + ArrayPrototypeJoin( + StringPrototypeSplit(frame, ' at'), + '', + ), '', ); - if (processed.length > 0 && processed.length !== frame.length) { + const trimmedProcessed = processed.trim(); + if (trimmedProcessed.length > 0 && processed !== kDefaultIndent && (processed.length !== frame.length || + StringPrototypeStartsWith(trimmedProcessed, '[cause]')) && + !ArrayPrototypeSome(keywords, (str) => StringPrototypeStartsWith(processed, str))) { ArrayPrototypePush(frames, processed); } }, @@ -275,4 +292,15 @@ function isAssertionLike(value) { return value && typeof value === 'object' && 'expected' in value && 'actual' in value; } +function getErrorStack(cause, errStack) { + try { + if (cause !== null && ObjectPrototypeHasOwnProperty(cause, 'cause')) { + return inspect(cause); + } + return cause?.stack ?? errStack; + } catch (err) { + return inspect(err); + } +} + module.exports = tapReporter; diff --git a/test/message/test_runner_describe_it.out b/test/message/test_runner_describe_it.out index 209cf5bb6715e8..aae7edf3601c70 100644 --- a/test/message/test_runner_describe_it.out +++ b/test/message/test_runner_describe_it.out @@ -118,9 +118,9 @@ not ok 14 - async assertion fail failureType: 'testCodeFailure' error: |- Expected values to be strictly equal: - + true !== false - + code: 'ERR_ASSERTION' name: 'AssertionError' expected: false @@ -569,7 +569,7 @@ not ok 56 - describe async throw fails error: 'test timed out after 5ms' code: 'ERR_TEST_FAILURE' stack: |- - async Promise.all (index 0) + async Promise.all (index 0) ... # Subtest: timed out callback test not ok 2 - timed out callback test diff --git a/test/message/test_runner_output.js b/test/message/test_runner_output.js index a53ded3dfde3ac..283b5797d34c1a 100644 --- a/test/message/test_runner_output.js +++ b/test/message/test_runner_output.js @@ -384,6 +384,46 @@ test('unfinished test with unhandledRejection', async () => { }); }); +test('should print error cause', () => { + Error.stackTraceLimit = 4; + throw new Error('foo', { cause: new Error('bar') }); +}); + +test('should print error cause for nested errors', () => { + throw new Error('a', { cause: new Error('b', { cause: + new Error('c', { cause: new Error('d', { cause: new Error('e') }) }) }) }); +}); + +test('should handle cycles in error', () => { + const outer = new Error('b', { cause: null }); + outer.cause = new Error('c', { cause: new Error('d', { cause: outer }) }); + throw outer; +}); + +test('should handle primitive, undefined and null cause', () => { + test('primitive cause', () => { + throw new Error('foo', { cause: 'something went wrong' }); + }); + test('undefined cause', () => { + throw new Error('foo', { cause: undefined }); + }); + test('null cause', () => { + throw new Error('foo', { cause: null }); + }); +}); + +test('should handle case when cause throw', () => { + const error = new Error(); + Reflect.defineProperty(error, 'cause', { get() { throw new Error('bar'); } }); + throw error; +}); + +test('should handle case when stack throw', () => { + const error = new Error(); + Reflect.defineProperty(error, 'stack', { get() { throw new Error('bar'); } }); + throw error; +}); + // Verify that uncaught exceptions outside of any tests are handled after the // test harness has finished bootstrapping itself. setImmediate(() => { diff --git a/test/message/test_runner_output.out b/test/message/test_runner_output.out index 668676cb6eeda6..f5f6ba58010828 100644 --- a/test/message/test_runner_output.out +++ b/test/message/test_runner_output.out @@ -624,8 +624,145 @@ not ok 64 - unfinished test with unhandledRejection * * ... +# Subtest: should print error cause +not ok 65 - should print error cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: bar + * + * + * + * + ... +# Subtest: should print error cause for nested errors +not ok 66 - should print error cause for nested errors + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'a' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: [Error] + ... +# Subtest: should handle cycles in error +not ok 67 - should handle cycles in error + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'b' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: Error: d + * + * + * + * + [cause]: [Circular *1] + ... +# Subtest: should handle primitive, undefined and null cause + # Subtest: primitive cause + not ok 1 - primitive cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: 'something went wrong' + ... + # Subtest: undefined cause + not ok 2 - undefined cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: undefined + ... + # Subtest: null cause + not ok 3 - null cause + --- + duration_ms: * + failureType: 'cancelledByParent' + error: 'test did not finish before its parent and was cancelled' + code: 'ERR_TEST_FAILURE' + ... + 1..3 +not ok 68 - should handle primitive, undefined and null cause + --- + duration_ms: * + failureType: 'subtestsFailed' + error: '3 subtests failed' + code: 'ERR_TEST_FAILURE' + ... +# Subtest: should handle case when cause throw +not ok 69 - should handle case when cause throw + --- + duration_ms: * + failureType: 'testCodeFailure' + error: '' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + ... +# Subtest: should handle case when stack throw +not ok 70 - should handle case when stack throw + --- + duration_ms: * + failureType: 'testCodeFailure' + error: '' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + ... # Subtest: invalid subtest fail -not ok 65 - invalid subtest fail +not ok 71 - invalid subtest fail --- duration_ms: * failureType: 'parentAlreadyFinished' @@ -634,7 +771,7 @@ not ok 65 - invalid subtest fail stack: |- * ... -1..65 +1..71 # Warning: Test "unhandled rejection - passes but warns" 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. # Warning: Test "async unhandled rejection - passes but warns" 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. # Warning: 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. @@ -642,11 +779,11 @@ not ok 65 - invalid subtest fail # Warning: Test "immediate reject - passes but warns" 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. # Warning: Test "callback called twice in different ticks" 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. # Warning: Test "callback async throw after done" 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 79 +# tests 88 # suites 0 # pass 37 -# fail 24 -# cancelled 3 +# fail 32 +# cancelled 4 # skipped 10 # todo 5 # duration_ms * diff --git a/test/message/test_runner_output_cli.out b/test/message/test_runner_output_cli.out index e51b6b472ca44f..fc308601bfb5ba 100644 --- a/test/message/test_runner_output_cli.out +++ b/test/message/test_runner_output_cli.out @@ -624,8 +624,145 @@ not ok 64 - unfinished test with unhandledRejection * * ... +# Subtest: should print error cause +not ok 65 - should print error cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: bar + * + * + * + * + ... +# Subtest: should print error cause for nested errors +not ok 66 - should print error cause for nested errors + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'a' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: [Error] + ... +# Subtest: should handle cycles in error +not ok 67 - should handle cycles in error + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'b' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: Error: d + * + * + * + * + [cause]: [Circular *1] + ... +# Subtest: should handle primitive, undefined and null cause + # Subtest: primitive cause + not ok 1 - primitive cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: 'something went wrong' + ... + # Subtest: undefined cause + not ok 2 - undefined cause + --- + duration_ms: * + failureType: 'testCodeFailure' + error: 'foo' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + [cause]: undefined + ... + # Subtest: null cause + not ok 3 - null cause + --- + duration_ms: * + failureType: 'cancelledByParent' + error: 'test did not finish before its parent and was cancelled' + code: 'ERR_TEST_FAILURE' + ... + 1..3 +not ok 68 - should handle primitive, undefined and null cause + --- + duration_ms: * + failureType: 'subtestsFailed' + error: '3 subtests failed' + code: 'ERR_TEST_FAILURE' + ... +# Subtest: should handle case when cause throw +not ok 69 - should handle case when cause throw + --- + duration_ms: * + failureType: 'testCodeFailure' + error: '' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + ... +# Subtest: should handle case when stack throw +not ok 70 - should handle case when stack throw + --- + duration_ms: * + failureType: 'testCodeFailure' + error: '' + code: 'ERR_TEST_FAILURE' + stack: |- + * + * + * + * + ... # Subtest: invalid subtest fail -not ok 65 - invalid subtest fail +not ok 71 - invalid subtest fail --- duration_ms: * failureType: 'parentAlreadyFinished' @@ -641,12 +778,12 @@ not ok 65 - invalid subtest fail # Warning: Test "immediate reject - passes but warns" 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. # Warning: Test "callback called twice in different ticks" 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. # Warning: Test "callback async throw after done" 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. -1..65 -# tests 79 +1..71 +# tests 88 # suites 0 # pass 37 -# fail 24 -# cancelled 3 +# fail 32 +# cancelled 4 # skipped 10 # todo 5 # duration_ms * diff --git a/test/message/test_runner_output_dot_reporter.out b/test/message/test_runner_output_dot_reporter.out index 823ecfb146b991..e3467a3bdf4694 100644 --- a/test/message/test_runner_output_dot_reporter.out +++ b/test/message/test_runner_output_dot_reporter.out @@ -1,4 +1,5 @@ ..XX...X..XXX.X..... XXX.....X..X...X.... .........X...XXX.XX. -.....XXXXXXX...XXXX +.....XXXXXXX...XXXXX +XXXXXXXX diff --git a/test/message/test_runner_output_spec_reporter.out b/test/message/test_runner_output_spec_reporter.out index b3ca09b0561893..d57662bbfba28f 100644 --- a/test/message/test_runner_output_spec_reporter.out +++ b/test/message/test_runner_output_spec_reporter.out @@ -265,6 +265,99 @@ * * + should print error cause (*ms) + Error: foo + * + * + * + * + [cause]: Error: bar + * + * + * + * + } + + should print error cause for nested errors (*ms) + Error: a + * + * + * + * + [cause]: Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: [Error] + } + } + } + + should handle cycles in error (*ms) + Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: Error: d + * + * + * + * + [cause]: [Circular *1] + } + } + } + + should handle primitive, undefined and null cause + primitive cause (*ms) + Error: foo + * + * + * + * + [cause]: 'something went wrong' + } + + undefined cause (*ms) + Error: foo + * + * + * + * + [cause]: undefined + } + + null cause (*ms) + 'test did not finish before its parent and was cancelled' + + should handle primitive, undefined and null cause (*ms) + + should handle case when cause throw (*ms) + Error: bar + * + * + * + * + + should handle case when stack throw (*ms) + Error: bar + * + * + * + * + invalid subtest fail (*ms) 'test could not be started because its parent finished' @@ -275,11 +368,11 @@ Warning: Test "immediate reject - passes but warns" 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. Warning: Test "callback called twice in different ticks" 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. Warning: Test "callback async throw after done" 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 79 + tests 88 suites 0 pass 37 - fail 24 - cancelled 3 + fail 32 + cancelled 4 skipped 10 todo 5 duration_ms * @@ -490,5 +583,98 @@ * * + should print error cause (*ms) + Error: foo + * + * + * + * + [cause]: Error: bar + * + * + * + * + } + + should print error cause for nested errors (*ms) + Error: a + * + * + * + * + [cause]: Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: [Error] + } + } + } + + should handle cycles in error (*ms) + Error: b + * + * + * + * + [cause]: Error: c + * + * + * + * + [cause]: Error: d + * + * + * + * + [cause]: [Circular *1] + } + } + } + + primitive cause (*ms) + Error: foo + * + * + * + * + [cause]: 'something went wrong' + } + + undefined cause (*ms) + Error: foo + * + * + * + * + [cause]: undefined + } + + null cause (*ms) + 'test did not finish before its parent and was cancelled' + + should handle primitive, undefined and null cause (*ms) + '3 subtests failed' + + should handle case when cause throw (*ms) + Error: bar + * + * + * + * + + should handle case when stack throw (*ms) + Error: bar + * + * + * + * + invalid subtest fail (*ms) 'test could not be started because its parent finished'