Test runner naively rethrows non-testing error without preserving stack trace

[timmolendijk]

Version

v18.8.0

Platform

Darwin Tims-MacBook-Pro.local 21.6.0 Darwin Kernel Version 21.6.0: Wed Aug 10 14:28:23 PDT 2022; root:xnu-8020.141.5~2/RELEASE_ARM64_T6000 arm64

Subsystem

test runner

What steps will reproduce the bug?

The following line of code in the test runner harness rethrows an error if it is not coming from a test:

node/lib/internal/test_runner/harness.js

Line 35 in 59527de

throw err;

In the process err.stack is lost, while this is crucial information for understanding what went wrong.

How often does it reproduce? Is there a required condition?

I am not familiar enough with the test runner’s architecture, but I think this is relevant in scenarios where the code that throws the original error runs in a timer such as setInterval.

What is the expected behavior?

The test runner’s stdout includes the original error’s stack trace.

What do you see instead?

The test runner only displays the stack trace of the rethrown error, which isn’t very helpful.

Additional information

No response

[MoLow]

why isn't this expected?

[timmolendijk]

When the code that is being tested crashes, either the code is broken or the test is broken (or both). You want to then be able to debug this with full information. Currently the test runner catches non-testing errors and strips them of their stack trace. This makes debugging unnecessarily hard.

So in other words: I expect a test runner to give me (at least) the same information about what’s going wrong with my code as I am given when I run my code directly (without a test runner).

[tniessen]

I expect a test runner to give me (at least) the same information about what’s going wrong with my code as I am given when I run my code directly (without a test runner).

I haven't been able to reproduce the issue, could you provide some example code?

This code appears to retain the stack trace in the test runner output:

import test from 'node:test';

function someOtherFunction() {
  throw new Error('foo');
}

function someFunction() {
  someOtherFunction();
}

test('foo', async () => {
  someFunction();
});

TAP version 13
# Subtest: /home/tniessen/dev/github-44611/test2.mjs
not ok 1 - /home/tniessen/dev/github-44611/test2.mjs
  ---
  duration_ms: 46.156969
  failureType: 'subtestsFailed'
  exitCode: 1
  stdout: |-
    TAP version 13
    # Subtest: foo
    not ok 1 - foo
      ---
      duration_ms: 1.360099
      failureType: 'testCodeFailure'
      error: 'foo'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        someOtherFunction (file:///home/tniessen/dev/github-44611/test2.mjs:4:9)
        someFunction (file:///home/tniessen/dev/github-44611/test2.mjs:8:3)
        TestContext.<anonymous> (file:///home/tniessen/dev/github-44611/test2.mjs:12:3)
        Test.runInAsyncScope (node:async_hooks:203:9)
        Test.run (node:internal/test_runner/test:483:25)
        Test.start (node:internal/test_runner/test:410:17)
        test (node:internal/test_runner/harness:129:18)
        file:///home/tniessen/dev/github-44611/test2.mjs:11:1
        ModuleJob.run (node:internal/modules/esm/module_job:193:25)
        async Promise.all (index 0)
      ...
    1..1
    # tests 1
    # pass 0
    # fail 1
    # cancelled 0
    # skipped 0
    # todo 0
    # duration_ms 5.581997
    
  stderr: |-
    (node:19927) ExperimentalWarning: The test runner is an experimental feature. This feature could change at any time
    (Use `node --trace-warnings ...` to show where the warning was created)
    
  error: 'test failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1
# tests 1
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 49.141167

[timmolendijk]

import test from 'node:test';

function someOtherFunction() {
  throw new Error('foo');
}

test('foo', async () => {
  await new Promise(resolve => {
    setTimeout(() => {
      someOtherFunction();
      resolve();
    });
  });
});

TAP version 13
# Subtest: /Users/tim/Documents/dev/testje/test/stacktrace.mjs
not ok 1 - /Users/tim/Documents/dev/testje/test/stacktrace.mjs
  ---
  duration_ms: 0.040104209
  failureType: 'subtestsFailed'
  exitCode: 1
  stdout: |-
    TAP version 13
    # Subtest: foo
    not ok 1 - foo
      ---
      duration_ms: 0.001857459
      failureType: 'uncaughtException'
      error: 'foo'
      code: 'ERR_TEST_FAILURE'
      stack: |-
        process.emit (node:events:513:28)            👈👈👈
      ...
    1..1
    # tests 1
    # pass 0
    # fail 1
    # cancelled 0
    # skipped 0
    # todo 0
    # duration_ms 0.025160167

  stderr: |-
    (node:79000) ExperimentalWarning: The test runner is an experimental feature. This feature could change at any time
    (Use `node --trace-warnings ...` to show where the warning was created)

  error: 'test failed'
  code: 'ERR_TEST_FAILURE'
  ...
1..1
# tests 1
# pass 0
# fail 1
# cancelled 0
# skipped 0
# todo 0
# duration_ms 0.070254083

[tniessen]

Thanks, I can reproduce this. Because this does not seem to happen when removing the test runner boilerplate, I am assuming it is indeed a bug in the test runner.