feat(core): print cause of uncaught errors in their stack trace

[thibseisel]

PR Checklist

Please check if your PR fulfills the following requirements:

• The commit message follows our guidelines: https://github.com/nestjs/nest/blob/master/CONTRIBUTING.md
• Tests for the changes have been added (for bug fixes / features)
• Docs have been added / updated (for bug fixes / features)

PR Type

What kind of change does this PR introduce?

• Bugfix
• Feature
• Code style update (formatting, local variables)
• Refactoring (no functional changes, no api changes)
• Build related changes
• CI related changes
• Other... Please describe:

What is the current behavior?

Issue Number: #13550

When an uncaught error is thrown, NestJS handles it using the configured ExceptionFilter. If the default filter is not overridden, the error is logged under the ExceptionsHandler tag with its message and stack trace.

Since ECMAScript 2022, the Error constructor accepts a new cause parameter option. The cause of an Error is printed to the console when passed to console.error:

const cause = new Error("The real cause of our problem");
const error = new Error("Something went wrong here", { cause })
const caught = new Error("An unexpected error occurred", { cause: exception });
console.error(caught);

// prints stack trace, recursively specifying the cause
Error: An unexpected error occurred
    at REPL3:1:14
    at ContextifyScript.runInThisContext (node:vm:136:12)
    ... 7 lines matching cause stack trace ...
    at [_line] [as _line] (node:internal/readline/interface:888:18) {
  [cause]: Error: Something went wrong here
      at REPL2:1:13
      at ContextifyScript.runInThisContext (node:vm:136:12)
      ... 7 lines matching cause stack trace ...
      at [_line] [as _line] (node:internal/readline/interface:888:18) {
    [cause]: Error: The real cause of our problem
        at REPL1:1:13
        at ContextifyScript.runInThisContext (node:vm:136: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:417:12)
        at [_line] [as _line] (node:internal/readline/interface:888:18)
  }
}

But since NestJS only considers the caught error's stack trace, it does not include the root causes, making it hard to diagnose issues. The above example would only print something like the following:

Error: An unexpected error occurred
    at REPL3:1:14
    at ContextifyScript.runInThisContext (node:vm:136:12)
    ... 7 lines matching cause stack trace ...
    at [_line] [as _line] (node:internal/readline/interface:888:18)

What is the new behavior?

When an unexpected error occurs, NestJS now recursively logs error causes. This only focuses on error causes and does not display any custom property error objects may have.

The above example would generate the following stack trace:

Error: An unexpected error occurred
    at REPL3:1:14
    at ContextifyScript.runInThisContext (node:vm:136:12)
Caused by Error: Something went wrong here
    at REPL2:1:13
    at ContextifyScript.runInThisContext (node:vm:136:12)
Caused by Error: The real cause of our problem
    at REPL1:1:13
    at ContextifyScript.runInThisContext (node:vm:136:12)

Does this PR introduce a breaking change?

• Yes
• No

This change makes sure that stack trace of errors without a cause are logged exactly the same way as before.
The only impact is that logged error stack traces may be longer. Deeply nested errors may cause logs to be less readable.

Other information

None.

[kamilmysliwiec]

There are 2 failing unit tests

Thanks for your contribution!

[coveralls]

Pull Request Test Coverage Report for Build d4ce9edb-19ae-400b-bef2-ac4fb9aa2f87

Details

• 12 of 12 (100.0%) changed or added relevant lines in 4 files are covered.
• No unchanged relevant lines lost coverage.
• Overall coverage increased (+0.01%) to 92.219%

---

Totals
Change from base Build c9b17776-8993-4d3d-9083-ccfdef03782e:	0.01%
Covered Lines:	6756
Relevant Lines:	7326

---

💛 - Coveralls

[jochongs]

I've updated the test cases for the exception handler and submitted a PR for your review.

thibseisel#3

---

I noticed an issue in the existing test code, so I made the necessary adjustments and included them in this PR as well.

Currently, in the exception-handler.spec.ts file, the second test case seems to be designed for a scenario where the exception is not a RuntimeException.

nest/packages/core/test/errors/test/exception-handler.spec.ts

Lines 28 to 32 in 38c0548

	it('when exception is not instanceof RuntimeException', () => {
	const exception = new InvalidMiddlewareException('msg');
	instance.handle(exception);
	expect(errorSpy.calledWith(exception.what(), exception.stack)).to.be.true;
	});

However, the InvalidMiddlewareException used in the test appears to inherit from RuntimeException.

nest/packages/core/errors/exceptions/invalid-middleware.exception.ts

Lines 4 to 8 in 38c0548

	export class InvalidMiddlewareException extends RuntimeException {
	constructor(name: string) {
	super(INVALID_MIDDLEWARE_MESSAGE`${name}`);
	}
	}

To better match the intended test scenario, I have modified the exception variable to be an instance of Error instead of InvalidMiddlewareException.

@thibseisel Please take a look at my PR as well. Thanks. :)

[thibseisel]

@jochongs I just accepted your PR, thank you!

Also, I'd like to emphasize that unlike my initial implementation, this change no longer displays custom properties of an Error, only its chain of causes. This is because I decided to write a custom combineStackTrace function instead of relying on util.inspect, so that the generated stack trace is more compact.
This may no be what you initially wanted, please let me know if you'd like to make any change.

[jochongs]

@thibseisel

I’ve been thinking about the decision to print only the cause. I wonder if there might be value in printing all attributes of the Error object instead. I believe this could provide more comprehensive information for debugging. Was there a specific reason for choosing to print only the cause?

(I couldn’t find the original commit where inspect method was used, so I created this PR to compare the code. #13875)

[kamilmysliwiec]

I'm somewhat leaning toward printing all attributes too. Is there any specific reason we should consider printing only the cause prop?

[thibseisel]

@jochongs @kamilmysliwiec I omitted custom properties essentially to reduce verbosity. String properties are rather short, but some deep objects could make the stack-trace unreasonably long (I'm pointing at you, Node.js streams!).

I'm not against the idea though. Some custom errors have useful properties, for example AxiosError exposes the HTTP status code and response body.