Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Confusing stack trace when using --abort-on-uncaught-exception #21988

Closed
mmarchini opened this issue Jul 26, 2018 · 13 comments
Closed

Confusing stack trace when using --abort-on-uncaught-exception #21988

mmarchini opened this issue Jul 26, 2018 · 13 comments
Labels
post-mortem Issues and PRs related to the post-mortem diagnostics of Node.js. v8 engine Issues and PRs related to the V8 dependency.

Comments

@mmarchini
Copy link
Contributor

  • Version: master
  • Platform: OS X
  • Subsystem: errors

When using --abort-on-uncaught-exception, all lines in the stack trace appear as 1:1 instead of the actual line and column numbers.

function main() {
  throw new Error();
}

main();

If we run the above script, we'll get:

$ node e.js
/Users/mmarchini/workspace/nodejs/node/e.js:2
  throw new Error();
  ^

Error
    at main (/Users/mmarchini/workspace/nodejs/node/e.js:2:9)
    at Object.<anonymous> (/Users/mmarchini/workspace/nodejs/node/e.js:5:1)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3)
    at Function.Module.runMain (module.js:693:10)
    at startup (bootstrap_node.js:191:16)
    at bootstrap_node.js:612:3

But if we run it with --abort-on-uncaught-exception, the result is quite different (for example, main (./e.js:1:1) instead of main (./e.js:2:9)):

Uncaught Error

FROM
main (/Users/mmarchini/workspace/nodejs/node/e.js:1:1)
Object.<anonymous> (/Users/mmarchini/workspace/nodejs/node/e.js:1:1)
Module._compile (module.js:1:1)
Object.Module._extensions..js (module.js:1:1)
Module.load (module.js:1:1)
tryModuleLoad (module.js:1:1)
Function.Module._load (module.js:1:1)
Function.Module.runMain (module.js:1:1)
startup (bootstrap_node.js:1:1)
bootstrap_node.js:1:1
[1]    94600 illegal hardware instruction  node --abort-on-uncaught-exception e.js

At first I thought it was a V8 bug, but running the same script with d8 gives the expected result:

Uncaught Error

FROM
main (e.js:2:3)
e.js:5:1

Maybe it's something related to our modules system? cc @nodejs/modules

@addaleax addaleax added v8 engine Issues and PRs related to the V8 dependency. post-mortem Issues and PRs related to the post-mortem diagnostics of Node.js. labels Jul 26, 2018
@addaleax
Copy link
Member

This is a regression, introduced somewhere in v8.2.1...v8.3.0 – most likely #14574 (V8 5.8 → V8 6.0).

/cc @nodejs/v8

@benjamingr
Copy link
Member

benjamingr commented Jul 27, 2018

Does that mean that since V8 6 (about a year) stack traces were broken with --abort-on-uncaught-exception? Would be interesting to see how many people actually use the flag and how.

@misterdjules
Copy link

@benjamingr

Would be interesting to see how many people actually use the flag and how.

When aborting on uncaught errors, I usually don't look only at the stack trace that is outputted by V8. Instead I usually rely on getting the call stack from the resulting core dump. It is still confusing if they're inconsistent with each other.

I've also not used node > 6.x in production yet.

@targos
Copy link
Member

targos commented Jul 29, 2018

Note that Windows is not affected.

@mmarchini
Copy link
Contributor Author

Bisecting v8.2.1...v8.3.0 I got 44ad55d (#14574) as the first bad commit.

@mmarchini
Copy link
Contributor Author

Interesting, with ./node --always-opt --abort-on-uncaught-exception -e "throw new Error()" I got the correct output:

$ ./node --always-opt --abort-on-uncaught-exception -e "throw new Error()"
Uncaught Error

FROM
[eval]:1:1
Script.runInThisContext (vm.js:88:20)
Object.runInThisContext (vm.js:285:38)
Object.<anonymous> ([eval]-wrapper:6:22)
Module._compile (internal/modules/cjs/loader.js:689:30)
evalScript (internal/bootstrap/node.js:563:27)
startup (internal/bootstrap/node.js:1:1)
bootstrapNodeJSCore (internal/bootstrap/node.js:596:3)
[1]    53989 illegal hardware instruction  ./node --always-opt --abort-on-uncaught-exception -e "throw new Error()"

Seems to be a problem with interpreted functions and AbstractCode::SourcePosition, because the ByteArray passed to SourcePositionTableIterator in this function has length() = 0. @nodejs/v8 any thoughts on this? Seems to be a V8 bug.

Drieger added a commit to Drieger/node that referenced this issue Sep 10, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{nodejs#54253}

Refs: v8/v8@9a23bdd
Fixes: nodejs#21988
Drieger added a commit to Drieger/node that referenced this issue Sep 10, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{nodejs#54253}

Refs: v8/v8@9a23bdd
Fixes: nodejs#21988
@addaleax
Copy link
Member

Ping @nodejs/v8 – any ideas here?

@mmarchini
Copy link
Contributor Author

The issue was fixed on V8 6.9, we just need to backport the fixes for v10.x and v8.x (v6.x is not affected).

@misterdjules
Copy link

@mmarchini Do you know what the earliest 10.x version to which the fix will be back ported? Is there a PR to which we can subscribe?

@mmarchini
Copy link
Contributor Author

Not yet. I was talkting to @Drieger and he'll open a backport PR later today, so I'm guessing we'll have this fixed in the next v10.x release.

@Drieger
Copy link
Contributor

Drieger commented Sep 17, 2018

@misterdjules @mmarchini I opened #22910 to backport to v10.x

Drieger added a commit to Drieger/node that referenced this issue Sep 18, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{nodejs#54253}

Refs: nodejs#21988
targos pushed a commit that referenced this issue Sep 19, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{#54253}

Refs: v8/v8@9a23bdd
Refs: #21988
PR-URL: #22910
Reviewed-By: Matheus Marchini <mat@mmarchini.me>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
targos pushed a commit that referenced this issue Sep 20, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{#54253}

Refs: v8/v8@9a23bdd
Refs: #21988
PR-URL: #22910
Reviewed-By: Matheus Marchini <mat@mmarchini.me>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
BethGriggs pushed a commit that referenced this issue Oct 2, 2018
Original commit message:

    [Isolate] Fix Isolate::PrintCurrentStackTrace for interpreted frames

    Previously we were getting the code object from the stack, so printed incorrect
    position details for interpreted frames.

    BUG=v8:7916

    Change-Id: I2f87584117d88b7db3f3b9bdbfe793c4d3e33fe9
    Reviewed-on: https://chromium-review.googlesource.com/1126313
    Reviewed-by: Toon Verwaest <verwaest@chromium.org>
    Commit-Queue: Ross McIlroy <rmcilroy@chromium.org>
    Cr-Commit-Position: refs/heads/master@{#54253}

Refs: v8/v8@9a23bdd
Fixes: #21988

PR-URL: #22418
Refs: #22338
Reviewed-By: Matheus Marchini <mat@mmarchini.me>
Reviewed-By: Ujjwal Sharma <usharma1998@gmail.com>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>
@Trott
Copy link
Member

Trott commented Nov 13, 2018

Should this be closed?

@mmarchini
Copy link
Contributor Author

IIRC, yes (we can reopen otherwise).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
post-mortem Issues and PRs related to the post-mortem diagnostics of Node.js. v8 engine Issues and PRs related to the V8 dependency.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants