You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
=== release test-inspector-multisession-ws ===
Path: parallel/test-inspector-multisession-ws
[test] Connecting to a child Node process
[test] Testing /json/list
[test] Connecting to a child Node process
[test] Testing /json/list
[err] Debugger listening on ws://127.0.0.1:42923/888acdfc-62b5-40ba-b378-641578b82790
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[err] Debugger attached.
[err] Debugger attached.
[err]
[test] Breaking in code and verifying events are fired
Timed out waiting for matching notification (SessionA paused))
1
Command: out/Release/node /home/mzasso/git/nodejs/canary/test/parallel/test-inspector-multisession-ws.js
FYI, I'm looking into this (couldn't find any PRs referencing this issue, so I assume no one fixed it yet). The child process (the process being inspected) is segfaulting when it receives a Debugger.pause. I was able to reproduce this outside test with:
Interestingly enough, this only happens with --inspect-brk -> Debugger.resume -> Debugger.pause. --inspect -> Debugger.pause works just fine. And even more interesting, if I connect Chrome DevTools to node --inspect-brk script.js, resume and pause afterwards, it doesn't crash.
I'll keep investigating and share any results I find.
Reacted by Michaël Zasso, Jiawen Geng and Ruben Bridgewater
My current theory is that we're hitting pause right after a script is loaded, parsed, maybe even compiled, and pushed onto the stack, but it's not quite ready to run yet.
Why this is happening so frequently? When session.on runs, it will require files in the inspector thread. When console.log runs, it will require several files if they were not required yet. Since the script is so small and only requires inspect, most Node.js modules are not loaded by defautl (on most common cases, those modules will be loaded when a pause happens, thus the crash doesn't happen). This test is, unfortunately (or fortunately), well crafted enough to trigger this crash quite frequently, because it has several requires happening indirectly "during execution" (not as consequence of direct requires).
Why this is not happening on master? No idea
Is this a bug on V8, Node.js or in our test? I'm inclined to say V8, but want to look a bit further before opening a bug anywhere.
There are a few fixes we can apply to the test if we want to unblock the upgrade and investigate this issue in parallel. Let me know if that's something you want, I can send a patch.
Notes I took while debugging, mostrly unstrucutred, unfiltered, and unrevised
If I add a small delay between Debugger.resume and Debugger.pause, the test will pass. That doesn't seem like the right way to fix though, but suggests we have something like a race condition here (especially since the test passes sometimes). This could also explain why Chrome DevTools doesn't crash the script.
Starting the process with --inspect and Debugger.resume -> Debugger.pause on repeat doesn't seem to cause the issue, so it seems like something exclusive to how --inspect-brk is implemented.
The debug build is hitting a DCHECK on the same function the Release build is crashing (here). We're likely reaching that code while in an inconsistent state.
Here's the (supposedly) stack trace on the DCHECK when it fails (printed using gdbinit's jst):
Ok, now we are in TTY, apparently inside console.log? On another run I got the last frame being on net.js.
In both cases, the type of context_ is NATIVE_CONTEXT, which is why the DCHECK is failing (it's not a function or debug context). I'll go on a limb here and guess this has something to do with pausing withing a still-running require. Let's do some testing:
This is all accetonal evidence, but it leads me to believe the issue is manifesting when we call pause and a recently loaded script is in an intermediate state (it's not running yet, but it was at least parsed, probably compiled and loaded on the stack).
Likely caused by this change: https://chromium-review.googlesource.com/c/v8/v8/+/1876821. Now the NativeContext has a SCRIPT_SCOPE attached to it instead of a FUNCTION_SCOPE. Will keep digging, I think we might be using the NativeContext in an incompatible way compared to the new behavior.
$ ./node[test] Connecting to a child Node process[test] Testing /json/list[test] Connecting to a child Node process[test] Testing /json/list[err] Debugger listening on ws://127.0.0.1:44189/05bc75ec-1ceb-4da4-a207-53573d3b400d[err] For help, see: https://nodejs.org/en/docs/inspector[err] [err] Debugger attached.[err] Debugger attached.[err] [test] Breaking in code and verifying events are firedTimed out waiting for matching notification (SessionA paused))1
I'm inclined to say this is a bug on V8. I'm trying to come up with a test on V8 for this, but writing a custom inspector test is somewhat investing, so it's taking some time.
I was able to confirm (using bpftrace and some debugging printf's) that the condition for the segfault to happen is:
Native function is called
Inspector receives pause signal
Native function returns a function generated with ScriptCompiler::CompileFunctionInContext
Function described above is called right after we return
The most likely scenario for this to happen is when we try to pause while requiring an internal module, although in theory we can probably trigger it with vm.compileFunction.
The test is super flaky (the Debugger.pause inspector protocol call must happen at the exact "wrong" time), so in the run you linked the test passed. GitHub Actions won't report results from Jenkins.
The commit where it started is likely https://chromium-review.googlesource.com/c/v8/v8/+/1876821, but I haven't bisected to double check (since I don't have a test on V8 yet, would need to bisect on node-v8, which is too much effort). I think I'm close to have a repro on V8 though.
Activity
targos commentedon Nov 18, 2019
@nodejs/inspector
targos commentedon Nov 18, 2019
This is with V8 lkgr (canary branch of this repo)
mmarchini commentedon Feb 22, 2020
FYI, I'm looking into this (couldn't find any PRs referencing this issue, so I assume no one fixed it yet). The child process (the process being inspected) is segfaulting when it receives a
Debugger.pause. I was able to reproduce this outside test with:Stack from core dump:
Interestingly enough, this only happens with
--inspect-brk->Debugger.resume->Debugger.pause.--inspect->Debugger.pauseworks just fine. And even more interesting, if I connect Chrome DevTools tonode --inspect-brk script.js, resume and pause afterwards, it doesn't crash.I'll keep investigating and share any results I find.
mmarchini commentedon Feb 22, 2020
My current theory is that we're hitting pause right after a script is loaded, parsed, maybe even compiled, and pushed onto the stack, but it's not quite ready to run yet.
Why this is happening so frequently? When
session.onruns, it willrequirefiles in the inspector thread. Whenconsole.logruns, it will require several files if they were not required yet. Since the script is so small and only requiresinspect, most Node.js modules are not loaded by defautl (on most common cases, those modules will be loaded when a pause happens, thus the crash doesn't happen). This test is, unfortunately (or fortunately), well crafted enough to trigger this crash quite frequently, because it has several requires happening indirectly "during execution" (not as consequence of direct requires).Why this is not happening on master? No idea
Is this a bug on V8, Node.js or in our test? I'm inclined to say V8, but want to look a bit further before opening a bug anywhere.
There are a few fixes we can apply to the test if we want to unblock the upgrade and investigate this issue in parallel. Let me know if that's something you want, I can send a patch.
Notes I took while debugging, mostrly unstrucutred, unfiltered, and unrevised
If I add a small delay between
Debugger.resumeandDebugger.pause, the test will pass. That doesn't seem like the right way to fix though, but suggests we have something like a race condition here (especially since the test passes sometimes). This could also explain why Chrome DevTools doesn't crash the script.Starting the process with
--inspectandDebugger.resume->Debugger.pauseon repeat doesn't seem to cause the issue, so it seems like something exclusive to how--inspect-brkis implemented.The debug build is hitting a DCHECK on the same function the Release build is crashing (here). We're likely reaching that code while in an inconsistent state.
Here's the (supposedly) stack trace on the DCHECK when it fails (printed using gdbinit's jst):
Workers, huh? I wonder what that's doing there (and why our code is in the middle of the stack). Ok, let's try a smaller piece of code:
Ok, now we are in TTY, apparently inside
console.log? On another run I got the last frame being on net.js.In both cases, the type of
context_is NATIVE_CONTEXT, which is why the DCHECK is failing (it's not a function or debug context). I'll go on a limb here and guess this has something to do with pausing withing a still-running require. Let's do some testing:Well, this works. Let's try the other way around. The code above should break on Chrome DevTools:
Well, Chrome DevTools worked. I tried the same on a Node.js module and got the same result.
So, looking back at the output of
jst. In the crashing script:Notice the
[bytecode=0xbec0833ad51 offset=-1]. I'm not sure, but I think theoffset=-1mean the code is not executing yet.jstfrom a script with awhile (true) {}in it (notice we have a positive offset this time):This gives me an idea to break
--inspect. If we console.log insidesession.on("pause,, we'll be lazily loading Let's try it:And boom!
This is all accetonal evidence, but it leads me to believe the issue is manifesting when we call pause and a recently loaded script is in an intermediate state (it's not running yet, but it was at least parsed, probably compiled and loaded on the stack).
targos commentedon Feb 24, 2020
@mmarchini thanks a lot for looking into this!
mmarchini commentedon Feb 26, 2020
Likely caused by this change: https://chromium-review.googlesource.com/c/v8/v8/+/1876821. Now the NativeContext has a SCRIPT_SCOPE attached to it instead of a FUNCTION_SCOPE. Will keep digging, I think we might be using the NativeContext in an incompatible way compared to the new behavior.
gengjiawen commentedon Feb 28, 2020
Is this test flaky ? it's not seeing in node-v8 master.
mmarchini commentedon Feb 28, 2020
Yes, but the failing is legit
Do you mean
canary? Let me try itgengjiawen commentedon Feb 28, 2020
yeap, only 3 test failed, but this one is not one of them.
https://github.com/nodejs/node-v8/runs/472689076
mmarchini commentedon Feb 28, 2020
Still happening:
I also used one of the scripts described in https://github.com/nodejs/node-v8/issues/120#issuecomment-589939128, and it is still segfaulting.
I'm inclined to say this is a bug on V8. I'm trying to come up with a test on V8 for this, but writing a custom inspector test is somewhat investing, so it's taking some time.
I was able to confirm (using bpftrace and some debugging printf's) that the condition for the segfault to happen is:
ScriptCompiler::CompileFunctionInContextThe most likely scenario for this to happen is when we try to pause while requiring an internal module, although in theory we can probably trigger it with
vm.compileFunction.mmarchini commentedon Feb 28, 2020
It also failed on the latest Jenkins run: https://ci.nodejs.org/job/node-test-commit-linux/33109/nodes=ubuntu1804-64/consoleFull
gengjiawen commentedon Feb 28, 2020
Weird github CI not reporting this error. Any clue ? @cclauss
mmarchini commentedon Feb 28, 2020
The test is super flaky (the
Debugger.pauseinspector protocol call must happen at the exact "wrong" time), so in the run you linked the test passed. GitHub Actions won't report results from Jenkins.gengjiawen commentedon Feb 28, 2020
Is it possible we biselect v8 commit to find the problem ?
mmarchini commentedon Feb 28, 2020
The commit where it started is likely https://chromium-review.googlesource.com/c/v8/v8/+/1876821, but I haven't bisected to double check (since I don't have a test on V8 yet, would need to bisect on node-v8, which is too much effort). I think I'm close to have a repro on V8 though.
20 remaining items
test: mark inspector tests as flaky
test: mark inspector tests as flaky
test: mark inspector tests as flaky
test: mark inspector tests as flaky
mmarchini commentedon Mar 20, 2020
We should open a tracking issue on nodejs/node, since the underlying bug still exists on V8
gengjiawen commentedon Mar 20, 2020
Move this to issue to
nodejs/node?mmarchini commentedon Mar 20, 2020
I thought opening a new issue made more sense, but @targos was faster than me :)