Test runner does not print Error cause

[Qix-]

Version

v18.7.0

Platform

Darwin Joshs-MBP-2 21.6.0 Darwin Kernel Version 21.6.0: Sat Jun 18 17:07:22 PDT 2022; root:xnu-8020.140.41~1/RELEASE_ARM64_T6000 arm64

Subsystem

Test Runner

What steps will reproduce the bug?

import test from 'node:test';

test('error', () => {
	throw new Error('outer', {cause: new Error('inner')});
});

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

Unconditional

What is the expected behavior?

Getting cause output such as:

file:///private/tmp/test-error-cause-test/lib.mjs:1
throw new Error('outer', {cause: new Error('inner')});
      ^

Error: outer
    at file:///private/tmp/test-error-cause-test/lib.mjs:1:7
    at ModuleJob.run (node:internal/modules/esm/module_job:193:25)
    ... 3 lines matching cause stack trace ...
    at async handleMainPromise (node:internal/modules/run_main:65:12) {
  [cause]: Error: inner
      at file:///private/tmp/test-error-cause-test/lib.mjs:1:34
      at ModuleJob.run (node:internal/modules/esm/module_job:193:25)
      at async Promise.all (index 0)
      at async ESMLoader.import (node:internal/modules/esm/loader:541:24)
      at async loadESM (node:internal/process/esm_loader:91:5)
      at async handleMainPromise (node:internal/modules/run_main:65:12)
}

Node.js v18.7.0

What do you see instead?

(partial TAP output)

  failureType: 'testCodeFailure'
  error: 'outer'
  code: 'ERR_TEST_FAILURE'
  stack: |-
    TestContext.<anonymous> (file:///private/tmp/test-error-cause-test/cli.mjs:4:8)
    Test.runInAsyncScope (node:async_hooks:203:9)
    Test.run (node:internal/test_runner/test:417:25)
    Test.start (node:internal/test_runner/test:367:17)
    Test.test (node:internal/test_runner/harness:149:18)
    file:///private/tmp/test-error-cause-test/cli.mjs:3:1
    ModuleJob.run (node:internal/modules/esm/module_job:193:25)
    async Promise.all (index 0)
    async ESMLoader.import (node:internal/modules/esm/loader:541:24)
    async loadESM (node:internal/process/esm_loader:91:5)
  ...

Additional information

The cause parameter is essential in understanding e.g. undici's (Node.js's "native" fetch() implementation) error messages as otherwise you just get a cryptic fetch failed error message. This is a huge pain point in trying to adopt the test runner for a new project.

[Qix-]

It looks like err.stack is used for the output, but using util.format(err) is what yields the correct cause output. Not sure if that's the Correct Way but I'm willing to submit a PR if that's an appropriate fix.

I'm sure somewhere a conversation has been had about what .stack returns for legacy reasons or something, but first reaction is that that would be where this should be updated.

[BridgeAR]

That would be great! Using util.inspect(error) would indeed be the correct way.

Side note: we might want to add a linter rule that prevents using .stack in lib. It might just have a couple of false positives though.

[MoLow]

there is some splitting and parsing done on the stack trace - I assume it is there to make sure the YAML is valid
CC @cjihrig

[Qix-]

@BridgeAR to be clear, is .inspect() or .format() more preferable? My gut instinct also says .inspect() but just want to be sure.

@MoLow looks like just a |- with the first line removed and properly indented, no?

Something like

util.inspect(error).split('\n').slice(1).forEach(line => stream.write(`${indent}${line}\n`))

[MoLow]

@Qix- the parsing also converts a stack trace from at .. function (file:line:col) to function (file:line:col)
and you would probably also want to add leftTrim

[Qix-]

Extra error properties would kind of blend in though, was there a specific reason at was omitted?

e.g. without any processing (though I manually removed the first line)

> console.log(util.inspect((() => { e = new Error('hi'); e.foo = 'bar'; return e})()))

    at REPL25:1:39
    at REPL25:1:81
    at Script.runInThisContext (node:vm:129:12)
    at REPLServer.defaultEval (node:repl:572:29)
    at bound (node:domain:433:15)
    at REPLServer.runBound [as eval] (node:domain:444:12)
    at REPLServer.onLine (node:repl:902:10)
    at REPLServer.emit (node:events:525:35)
    at REPLServer.emit (node:domain:489:12)
    at [_onLine] [as _onLine] (node:internal/readline/interface:425:12) {
  foo: 'bar'
}

vs with trim + at removal:

> console.log(util.inspect((() => { e = new Error('hi'); e.foo = 'bar'; return e})()).split('\n').map(l => l.trimLeft().replace(/^at /, '')).join('\n'))

REPL28:1:39
REPL28:1:81
Script.runInThisContext (node:vm:129:12)
REPLServer.defaultEval (node:repl:572:29)
bound (node:domain:433:15)
REPLServer.runBound [as eval] (node:domain:444:12)
REPLServer.onLine (node:repl:902:10)
REPLServer.emit (node:events:525:35)
REPLServer.emit (node:domain:489:12)
[_onLine] [as _onLine] (node:internal/readline/interface:425:12) {
foo: 'bar'
}

[MoLow]

was there a specific reason at was omitted?

Waiting for @cjihrig to answer

[cjihrig]

No particular reason. It was more of a stylistic choice.

[MoLow]

@qix waiting for a PR then

[BridgeAR]

In case leading whitespace is not required: it's possible to define that as an option using util.inspect(). That way there's no need to trim the whitespace (even though I believe it's easier to read in case it's kept. I am just not sure if it's required to keep it for a specific output).

[Qix-]

Haven't forgotten about this - trying to get tests on main working first.

Looking at the implementation, I'd be stripping away a lot of logic that's there just by switching to util.inspect(). Since we're trying to serve YAML results a la TAP, perhaps I can do something a bit more 'proper'.

Would it be beneficial to instead output a YAML array of causes (iterating over the error object until !cause is true) and outputting each of the errors as an array entry? That would also allow for custom properties to be mapped to YAML object keys for each array entry as well.

Something like...

try {
    somethingThatThrows();
} catch (error) {
    const err = new Error('operation failed', {cause: error});
    err.foo = 'BAR';
    throw err;
}

- message: operation failed
  stack:
  - ...
  - ...
  - ...
  foo: BAR
- message: internal error
  code: INTERNAL_ERROR
  stack:
  - somethingThatThrows() (...)
  - ...
  - ...

Not sure if that's breaking the TAP protocol at all but handles this case well whilst adding more value to the YAML output, in my opinion.

[cjihrig]

This should be fixed once #47867 lands.