test: fix test runner does not print error cause #46576

pulkit-30 · 2023-02-08T18:55:37Z

code:

import test from 'node:test';

test('should print error cause', () => {
  throw new Error('foo', {cause: new Error('bar')});
});

before: test runner doesn't print Error cause

TAP version 13
# Subtest: should print error cause
not ok 1 - should print error cause
  ---
  duration_ms: 0.818167
  failureType: 'testCodeFailure'
  error: 'foo'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:4:9)
    Test.runInAsyncScope (node:async_hooks:206:9)
    Test.run (node:internal/test_runner/test:549:25)
    Test.start (node:internal/test_runner/test:465:17)
    test (node:internal/test_runner/harness:171:18)
    file:///Users/pulkitgupta/Desktop/node/_test.mjs:3:1
    ModuleJob.run (node:internal/modules/esm/module_job:193:25)
  ...
1..1
# tests 1
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 5.839667

after changes:

TAP version 13
# Subtest: should print error cause
not ok 1 - should print error cause
  ---
  duration_ms: 0.648959
  failureType: 'testCodeFailure'
  error: 'foo'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    Error: foo
    TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:4:9)
    Test.runInAsyncScope (node:async_hooks:206:9)
        ... 4 lines matching cause stack trace ...
    ModuleJob.run (node:internal/modules/esm/module_job:193:25) {
      [cause]: Error: bar
          at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:4:34)
          at Test.runInAsyncScope (node:async_hooks:206:9)
          at Test.run (node:internal/test_runner/test:549:25)
          at Test.start (node:internal/test_runner/test:465:17)
          at test (node:internal/test_runner/harness:171:18)
          at file:///Users/pulkitgupta/Desktop/node/_test.mjs:3:1
          at ModuleJob.run (node:internal/modules/esm/module_job:193:25)
    }
  ...
1..1
# tests 1
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 5.896167

nodejs-github-bot · 2023-02-08T18:55:41Z

Review requested:

@nodejs/test_runner

ljharb · 2023-02-08T19:12:23Z

lib/internal/test_runner/reporter/tap.js

@@ -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;


a cause can be any JS value, including a primitive, and undefined. Causes should be printed whether they have a stack or not. Can you add some tests for non-error cause values?

Can you also add a test for something like this:

new Error('a', { cause: new Error('b', { cause: new Error('c', { cause: new Error('d', { cause: new Error('e') }) }) }) })

I'm usually in the "don't worry about primordials" crowd but since this is error handling and debugging code it needs to be very resilient.

I would expect it to deal the following (all real cases from the past):

What if someone subclassed Error with .cause with a getter that throws?

What if .stack throws?

In addition to @chjirig's test case, please add one like this:

const outer = new Error('b', { cause: null }); outer.cause = new Error('c', { cause: new Error('d', { cause: outer }) }) });`

to ensure cycles are handled.

MoLow · 2023-02-09T15:59:37Z

please also make sure (with a test?) that the cause is shown both when running with --test and without (the TAP & yaml are serialized and deserialized when running with --test)

MoLow · 2023-02-09T16:04:34Z

test/message/test_runner_output.out

+    *
+    *
+    *
+    *


perhaps some of these lines (that are not a stack trace) should not be an asterisk

I agree with @MoLow here.

pulkit-30 · 2023-02-09T16:23:17Z

Thanks for reviews @cjihrig @ljharb @benjamingr @MoLow,
I will update PR with required changes ASAP 🚀
also looking at failing tests

pulkit-30 · 2023-02-11T16:17:18Z

test.mjs

import test from 'node:test';

test('should print error cause', () => {
  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;
});

output:

TAP version 13
# Subtest: should print error cause
not ok 1 - should print error cause
  ---
  duration_ms: 0.773584
  failureType: 'testCodeFailure'
  error: 'foo'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:4:9)
    Test.runInAsyncScope (node:async_hooks:206:9)
    ModuleJob.run (node:internal/modules/esm/module_job:193:25) {
      [cause]: Error: bar
          at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:4:34)
          at Test.runInAsyncScope (node:async_hooks:206:9)
          at Test.run (node:internal/test_runner/test:549:25)
          at Test.start (node:internal/test_runner/test:465:17)
          at test (node:internal/test_runner/harness:171:18)
          at file:///Users/pulkitgupta/Desktop/node/_test.mjs:3:1
          at ModuleJob.run (node:internal/modules/esm/module_job:193:25)
    }
  ...
# Subtest: should print error cause for nested errors
not ok 2 - should print error cause for nested errors
  ---
  duration_ms: 1.281542
  failureType: 'testCodeFailure'
  error: 'a'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:8:9)
    Test.runInAsyncScope (node:async_hooks:206:9)
    Test.run (node:internal/test_runner/test:577:10) {
      [cause]: Error: b
          at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:8:33)
          at Test.runInAsyncScope (node:async_hooks:206:9)
          at Test.run (node:internal/test_runner/test:577:10) {
        [cause]: Error: c
            at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:8:57)
            at Test.runInAsyncScope (node:async_hooks:206:9)
            at Test.run (node:internal/test_runner/test:577:10) {
          [cause]: [Error]
        }
      }
    }
  ...
# Subtest: should handle cycles in error
not ok 3 - should handle cycles in error
  ---
  duration_ms: 0.057458
  failureType: 'testCodeFailure'
  error: 'b'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:12:17)
    Test.runInAsyncScope (node:async_hooks:206:9)
    async Test.processPendingSubtests (node:internal/test_runner/test:304:7) {
      [cause]: Error: c
          at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:13:17)
          at Test.runInAsyncScope (node:async_hooks:206:9)
          at async Test.processPendingSubtests (node:internal/test_runner/test:304:7) {
        [cause]: Error: d
            at TestContext.<anonymous> (file:///Users/pulkitgupta/Desktop/node/_test.mjs:13:41)
            at Test.runInAsyncScope (node:async_hooks:206:9)
            at async Test.processPendingSubtests (node:internal/test_runner/test:304:7) {
          [cause]: [Circular *1]
        }
      }
    }
  ...
1..3
# tests 3
# pass 0
# fail 3
# cancelled 0
# skipped 0
# todo 0
# duration_ms 6.749875

@ljharb @cjihrig

cjihrig · 2023-02-11T18:03:01Z

lib/internal/test_runner/reporter/tap.js

@@ -10,10 +10,12 @@ const {
  StringPrototypeReplaceAll,
  StringPrototypeSplit,
  StringPrototypeRepeat,
+  StringPrototypeStartsWith


Please keep these sorted.

cjihrig · 2023-02-11T18:06:01Z

lib/internal/test_runner/reporter/tap.js

 } = primordials;
 const { inspectWithNoCustomRetry } = require('internal/errors');
 const { isError, kEmptyObject } = require('internal/util');
 const { relative } = require('path');
+const util = require('util');


We should use internal/util/inspect.js I think. Also use destructuring to reduce the chance of things being tampered with.

cjihrig · 2023-02-11T18:12:08Z

lib/internal/test_runner/reporter/tap.js


+    if (cause?.cause) {
+      const errCause = util.inspect(cause).split('\n').slice(1)


split(), slice(), filter(), and join() all need to use primordials.

cjihrig · 2023-02-11T18:14:23Z

lib/internal/test_runner/reporter/tap.js


+    if (cause?.cause) {
+      const errCause = util.inspect(cause).split('\n').slice(1)
+                      .filter((line) => !StringPrototypeStartsWith(line.trim(), '...') && line)


It seems like the && line should be line &&. Also, I would check for typeof line === 'string'

cjihrig · 2023-02-11T18:16:18Z

test/message/test_runner_output.js

@@ -383,3 +383,17 @@ 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')});


Please run make lint locally.

cjihrig · 2023-02-11T18:16:50Z

test/message/test_runner_output.out

+    *
+    *
+    *
+    *


I agree with @MoLow here.

GeoffreyBooth · 2023-02-13T01:13:47Z

test/message/test_runner_output.js

@@ -383,3 +383,17 @@ 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')});


Please add Error.stackTraceLimit = 0; to eliminate the stack traces from the output (and therefore the streams of asterisks) unless you’re intending to evaluate something in the stack trace. It’s annoying for tests to start failing because a refactoring changes the number of lines of a stack trace.

MoLow · 2023-02-14T18:33:27Z

test/message/test_runner_describe_it.out

    *
+    *
+    *
+    *
+    *


Suggested change

*

*

*

*

*

*

failureType: 'multipleCallbackInvocations',

cause: 'callback invoked multiple times',

code: 'ERR_TEST_FAILURE'

*

MoLow · 2023-02-14T18:35:44Z

test/message/test_runner_output_cli.out

Suggested change

*

*

*

*

*

*

failureType: 'multipleCallbackInvocations',

cause: 'callback invoked multiple times',

code: 'ERR_TEST_FAILURE'

*

MoLow · 2023-02-14T18:37:00Z

test/message/test_runner_output_cli.out

Suggested change

*

*

*

*

*

*

*

*

*

*

*

*

*

*

[cause]: Error: bar

*

*

*

*

*

MoLow · 2023-02-14T18:38:09Z

test/message/test_runner_output_cli.out

Suggested change

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

[cause]: Error: b

*

*

*

*

[cause]: Error: c

*

*

*

*

[cause]: [Error]

*

*

*

MoLow · 2023-02-14T18:40:06Z

test/message/test_runner_output_cli.out

Suggested change

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

*

[cause]: Error: c

*

*

*

*

[cause]: Error: d

*

*

*

*

[cause]: [Circular *1]

*

*

*

MoLow · 2023-02-14T18:44:41Z

test/message/test_runner_output.js

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


there are still some cases discussed here with no tests:
#46576 (comment)

non error cause (primitives, undefined etc)

cause/stack throws

cause/stack throws

How can I test this?

cause/stack throws

How can I test this?

const error = new Error; Reflect.defineProperty(error, 'cause', { get() { throw null } }); throw error;

MoLow · 2023-02-14T18:45:35Z

test/message/test_runner_output.out

@@ -447,6 +447,10 @@ not ok 50 - callback called twice in future tick
  code: 'ERR_TEST_FAILURE'
  stack: |-
    *
+    *


same suggestions I maid apply to this file as well

MoLow · 2023-02-14T18:45:40Z

test/message/test_runner_output_spec_reporter.out

@@ -262,6 +262,61 @@
  *
  *

+ should print error cause (*ms)


same suggestions I made apply to this file as well

aduh95 · 2023-03-19T11:12:24Z

lib/internal/test_runner/reporter/tap.js

@@ -209,7 +219,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 (cause?.cause) {


Suggested change

if (cause?.cause) {

if (cause != null && ObjectPrototypeHasOwnProperty(cause, 'cause')) {

Otherwise it wouldn't detect a falsy cause (e.g. null, undefined, false, empty string, etc.)

cjihrig · 2023-05-10T13:51:00Z

This has conflicts now and should be superseded by #47867. Closing. Thanks for the PR though.

nodejs-github-bot added dont-land-on-v14.x needs-ci PRs that need a full CI run. test_runner Issues and PRs related to the test runner subsystem. labels Feb 8, 2023

ljharb reviewed Feb 8, 2023

View reviewed changes

MoLow reviewed Feb 9, 2023

View reviewed changes

pulkit-30 force-pushed the fix-44656 branch from 6d254a0 to f0e5658 Compare February 11, 2023 16:17

cjihrig reviewed Feb 11, 2023

View reviewed changes

GeoffreyBooth reviewed Feb 13, 2023

View reviewed changes

pulkit-30 requested review from cjihrig and MoLow and removed request for cjihrig February 14, 2023 16:59

MoLow reviewed Feb 14, 2023

View reviewed changes

pulkit-30 force-pushed the fix-44656 branch from dbd4563 to 4763c82 Compare March 19, 2023 09:09

aduh95 reviewed Mar 19, 2023

View reviewed changes

test: fix test runner does not print error cause

1e13b97

pulkit-30 force-pushed the fix-44656 branch from ce4141a to 1e13b97 Compare March 29, 2023 19:02

targos removed the dont-land-on-v14.x label May 3, 2023

cjihrig closed this May 10, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: fix test runner does not print error cause #46576

test: fix test runner does not print error cause #46576

pulkit-30 commented Feb 8, 2023

nodejs-github-bot commented Feb 8, 2023

ljharb Feb 8, 2023

cjihrig Feb 9, 2023

benjamingr Feb 9, 2023

ljharb Feb 9, 2023

MoLow commented Feb 9, 2023

MoLow Feb 9, 2023 •

edited

Loading

cjihrig Feb 11, 2023

pulkit-30 commented Feb 9, 2023

pulkit-30 commented Feb 11, 2023

cjihrig Feb 11, 2023

cjihrig Feb 11, 2023

cjihrig Feb 11, 2023

cjihrig Feb 11, 2023

cjihrig Feb 11, 2023

cjihrig Feb 11, 2023

GeoffreyBooth Feb 13, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023

pulkit-30 Mar 19, 2023

aduh95 Mar 19, 2023

MoLow Feb 14, 2023

MoLow Feb 14, 2023 •

edited

Loading

aduh95 Mar 19, 2023

cjihrig commented May 10, 2023


		if (cause?.cause) {
		const errCause = util.inspect(cause).split('\n').slice(1)

-    *
-    *
-    *
-    *
-    *
+    *
+      failureType: 'multipleCallbackInvocations',
+      cause: 'callback invoked multiple times',
+      code: 'ERR_TEST_FAILURE'
+    *

	if (cause?.cause) {
	if (cause != null && ObjectPrototypeHasOwnProperty(cause, 'cause')) {

test: fix test runner does not print error cause #46576

test: fix test runner does not print error cause #46576

Conversation

pulkit-30 commented Feb 8, 2023

nodejs-github-bot commented Feb 8, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MoLow commented Feb 9, 2023

MoLow Feb 9, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pulkit-30 commented Feb 9, 2023

pulkit-30 commented Feb 11, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MoLow Feb 14, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cjihrig commented May 10, 2023

MoLow Feb 9, 2023 •

edited

Loading

MoLow Feb 14, 2023 •

edited

Loading