test: fix test runner does not print error cause

Author: pulkit-30

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'];

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;

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

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(() => {

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,19 +771,19 @@ 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.
 # Warning: Test "immediate throw - passes but warns" 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.
 # 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 *