test: fix test runner does not print error cause

Author: pulkit-30

lib/internal/test_runner/reporter/tap.js

@@ -14,6 +14,7 @@ const {
 const { inspectWithNoCustomRetry } = require('internal/errors');
 const { isError, kEmptyObject } = require('internal/util');
 const { relative } = require('path');
+const util = require('util');
 const kDefaultIndent = '    '; // 4 spaces
 const kFrameStartRegExp = /^ {4}at /;
 const kLineBreakRegExp = /\n|\r\n/;
@@ -196,6 +197,7 @@ function jsToYaml(indent, name, value) {
       operator,
       stack,
     } = value;
+    const errHasInnerCause = hasInnerCause(value);
     let errMsg = message ?? '<unknown error>';
     let errStack = stack;
     let errCode = code;
@@ -207,7 +209,11 @@ 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;
+      if (errHasInnerCause) {
+        errStack = util.inspect(cause);
+      } else {
+        errStack = cause?.stack ?? errStack;
+      }
       errCode = cause?.code ?? errCode;
       if (isAssertionLike(cause)) {
         errExpected = cause.expected;
@@ -245,8 +251,9 @@ function jsToYaml(indent, name, value) {
             frame,
             ''
           );
-
-          if (processed.length > 0 && processed.length !== frame.length) {
+          if (errHasInnerCause && processed.length > 0) {
+            ArrayPrototypePush(frames, processed);
+          } else if (processed.length > 0 && processed.length !== frame.length) {
             ArrayPrototypePush(frames, processed);
           }
         }
@@ -268,4 +275,8 @@ function isAssertionLike(value) {
   return value && typeof value === 'object' && 'expected' in value && 'actual' in value;
 }
 
+function hasInnerCause(value) {
+  return value?.cause?.cause?.stack ? true : false;
+}
+
 module.exports = tapReporter;

test/message/test_runner_output.js

@@ -383,3 +383,7 @@ test('unfinished test with unhandledRejection', async () => {
     setTimeout(() => Promise.reject(new Error('bar')));
   });
 });
+
+test('should print error cause', () => {
+  throw new Error('foo', { cause: new Error('bar') });
+});

test/message/test_runner_output.out

@@ -620,8 +620,32 @@ 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: |-
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+    *
+  ...
 # Subtest: invalid subtest fail
-not ok 65 - invalid subtest fail
+not ok 66 - invalid subtest fail
   ---
   duration_ms: *
   failureType: 'parentAlreadyFinished'
@@ -630,16 +654,16 @@ not ok 65 - invalid subtest fail
   stack: |-
     *
   ...
-1..65
+1..66
 # 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: 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 65
+# tests 66
 # pass 27
-# fail 21
+# fail 22
 # cancelled 2
 # skipped 10
 # todo 5

test/message/test_runner_output_cli.out

@@ -621,8 +621,32 @@ TAP version 13
         *
         *
       ...
+    # Subtest: should print error cause
+    not ok 65 - should print error cause
+      ---
+      duration_ms: *
+      failureType: 'testCodeFailure'
+      error: 'foo'
+      code: 'ERR_TEST_FAILURE'
+      stack: |-
+        *
+        *
+        *
+
+        *
+        *
+        *
+        *
+        *
+        *
+        *
+        *
+        *
+        *
+        *
+      ...
     # Subtest: invalid subtest fail
-    not ok 65 - invalid subtest fail
+    not ok 66 - invalid subtest fail
       ---
       duration_ms: *
       failureType: 'parentAlreadyFinished'
@@ -631,7 +655,7 @@ TAP version 13
       stack: |-
         *
       ...
-    1..65
+    1..66
     # 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: 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.

test/message/test_runner_output_dot_reporter.out

@@ -1,4 +1,4 @@
 ..XX...X..XXX.X.....
 XXX.....X..X...X....
 .........X...XXX.XX.
-.....XXXXXXX...XXXX
+.....XXXXXXX...XXXXX

test/message/test_runner_output_spec_reporter.out

@@ -262,6 +262,23 @@
   *
   *
 
+ should print error cause (*ms)
+  Error: foo
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+  *
+
  invalid subtest fail (*ms)
   'test could not be started because its parent finished'
 
@@ -271,9 +288,9 @@
  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 65
+ tests 66
  pass 27
- fail 21
+ fail 22
  cancelled 2
  skipped 10
  todo 5