process: split routines used to enhance fatal exception stack traces #28308

joyeecheung · 2019-06-19T23:30:06Z

Previously the enhancement were done right after emitting
'uncaughtException', which meant by the time we knew the
exception was fatal in C++, the error.stack had already been
patched.

This patch moves those routines to be called later during the
fatal exception handling, and split them into two stages:
before and after the inspector is notified by the invocation of
V8Inspector::exceptionThrown. We now expand the stack to include
additional informations about unhandled 'error' events before
the inspector is notified, but delay the highlighting of the
frames until after the inspector is notified, so that the
ANSI escape sequences won't show up in the inspector console.

Fixes: #28287

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
commit message follows commit guidelines

Previously the enhancement were done right after emitting `'uncaughtException'`, which meant by the time we knew the exception was fatal in C++, the error.stack had already been patched. This patch moves those routines to be called later during the fatal exception handling, and split them into two stages: before and after the inspector is notified by the invocation of `V8Inspector::exceptionThrown`. We now expand the stack to include additional informations about unhandled 'error' events before the inspector is notified, but delay the highlighting of the frames until after the inspector is notified, so that the ANSI escape sequences won't show up in the inspector console.

nodejs-github-bot · 2019-06-19T23:32:11Z

CI: https://ci.nodejs.org/job/node-test-pull-request/23988/

joyeecheung · 2019-06-19T23:37:19Z

lib/internal/errors.js

+    try {
+      // Set the error.stack here so it gets picked up by the
+      // inspector.
+      error.stack = error[kEnhanceStackBeforeInspector]();


Ideally we probably should not even have to do this, instead we can just return a string to some API and leave the error.stack intact, because patching error.stack (which is just a randomly formatted string) over and over is error-prone, especially in the presence of Error.prepareStackTrace...but there does not seem to be a hook to customize the stack trace in the console message logged by the inspector.

Yeah and error.stack might not be writeable, (should be fine in this case)

joyeecheung · 2019-06-19T23:53:02Z

lib/internal/errors.js

+    try {
+      return inspect(error, { colors });
+    } catch {
+      return originalStack;


Note that here we don't patch error.stack at all - patching error.stack is only one of the many ways to pass some metadata around along with the error. The cleanest way, however, is to just wrap those metadata in something else instead of polluting error itself over and over, which is also what V8 does in its embedder API (the source of truth of the stack trace is message->GetStackTrace(), not error->Get(context, stack_string), and there are many other structured metadata in Message)

Ideally we could also just pass structured data (e.g. error.code, error.requireStack) back to the caller and it knows how to format and print those out without relying on error.stack at all

Can't we do this in a WeakMap? Their point is extending things from the outside after all

I don't think we need a WeakMap for this, as this is kind of a one-off thing so there is no mapping necessary. We only need to pass a separate object around, the association between the error and the object can already be known from how they are passed around, and we probably don't need an equivalent of Exception::CreateMessage.

(Also now that you mentioned it...I believe V8 still does not have embedder API to interface with WeakMaps? That's why we still have to create our ESM module wrap map in JS land)

Hakerh400 · 2019-06-20T00:04:10Z

Very nice, I'm ok with closing my PR in favor of this, but these patches still don't work on Windows. Tested on Windows 8.1 Pro 6.3.9600, got the following output in the console:

C:\> node-60e3f81.exe -e "throw new Error"
[eval]:1
throw new Error
^

Error
    at [eval]:1:7
←[90m    at Script.runInThisContext (vm.js:123:20)←[39m
←[90m    at Object.runInThisContext (vm.js:313:38)←[39m
    at Object.<anonymous> ([eval]-wrapper:9:26)
←[90m    at Module._compile (internal/modules/cjs/loader.js:779:30)←[39m
←[90m    at evalScript (internal/process/execution.js:80:25)←[39m
←[90m    at internal/main/eval_string.js:23:3←[39m

Or is this not supposed to work on Windows?

joyeecheung · 2019-06-20T00:08:29Z

@Hakerh400 See #28291 (comment) - that requires a different fix in PrintErrorString(), but then that's a separate issue from #28287 - it already does not work on Windows on master anyway, and I don't think removing the feature for every platform should be the fix.

nodejs-github-bot · 2019-06-25T15:16:32Z

CI: https://ci.nodejs.org/job/node-test-pull-request/24088/

joyeecheung · 2019-06-26T14:38:38Z

@BridgeAR @nodejs/process @addaleax

CI is happy. Can I have some reviews please?

joyeecheung · 2019-06-26T14:44:16Z

lib/internal/errors.js

+    } = lazyInternalUtilInspect();
+    const colors = internalBinding('util').guessHandleType(2) === 'TTY' &&
+                   require('internal/tty').hasColors() ||
+                   defaultColors;


On the windows issue: we could temporarily disable the coloring by adding process.plaform === 'win32' to the conditions here, though I would prefer an alternative fix with changing the implementation of PrintErrorString() to use uv_write for TTY instead. I have a WIP in https://github.com/joyeecheung/node/tree/print-uv-write which still fails a few tests that I need to investigate. Either way that's kind of orthognal to this PR as this only tries to fix #28287

Trott · 2019-06-26T15:52:45Z

Is it worth the effort to add a test for the changed behavior?

benjamingr

I have a feeling I've seen some of those changes before in another PR, code runs fine and changes seem positive and reasonable.

A test would be great.

joyeecheung · 2019-06-27T11:47:00Z

@Trott This is testing behaviors after the error thrown is identified as fatal, which means we cannot count on any notification to the test about the changed behavior when they are in the same process. We could test that reliably if um...we have an out-of-process WebSocket client in this code base, but I don't think the test is worth that dependency people have been arguing about for years :S

We might consider reporting to inspector even when the error is handled by uncaughtException and is not fatal anymore (that's also somewhat reasonable IMO and match the behavior of chrome's window.addEventListener('error')), that way we do have a reliable place to test the stack reported to the inspector (given that the inspector protocol implementation is synchronous), but that would be a separate change.

joyeecheung · 2019-06-27T12:28:46Z

Landed in 9445492

Previously the enhancement were done right after emitting `'uncaughtException'`, which meant by the time we knew the exception was fatal in C++, the error.stack had already been patched. This patch moves those routines to be called later during the fatal exception handling, and split them into two stages: before and after the inspector is notified by the invocation of `V8Inspector::exceptionThrown`. We now expand the stack to include additional informations about unhandled 'error' events before the inspector is notified, but delay the highlighting of the frames until after the inspector is notified, so that the ANSI escape sequences won't show up in the inspector console. PR-URL: #28308 Fixes: #28287 Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

nodejs-github-bot added the lib / src Issues and PRs related to general changes in the lib or src directory. label Jun 19, 2019

joyeecheung mentioned this pull request Jun 19, 2019

process: improve handling of formatted error stack #28291

Closed

2 tasks

joyeecheung commented Jun 19, 2019

View reviewed changes

joyeecheung commented Jun 26, 2019

View reviewed changes

benjamingr approved these changes Jun 26, 2019

View reviewed changes

joyeecheung closed this Jun 27, 2019

targos mentioned this pull request Jul 2, 2019

Release v12.6.0 proposal #28508

Merged

This was referenced Jul 3, 2019

2019-07-03 Version 12.6.0 (Current) @targos beevelop/docker-nodejs#288

Closed

2019-07-03 Version 12.6.0 (Current) @targos beevelop/docker-nodejs#289

Closed

2019-07-03 Version 12.6.0 (Current) @targos beevelop/docker-nodejs#290

Closed

Hakerh400 mentioned this pull request Aug 31, 2019

Uncaught error stack trace is misformatted on some platforms #29387

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

process: split routines used to enhance fatal exception stack traces #28308

process: split routines used to enhance fatal exception stack traces #28308

joyeecheung commented Jun 19, 2019 •

edited

Loading

nodejs-github-bot commented Jun 19, 2019

joyeecheung Jun 19, 2019 •

edited

Loading

benjamingr Jun 26, 2019

joyeecheung Jun 19, 2019 •

edited

Loading

benjamingr Jun 26, 2019

joyeecheung Jun 27, 2019

joyeecheung Jun 27, 2019

Hakerh400 commented Jun 20, 2019

joyeecheung commented Jun 20, 2019 •

edited

Loading

nodejs-github-bot commented Jun 25, 2019

joyeecheung commented Jun 26, 2019

joyeecheung Jun 26, 2019 •

edited

Loading

Trott commented Jun 26, 2019

benjamingr left a comment

joyeecheung commented Jun 27, 2019 •

edited

Loading

joyeecheung commented Jun 27, 2019

process: split routines used to enhance fatal exception stack traces #28308

process: split routines used to enhance fatal exception stack traces #28308

Conversation

joyeecheung commented Jun 19, 2019 • edited Loading

Checklist

nodejs-github-bot commented Jun 19, 2019

joyeecheung Jun 19, 2019 • edited Loading

Choose a reason for hiding this comment

benjamingr Jun 26, 2019

Choose a reason for hiding this comment

joyeecheung Jun 19, 2019 • edited Loading

Choose a reason for hiding this comment

benjamingr Jun 26, 2019

Choose a reason for hiding this comment

joyeecheung Jun 27, 2019

Choose a reason for hiding this comment

joyeecheung Jun 27, 2019

Choose a reason for hiding this comment

Hakerh400 commented Jun 20, 2019

joyeecheung commented Jun 20, 2019 • edited Loading

nodejs-github-bot commented Jun 25, 2019

joyeecheung commented Jun 26, 2019

joyeecheung Jun 26, 2019 • edited Loading

Choose a reason for hiding this comment

Trott commented Jun 26, 2019

benjamingr left a comment

Choose a reason for hiding this comment

joyeecheung commented Jun 27, 2019 • edited Loading

joyeecheung commented Jun 27, 2019

joyeecheung commented Jun 19, 2019 •

edited

Loading

joyeecheung Jun 19, 2019 •

edited

Loading

joyeecheung Jun 19, 2019 •

edited

Loading

joyeecheung commented Jun 20, 2019 •

edited

Loading

joyeecheung Jun 26, 2019 •

edited

Loading

joyeecheung commented Jun 27, 2019 •

edited

Loading