node
node copied to clipboard
nodejs
Test runner does not print Error `cause`
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.
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.
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.
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
@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`))
@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
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'
}
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).
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.