Skip to content

Test runner does not print Error cause #44656

Description

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

Activity

  1. added
    test_runnerIssues and PRs related to the test runner subsystem.
    on Sep 15, 2022
  2. Qix- commented on Sep 15, 2022

    @Qix-
    Author

    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.

  3. BridgeAR commented on Sep 15, 2022

    @BridgeAR
    Member

    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.

  4. MoLow commented on Sep 15, 2022

    @MoLow
    Member

    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

  5. Qix- commented on Sep 15, 2022

    @Qix-
    Author

    @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`))
  6. MoLow commented on Sep 15, 2022

    @MoLow
    Member

    @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

  7. Qix- commented on Sep 15, 2022

    @Qix-
    Author

    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'
    }
    
  8. MoLow commented on Sep 15, 2022

    @MoLow
    Member

    was there a specific reason at was omitted?

    Waiting for @cjihrig to answer

  9. cjihrig commented on Sep 15, 2022

    @cjihrig
    Contributor

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

  10. MoLow commented on Sep 15, 2022

    @MoLow
    Member

    @qix waiting for a PR then

  11. BridgeAR commented on Sep 16, 2022

    @BridgeAR
    Member

    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).

  12. Qix- commented on Sep 19, 2022

    @Qix-
    Author

    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.

  13. cjihrig commented on May 10, 2023

    @cjihrig
    Contributor

    This should be fixed once #47867 lands.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    test_runnerIssues and PRs related to the test runner subsystem.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions