search

nodejs / help

:sparkles: Need help with Node.js? File an Issue here. :rocket:
1.44k stars 276 forks source link

Node.js should log properly AggregateError when nested in Error.cause #4337

Open slorber opened 5 months ago

slorber commented 5 months ago

Version

21.6.1

Platform

MacOS 14.3 (23D56)

Subsystem

No response

What steps will reproduce the bug?

Node shell:

Logging an AggregateError is rendered as expected:

node
Welcome to Node.js v21.6.1.
Type ".help" for more information.
>
> console.log("GOOD",new AggregateError([
...   new Error("parent 1",{cause: new Error("cause 1")}),
...   new Error("parent 2",{cause: new Error("cause 2")}),
... ]))
GOOD AggregateError
    at REPL5:1:20
    at ContextifyScript.runInThisContext (node:vm:121:12)
    at REPLServer.defaultEval (node:repl:598:22)
    at bound (node:domain:432:15)
    at REPLServer.runBound [as eval] (node:domain:443:12)
    at REPLServer.onLine (node:repl:927:10)
    at REPLServer.emit (node:events:531:35)
    at REPLServer.emit (node:domain:488:12)
    at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)
    at [_line] [as _line] (node:internal/readline/interface:887:18) {
  [errors]: [
    Error: parent 1
        at REPL5:2:3
        at ContextifyScript.runInThisContext (node:vm:121:12)
        ... 7 lines matching cause stack trace ...
        at [_line] [as _line] (node:internal/readline/interface:887:18) {
      [cause]: Error: cause 1
          at REPL5:2:32
          at ContextifyScript.runInThisContext (node:vm:121:12)
          at REPLServer.defaultEval (node:repl:598:22)
          at bound (node:domain:432:15)
          at REPLServer.runBound [as eval] (node:domain:443:12)
          at REPLServer.onLine (node:repl:927:10)
          at REPLServer.emit (node:events:531:35)
          at REPLServer.emit (node:domain:488:12)
          at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)
          at [_line] [as _line] (node:internal/readline/interface:887:18)
    },
    Error: parent 2
        at REPL5:3:3
        at ContextifyScript.runInThisContext (node:vm:121:12)
        ... 7 lines matching cause stack trace ...
        at [_line] [as _line] (node:internal/readline/interface:887:18) {
      [cause]: Error: cause 2
          at REPL5:3:32
          at ContextifyScript.runInThisContext (node:vm:121:12)
          at REPLServer.defaultEval (node:repl:598:22)
          at bound (node:domain:432:15)
          at REPLServer.runBound [as eval] (node:domain:443:12)
          at REPLServer.onLine (node:repl:927:10)
          at REPLServer.emit (node:events:531:35)
          at REPLServer.emit (node:domain:488:12)
          at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)
          at [_line] [as _line] (node:internal/readline/interface:887:18)
    }
  ]
}

But the AggregateError becomes unusable when we use {cause: new AggregateError()}

> console.log("BAD",new Error(
...   "top-level",
...   {cause: new AggregateError([
...     new Error("parent 1",{cause: new Error("cause 1")}),
...     new Error("parent 2",{cause: new Error("cause 2")}),
...   ])}
... ))
BAD Error: top-level
    at REPL15:1:19
    at ContextifyScript.runInThisContext (node:vm:121:12)
    ... 7 lines matching cause stack trace ...
    at [_line] [as _line] (node:internal/readline/interface:887:18) {
  [cause]: AggregateError
      at REPL15:3:11
      at ContextifyScript.runInThisContext (node:vm:121:12)
      at REPLServer.defaultEval (node:repl:598:22)
      at bound (node:domain:432:15)
      at REPLServer.runBound [as eval] (node:domain:443:12)
      at REPLServer.onLine (node:repl:927:10)
      at REPLServer.emit (node:events:531:35)
      at REPLServer.emit (node:domain:488:12)
      at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)
      at [_line] [as _line] (node:internal/readline/interface:887:18) {
    [errors]: [ [Error], [Error] ]
  }
}
undefined

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

Always reproduces (on my computer + node 20/21 latest)

What is the expected behavior? Why is that the expected behavior?

The nested AggregateError should print all the involved errors, and their respective causes, so that we can probably troubleshoot the errors and see the root causes.

What do you see instead?

The AggregateError is rendered as "folded" and we cannot see details of individual errors.

Printing [errors]: [ [Error], [Error] ] is not actionable

Additional information

No response

BridgeAR commented 5 months ago

The issue is the default nesting level that is inspected. It is currently a trade off that is done. If you want to log the whole error, you can always call util.inspect() directly and log the result: console.log(util.inspect(deeplyNestedError, { depth: 10 }))

slorber commented 5 months ago

Thanks @BridgeAR.

Indeed I see the same problem when nesting regular erro cause errors.

Didn't know about util.inspect, that looks like a useful tool to use in my case.

const error = new Error("1", {
  cause: new Error("2", {
    cause: { cause: new Error("3", { cause: new Error("4") }) },
  }),
});

Is it fair to conclude that those 2 are equivalent?

Or are there default params to apply to inspect to get the same behavior?

console.log(error);

console.log(require("node:util").inspect(error));

FYI: unrelated but I initially thought my bug report disappeared when it was moved to this other repo. No GitHub notification. By chance I saved the url somewhere 😄

hebosho911 commented 4 months ago

Version

21.6.1

Platform

MacOS 14.3 (23D56)

Subsystem

No response

What steps will reproduce the bug?

Node shell:

Logging an AggregateError is rendered as expected:


node

Welcome to Node.js v21.6.1.

Type ".help" for more information.

>

> console.log("GOOD",new AggregateError([

...   new Error("parent 1",{cause: new Error("cause 1")}),

...   new Error("parent 2",{cause: new Error("cause 2")}),

... ]))

GOOD AggregateError

    at REPL5:1:20

    at ContextifyScript.runInThisContext (node:vm:121:12)

    at REPLServer.defaultEval (node:repl:598:22)

    at bound (node:domain:432:15)

    at REPLServer.runBound [as eval] (node:domain:443:12)

    at REPLServer.onLine (node:repl:927:10)

    at REPLServer.emit (node:events:531:35)

    at REPLServer.emit (node:domain:488:12)

    at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)

    at [_line] [as _line] (node:internal/readline/interface:887:18) {

  [errors]: [

    Error: parent 1

        at REPL5:2:3

        at ContextifyScript.runInThisContext (node:vm:121:12)

        ... 7 lines matching cause stack trace ...

        at [_line] [as _line] (node:internal/readline/interface:887:18) {

      [cause]: Error: cause 1

          at REPL5:2:32

          at ContextifyScript.runInThisContext (node:vm:121:12)

          at REPLServer.defaultEval (node:repl:598:22)

          at bound (node:domain:432:15)

          at REPLServer.runBound [as eval] (node:domain:443:12)

          at REPLServer.onLine (node:repl:927:10)

          at REPLServer.emit (node:events:531:35)

          at REPLServer.emit (node:domain:488:12)

          at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)

          at [_line] [as _line] (node:internal/readline/interface:887:18)

    },

    Error: parent 2

        at REPL5:3:3

        at ContextifyScript.runInThisContext (node:vm:121:12)

        ... 7 lines matching cause stack trace ...

        at [_line] [as _line] (node:internal/readline/interface:887:18) {

      [cause]: Error: cause 2

          at REPL5:3:32

          at ContextifyScript.runInThisContext (node:vm:121:12)

          at REPLServer.defaultEval (node:repl:598:22)

          at bound (node:domain:432:15)

          at REPLServer.runBound [as eval] (node:domain:443:12)

          at REPLServer.onLine (node:repl:927:10)

          at REPLServer.emit (node:events:531:35)

          at REPLServer.emit (node:domain:488:12)

          at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)

          at [_line] [as _line] (node:internal/readline/interface:887:18)

    }

  ]

}

But the AggregateError becomes unusable when we use {cause: new AggregateError()}


> console.log("BAD",new Error(

...   "top-level",

...   {cause: new AggregateError([

...     new Error("parent 1",{cause: new Error("cause 1")}),

...     new Error("parent 2",{cause: new Error("cause 2")}),

...   ])}

... ))

BAD Error: top-level

    at REPL15:1:19

    at ContextifyScript.runInThisContext (node:vm:121:12)

    ... 7 lines matching cause stack trace ...

    at [_line] [as _line] (node:internal/readline/interface:887:18) {

  [cause]: AggregateError

      at REPL15:3:11

      at ContextifyScript.runInThisContext (node:vm:121:12)

      at REPLServer.defaultEval (node:repl:598:22)

      at bound (node:domain:432:15)

      at REPLServer.runBound [as eval] (node:domain:443:12)

      at REPLServer.onLine (node:repl:927:10)

      at REPLServer.emit (node:events:531:35)

      at REPLServer.emit (node:domain:488:12)

      at [_onLine] [as _onLine] (node:internal/readline/interface:416:12)

      at [_line] [as _line] (node:internal/readline/interface:887:18) {

    [errors]: [ [Error], [Error] ]

  }

}

undefined

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

Always reproduces (on my computer + node 20/21 latest)

What is the expected behavior? Why is that the expected behavior?

The nested AggregateError should print all the involved errors, and their respective causes, so that we can probably troubleshoot the errors and see the root causes.

What do you see instead?

The AggregateError is rendered as "folded" and we cannot see details of individual errors.

Printing [errors]: [ [Error], [Error] ] is not actionable

Additional information

No response