search

nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
106.6k stars 29.07k forks source link

Failing test: test-inspector-multisession-ws #32383

Closed targos closed 4 years ago

targos commented 4 years ago 
=== 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
targos commented 4 years ago

@nodejs/inspector

targos commented 4 years ago

This is with V8 lkgr (canary branch of this repo)

mmarchini commented 4 years ago

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:

// script.js
const { Session } = require('inspector');
const session = new Session();
let done = false;
const interval = setInterval(() => {
  process._rawDebug('hey oh');
  if (done)
    clearInterval(interval);
}, 1000);
session.on('Debugger.paused', () => {
  done = true;
});
session.connect();
session.post('Debugger.enable');
console.log('Ready');
// connect.js
'use strict'

const http = require("http");
const WebSocket = require('ws');

function usage() {
  console.error('USAGE: node index.js <PID>')
  process.exit(1)
}

if (process.argv.length !== 3) usage();

const pid = Number(process.argv[2])

if (pid === NaN) usage();

let first = true;

function connectToInspector(url) {
  const ws = new WebSocket(url);

  ws.on('message', function incoming(data) {
    const res = JSON.parse(data);
    if (first && res.method == "Debugger.paused") {
      first = false;
      ws.send(JSON.stringify({"method": "Debugger.resume", "id": 4}));
    }
    if (res.method == "Debugger.resumed")
      ws.send(JSON.stringify({"method": "Debugger.pause", "id": 3}));
    if (res.method != "Debugger.scriptParsed")
      console.log(res);
  });

  ws.on('open', function open() {
    ws.send(JSON.stringify({"method": "Debugger.enable", "id": 1}));
    ws.send(JSON.stringify({"method": "Runtime.runIfWaitingForDebugger", "id": 2}));
  });
}

function getWebSocketPath(cb) {
  http.get("http://localhost:9229/json", (resp) => {
    let data = '';

    resp.on('data', (chunk) => {
      data += chunk;
    });

    resp.on('end', () => cb(JSON.parse(data)[0].webSocketDebuggerUrl));
  })
}

process.kill(pid, 'SIGUSR1');
getWebSocketPath(connectToInspector);
$ node --inspect-brk script.js &
[1] 13214
Debugger listening on ws://127.0.0.1:9229/6680ec92-a986-4a8c-8f2f-0daee5deabfb                                                           
For help, see: https://nodejs.org/en/docs/inspector

$ node connect.js $(pgrep node)
Debugger attached.
{
  id: 1,
  result: { debuggerId: '-5779516113788299134.3822508824226157107' }
}
{ id: 2, result: {} }
{
  method: 'Debugger.paused',
  params: {
    callFrames: [
      [Object], [Object],
      [Object], [Object],
      [Object], [Object],
      [Object]
    ],
    reason: 'Break on start',
    hitBreakpoints: []
  }
}
{ id: 4, result: {} }
{ method: 'Debugger.resumed', params: {} }
{ id: 3, result: {} }
[1]  + 14390 segmentation fault (core dumped)  /home/mmarchini/workspace/nodejs/node-v8/node --inspect-brk fooo.js

Stack from core dump:

* thread nodejs/node-v8#1, name = 'node', stop reason = signal SIGSEGV
  * frame #0: 0x0000564beda33b47 node`v8::internal::ScopeIterator::Type() const + 55
    frame nodejs/node-v8#1: 0x0000564beda321c0 node`v8::internal::DebugScopeIterator::Advance() + 48
    frame nodejs/node-v8#2: 0x0000564bee052d44 node`v8_inspector::V8DebuggerAgentImpl::currentCallFrames(std::unique_ptr<std::vector<std::unique_ptr<v8_inspector::protocol::Debugger::CallFrame, std::default_delete<v8_inspector::protocol::Debugger::CallFrame> >, std::allocator<std::unique_ptr<v8_inspector::protocol::Debugger::CallFrame, std::default_delete<v8_inspector::protocol::Debugger::CallFrame> > > >, std::default_delete<std::vector<std::unique_ptr<v8_inspector::protocol::Debugger::CallFrame, std::default_delete<v8_inspector::protocol::Debugger::CallFrame> >, std::allocator<std::unique_ptr<v8_inspector::protocol::Debugger::CallFrame, std::default_delete<v8_inspector::protocol::Debugger::CallFrame> > > > > >*) + 2404
    frame nodejs/node-v8#3: 0x0000564bee059fca node`v8_inspector::V8DebuggerAgentImpl::didPause(int, v8::Local<v8::Value>, std::vector<int, std::allocator<int> > const&, v8::debug::ExceptionType, bool, bool, bool) + 1386
    frame nodejs/node-v8#4: 0x0000564bee04185a node`std::_Function_handler<void (v8_inspector::V8InspectorSessionImpl*), v8_inspector::V8Debugger::handleProgramBreak(v8::Local<v8::Context>, v8::Local<v8::Value>, std::vector<int, std::allocator<int> > const&, v8::debug::ExceptionType, bool)::'lambda0'(v8_inspector::V8InspectorSessionImpl*)>::_M_invoke(std::_Any_data const&, v8_inspector::V8InspectorSessionImpl*&&) + 170
    frame nodejs/node-v8#5: 0x0000564bee064314 node`v8_inspector::V8InspectorImpl::forEachSession(int, std::function<void (v8_inspector::V8InspectorSessionImpl*)> const&) + 452
    frame nodejs/node-v8#6: 0x0000564bee044abf node`v8_inspector::V8Debugger::handleProgramBreak(v8::Local<v8::Context>, v8::Local<v8::Value>, std::vector<int, std::allocator<int> > const&, v8::debug::ExceptionType, bool) + 511
    frame nodejs/node-v8#7: 0x0000564beda44386 node`v8::internal::Debug::OnDebugBreak(v8::internal::Handle<v8::internal::FixedArray>) + 486
    frame nodejs/node-v8#8: 0x0000564beda44530 node`v8::internal::Debug::HandleDebugBreak(v8::internal::IgnoreBreakMode) + 384
    frame nodejs/node-v8#9: 0x0000564bed945f0d node`v8::debug::BreakRightNow(v8::Isolate*) + 45
    frame nodejs/node-v8#10: 0x0000564beda877e3 node`v8::internal::Isolate::InvokeApiInterruptCallbacks() + 163
    frame nodejs/node-v8#11: 0x0000564bedaa007d node`v8::internal::StackGuard::HandleInterrupts() + 557
    frame nodejs/node-v8#12: 0x0000564bede60e9d node`v8::internal::Runtime_StackGuard(int, unsigned long*, v8::internal::Isolate*) + 109
    frame nodejs/node-v8#13: 0x0000564bee1c06d9 node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit + 57
    frame nodejs/node-v8#14: 0x0000564bee159213 node`Builtins_InterpreterEntryTrampoline + 307
    frame nodejs/node-v8#15: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#16: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#17: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#18: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#19: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#20: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#21: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#22: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#23: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#24: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#25: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#26: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#27: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#28: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#29: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#30: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#31: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#32: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#33: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#34: 0x0000564bee156dfa node`Builtins_JSEntryTrampoline + 90
    frame nodejs/node-v8#35: 0x0000564bee156bd8 node`Builtins_JSEntry + 120
    frame nodejs/node-v8#36: 0x0000564beda724ae node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 446
    frame nodejs/node-v8#37: 0x0000564beda732f7 node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 119
    frame nodejs/node-v8#38: 0x0000564bed931863 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 323
    frame nodejs/node-v8#39: 0x0000564bed84e22e node`node::inspector::(anonymous namespace)::CallAndPauseOnStart(v8::FunctionCallbackInfo<v8::Value> const&) + 382
    frame nodejs/node-v8#40: 0x0000564bed98c17f node`v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) + 367
    frame nodejs/node-v8#41: 0x0000564bed98c540 node`v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) + 208
    frame nodejs/node-v8#42: 0x0000564bed98cdda node`v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 266
    frame nodejs/node-v8#43: 0x0000564bed98d68a node`v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) + 26
    frame nodejs/node-v8#44: 0x0000564bee1c07b9 node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit + 57
    frame nodejs/node-v8#45: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#46: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#47: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#48: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#49: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#50: 0x0000564bee15919e node`Builtins_InterpreterEntryTrampoline + 190
    frame nodejs/node-v8#51: 0x0000564bee156dfa node`Builtins_JSEntryTrampoline + 90
    frame nodejs/node-v8#52: 0x0000564bee156bd8 node`Builtins_JSEntry + 120
    frame nodejs/node-v8#53: 0x0000564beda724ae node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 446
    frame nodejs/node-v8#54: 0x0000564beda732f7 node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 119
    frame nodejs/node-v8#55: 0x0000564bed931863 node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 323
    frame nodejs/node-v8#56: 0x0000564bed71a0fa node`node::ExecuteBootstrapper(node::Environment*, char const*, std::vector<v8::Local<v8::String>, std::allocator<v8::Local<v8::String> > >*, std::vector<v8::Local<v8::Value>, std::allocator<v8::Local<v8::Value> > >*) + 138
    frame nodejs/node-v8#57: 0x0000564bed71afc3 node`node::StartExecution(node::Environment*, char const*) + 483
    frame nodejs/node-v8#58: 0x0000564bed71b657 node`node::StartMainThreadExecution(node::Environment*) + 1511
    frame nodejs/node-v8#59: 0x0000564bed7988fd node`node::NodeMainInstance::Run() + 557
    frame nodejs/node-v8#60: 0x0000564bed71d92b node`node::Start(int, char**) + 251
    frame nodejs/node-v8#61: 0x00007efe201aa1e3 libc.so.6`__libc_start_main(main=(node`main), argc=3, argv=0x00007fffa32fa788, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffa32fa778) at libc-start.c:308
    frame nodejs/node-v8#62: 0x0000564bed67803e node`_start + 46

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.

mmarchini commented 4 years ago

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](https://github.com/nodejs/node-v8/blob/91d492392e3e6bea024b840f5de8eece1040d685/deps/v8/src/debug/debug-scopes.cc#L452-L454)). 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): ``` ==== JS stack trace ========================================= 0: ExitFrame [pc: 0x55a4e9a62fff] Security context: 0x3a3408280545 #0# 1: /* anonymous */(aka /* anonymous */) [0x3a340817e0c9] [internal/worker/io.js:1] [bytecode=0x3a340833c395 offset=-1](this=0x3a340804030d ,0x3a34080cce49 #1#,0x3a34080c301d #2#,0x3a34080cce09 #3#,0x3a34080c213d #4#,0x3a34080c3ae1 #5#,0x3a3408287121 #6#) 2: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080cce09 #3#) 3: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d ,0x3a3408339a15 ) 4: /* anonymous */(aka /* anonymous */) [0x3a340817db0d] [internal/worker.js:34] [bytecode=0x3a340833a411 offset=376](this=0x3a340804030d ,0x3a34080ccdc5 #7#,0x3a34080c301d #2#,0x3a34080ccd85 #8#,0x3a34080c213d #4#,0x3a34080c3ae1 #5#,0x3a3408287121 #6#) 5: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080ccd85 #8#) 6: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d ,0x3a3408339985 ) 7: /* anonymous */(aka /* anonymous */) [0x3a340816188d] [worker_threads.js:9] [bytecode=0x3a3408339899 offset=4](this=0x3a340804030d ,0x3a34080cda3d #9#,0x3a34080c301d #2#,0x3a34080cd9fd #10#,0x3a34080c213d #4#,0x3a34080c3ae1 #5#,0x3a3408287121 #6#) 8: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080cd9fd #10#) 9: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d ,0x3a340831dff1 ) 10: /* anonymous */(aka /* anonymous */) [0x3a34081615a9] [inspector.js:29] [bytecode=0x3a3408338855 offset=253](this=0x3a340804030d ,0x3a34080c7a3d #11#,0x3a34080c301d #2#,0x3a34080c79f9 #12#,0x3a34080c213d #4#,0x3a34080c3ae1 #5#,0x3a3408287121 #6#) 11: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080c79f9 #12#) 12: compileForPublicLoader [0x3a34080c60fd] [internal/bootstrap/loaders.js:218] [bytecode=0x3a34083386f9 offset=49](this=0x3a34080c79f9 #12#) 13: loadNativeModule(aka loadNativeModule) [0x3a340813e9ed] [internal/modules/cjs/helpers.js:24] [bytecode=0x3a3408332051 offset=48](this=0x3a340804030d ,0x3a3408295fa9 ,0x3a3408295fa9 ) 14: _load [0x3a3408323c45] [internal/modules/cjs/loader.js:919] [bytecode=0x3a3408330ebd offset=224](this=0x3a340813599d #13#,0x3a3408295fa9 ,0x3a340814fcc9 #14#,0x3a340804044d ) 15: require [0x3a3408323cb1] [internal/modules/cjs/loader.js:1093] [bytecode=0x3a3408338535 offset=85](this=0x3a340814fcc9 #14#,0x3a3408295fa9 ) 16: require(aka require) [0x3a3408150ba5] [internal/modules/cjs/helpers.js:72] [bytecode=0x3a3408338441 offset=10](this=0x3a340804030d ,0x3a3408295fa9 ) 17: /* anonymous */ [0x3a3408150919] [/tmp/aa/fooo.js:1] [bytecode=0x3a340833819d offset=15](this=0x3a340814fdc1 #15#,0x3a340814fdc1 #15#,0x3a3408150ba5 #16#,0x3a340814fcc9 #14#,0x3a340814f5cd ,0x3a3408150b39 ) 18: InternalFrame [pc: 0x55a4e984081a] 19: EntryFrame [pc: 0x55a4e98405f8] 20: builtin exit frame: callAndPauseOnStart(this=0x3a34080c0121 #17#,0x3a3408150b39 ,0x3a340814f5cd ,0x3a340814fcc9 #14#,0x3a3408150ba5 #16#,0x3a340814fdc1 #15#,0x3a340814fdc1 #15#,0x3a3408150919 #18#,0x3a34080c0121 #17#) 21: _compile [0x3a3408323cdd] [internal/modules/cjs/loader.js:1201] [bytecode=0x3a340833581d offset=417](this=0x3a340814fcc9 #14#,0x3a3408150739 {\n // done = true;\n});\nsession.connect();\nsession.post('Debugger.enable');\nconsole.log('Ready');\n\n>,0x3a340814f5cd ) 22: .js [0x3a3408323d09] [internal/modules/cjs/loader.js:1224] [bytecode=0x3a3408333095 offset=155](this=0x3a3408147f91 #19#,0x3a340814fcc9 #14#,0x3a340814f5cd ) 23: load [0x3a3408323c85] [internal/modules/cjs/loader.js:1053] [bytecode=0x3a3408332679 offset=189](this=0x3a340814fcc9 #14#,0x3a340814f5cd ) 24: _load [0x3a3408323c45] [internal/modules/cjs/loader.js:948] [bytecode=0x3a3408330ebd offset=403](this=0x3a340813599d #13#,0x3a3408134d3d ,0x3a3408040171 ,0x3a34080403e5 ) 25: runMain(aka executeUserEntryPoint) [0x3a340814ebd5] [internal/modules/run_main.js:71] [bytecode=0x3a340832e075 offset=86](this=0x3a340813599d #13#,0x3a3408134d3d ) 26: /* anonymous */(aka /* anonymous */) [0x3a340812eda1] [internal/main/run_main_module.js:17] [bytecode=0x3a34083014e5 offset=61](this=0x3a340804030d ,0x3a34080c213d #4#,0x3a34080c301d #2#,0x3a34080c3ae1 #5#,0x3a3408287121 #6#,0x3a3408301239 #20#) 27: InternalFrame [pc: 0x55a4e984081a] 28: EntryFrame [pc: 0x55a4e98405f8] ``` 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: ```js let done = false; function lala() { setInterval(lala, 150); } lala(); console.log('Ready'); ``` ``` ==== JS stack trace ========================================= 0: ExitFrame [pc: 0x55b79756afff] Security context: 0x1d1108280545 #0# 1: /* anonymous */(aka /* anonymous */) [0x1d11081621b5] [tty.js:1] [bytecode=0x1d1108339e95 offset=-1](this=0x1d110804030d ,0x1d11080cd725 #1#,0x1d11080c301d #2#,0x1d11080cd6e5 #3#,0x1d11080c213d #4#,0x1d11080c3ae1 #5#,0x1d1108287121 #6#) 2: compileForInternalLoader [0x1d11080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x1d1108299ea1 offset=112](this=0x1d11080cd6e5 #3#) 3: nativeModuleRequire(aka nativeModuleRequire) [0x1d11080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x1d1108299d29 offset=79](this=0x1d110804030d ,0x1d11082fe4f5 ) 4: createWritableStdioStream(aka createWritableStdioStream) [0x1d110812d5c9] [internal/bootstrap/switches/is_main_thread.js:42] [bytecode=0x1d1108339c05 offset=68](this=0x1d110804030d ,1) 5: getStdout [0x1d110812d609] [internal/bootstrap/switches/is_main_thread.js:118] [bytecode=0x1d11083398d9 offset=19](this=0x1d11080c213d #4#) 6: StubFrame [pc: 0x55b79737a90f] 7: StubFrame [pc: 0x55b7977b928d] 8: get [0x1d1108118445] [internal/console/constructor.js:164] [bytecode=0x1d1108339785 offset=10](this=0x1d1108116f59 #7#) 9: StubFrame [pc: 0x55b79737a90f] 10: StubFrame [pc: 0x55b7977b928d] 11: /* anonymous */ [0x1d11082e4205] [internal/console/constructor.js:286] [bytecode=0x1d11083396c1 offset=9](this=0x1d1108116f59 #7#,0x1d1108161fed #8#) 12: log [0x1d11081165a1] [internal/console/constructor.js:297] [bytecode=0x1d11083395ed offset=29](this=0x1d1108116f59 #7#) 13: arguments adaptor frame: 1->0 14: InternalFrame [pc: 0x55b79734881a] 15: EntryFrame [pc: 0x55b7973485f8] 16: builtin exit frame: consoleCall(this=0x1d1108116f59 #7#,0x1d1108336411 ,0x1d110811725d #9#,0x1d110828ed39 #10#,0x1d1108116f59 #7#) 17: /* anonymous */ [0x1d1108150881] [/tmp/aa/fooo2.js:8] [bytecode=0x1d1108338041 offset=36](this=0x1d110814fde5 #11#,0x1d110814fde5 #11#,0x1d1108150b0d #12#,0x1d110814fced #13#,0x1d110814f5e9 ,0x1d1108150aa1 ) 18: InternalFrame [pc: 0x55b79734881a] 19: EntryFrame [pc: 0x55b7973485f8] 20: builtin exit frame: callAndPauseOnStart(this=0x1d11080c0121 #14#,0x1d1108150aa1 ,0x1d110814f5e9 ,0x1d110814fced #13#,0x1d1108150b0d #12#,0x1d110814fde5 #11#,0x1d110814fde5 #11#,0x1d1108150881 #15#,0x1d11080c0121 #14#) 21: _compile [0x1d1108323cdd] [internal/modules/cjs/loader.js:1201] [bytecode=0x1d1108335821 offset=417](this=0x1d110814fced #13#,0x1d110815075d ,0x1d110814f5e9 ) 22: .js [0x1d1108323d09] [internal/modules/cjs/loader.js:1224] [bytecode=0x1d1108333099 offset=155](this=0x1d1108147f91 #16#,0x1d110814fced #13#,0x1d110814f5e9 ) 23: load [0x1d1108323c85] [internal/modules/cjs/loader.js:1053] [bytecode=0x1d110833267d offset=189](this=0x1d110814fced #13#,0x1d110814f5e9 ) 24: _load [0x1d1108323c45] [internal/modules/cjs/loader.js:948] [bytecode=0x1d1108330ec1 offset=403](this=0x1d11081359a5 #17#,0x1d1108134d45 ,0x1d1108040171 ,0x1d11080403e5 ) 25: runMain(aka executeUserEntryPoint) [0x1d110814ebd5] [internal/modules/run_main.js:71] [bytecode=0x1d110832e075 offset=86](this=0x1d11081359a5 #17#,0x1d1108134d45 ) 26: /* anonymous */(aka /* anonymous */) [0x1d110812eda1] [internal/main/run_main_module.js:17] [bytecode=0x1d11083014e5 offset=61](this=0x1d110804030d ,0x1d11080c213d #4#,0x1d11080c301d #2#,0x1d11080c3ae1 #5#,0x1d1108287121 #6#,0x1d1108301239 #18#) 27: InternalFrame [pc: 0x55b79734881a] 28: EntryFrame [pc: 0x55b7973485f8] ``` 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: ```js require("tty"); let done = false; function lala() { setInterval(lala, 150); } lala(); console.log('Ready'); ``` Well, this works. Let's try the other way around. The code above should break on Chrome DevTools: ``` // require-me.js while (true) { } ``` ```js require("./require-me"); ``` 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: ``` ==== JS stack trace ========================================= 0: ExitFrame [pc: 0x55d12c53ecbf] Security context: 0x0bec08280545 #0# 1: /* anonymous */(aka /* anonymous */) [0xbec08162615] [net.js:1] [bytecode=0xbec0833ad51 offset=-1](this=0x0bec0804030d ,0x0bec080ccf71 #1#,0x0bec080c3039 #2#,0x0bec080ccf31 < NativeModule map = 0xbec08244041>#3#,0x0bec080c213d #4#,0x0bec080c3afd #5#,0x0bec08287121 #6#) 2: compileForInternalLoader [0xbec080c616d] [internal/bootstrap/loaders.js:276] [bytecode=0xbec08299ea1 offset=112](this=0x0bec080ccf31 #3#) ``` Notice the `[bytecode=0xbec0833ad51 offset=-1]`. I'm not sure, but I think the `offset=-1` mean the code is not executing yet. `jst` from a script with a `while (true) {}` in it (notice we have a positive offset this time): ``` ==== JS stack trace ========================================= 0: ExitFrame [pc: 0x557996d4ccbf] 1: StubFrame [pc: 0x557996fee2c4] Security context: 0x2e7b08280545 #0# 2: /* anonymous */(aka /* anonymous */) [0x2e7b0817e061] [os.js:23] [bytecode=0x2e7b0836b2cd offset=147](this=0x2e7b0804030d ,0x2e7b080cd049 #1#,0x2e7b080c308d #2#,0x2e7b080cd 009 #3#,0x2e7b080c213d #4#,0x2e7b080c3b51 #5#,0x2e7b08287121 #6#) 3: compileForInternalLoader [0x2e7b080c61c1] [internal/bootstrap/loaders.js:276] [bytecode=0x2e7b08299ea1 offset=112](this=0x2e7b080cd009 #3#) ``` This gives me an idea to break `--inspect`. If we console.log *inside* `session.on("pause, `, we'll be lazily loading Let's try it: ```js // crash-without-brk.js const { Session } = require('inspector'); const session = new Session(); let done = false; function lala() { setInterval(lala, 150); if (done) console.log('Ready'); } lala(); session.on('Debugger.paused', () => { done = true; }); session.connect(); session.post('Debugger.enable'); ``` And boom! ```console $ node --inspect crash-without-brk.js # after calling the websocket script # # Fatal error in ../../deps/v8/src/debug/debug-scopes.cc, line 452 # Debug check failed: current_scope_->NeedsContext() implies context_->IsFunctionContext() || context_->IsDebugEvaluateContext(). # # # #FailureMessage Object: 0x7ffee58c22f0 1: 0x56523d23cad4 node::DumpBacktrace(_IO_FILE*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 2: 0x56523d3c6f1f [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 3: 0x56523d3c6f43 [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 4: 0x56523ee3536b V8_Fatal(char const*, int, char const*, ...) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 5: 0x56523ee3539b [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 6: 0x56523d79f48e v8::internal::ScopeIterator::Type() const [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 7: 0x56523d79d168 v8::internal::DebugScopeIterator::DebugScopeIterator(v8::internal::Isolate*, v8::internal::FrameInspector*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 8: 0x56523d7a8878 v8::internal::DebugStackTraceIterator::GetScopeIterator() const [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 9: 0x56523e11736b v8_inspector::V8DebuggerAgentImpl::currentCallFrames(std::unique_ptr >, std::allocator > > >, std::default_delete >, std::alloc ator > > > > >*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 10: 0x56523e11ee77 v8_inspector::V8DebuggerAgentImpl::didPause(int, v8::Local, std::vector > const&, v8::debug::ExceptionType, bool, bool, bool) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 11: 0x56523e1063d0 [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 12: 0x56523e128d01 v8_inspector::V8InspectorImpl::forEachSession(int, std::function const&) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 13: 0x56523e1097ff v8_inspector::V8Debugger::handleProgramBreak(v8::Local, v8::Local, std::vector > const&, v8::debug::ExceptionType, bool) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 14: 0x56523d7bf06d v8::internal::Debug::OnDebugBreak(v8::internal::Handle) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 15: 0x56523d7bf24b v8::internal::Debug::HandleDebugBreak(v8::internal::IgnoreBreakMode) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 16: 0x56523d5850eb v8::debug::BreakRightNow(v8::Isolate*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 17: 0x56523d854939 v8::internal::Isolate::InvokeApiInterruptCallbacks() [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 18: 0x56523d881012 v8::internal::StackGuard::HandleInterrupts() [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 19: 0x56523de7aafb [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 20: 0x56523de7ae8e v8::internal::Runtime_StackGuard(int, unsigned long*, v8::internal::Isolate*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] 21: 0x56523e48ccbf [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node] [1] 11135 illegal hardware instruction (core dumped) /home/mmarchini/workspace/nodejs/node-v8/out/Debug/node --inspect crash-without-brk.js ``` 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 commented 4 years ago

@mmarchini thanks a lot for looking into this!

mmarchini commented 4 years ago

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 commented 4 years ago

Is this test flaky ? it's not seeing in node-v8 master.

mmarchini commented 4 years ago

Is this test flaky ?

Yes, but the failing is legit

it's not seeing in node-v8 master.

Do you mean canary? Let me try it

gengjiawen commented 4 years ago

Do you mean canary? Let me try it

yeap, only 3 test failed, but this one is not one of them.

https://github.com/nodejs/node-v8/runs/472689076

mmarchini commented 4 years ago

Still happening:

$ ./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 fired
Timed out waiting for matching notification (SessionA paused))
1

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:

  1. Native function is called
  2. Inspector receives pause signal
  3. Native function returns a function generated with ScriptCompiler::CompileFunctionInContext
  4. 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.

mmarchini commented 4 years ago

It also failed on the latest Jenkins run: https://ci.nodejs.org/job/node-test-commit-linux/33109/nodes=ubuntu1804-64/consoleFull

gengjiawen commented 4 years ago

Weird github CI not reporting this error. Any clue ? @cclauss

mmarchini commented 4 years ago

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.

gengjiawen commented 4 years ago

Is it possible we biselect v8 commit to find the problem ?

mmarchini commented 4 years ago

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.

mmarchini commented 4 years ago

Ok, got a repro on V8. I had to copy an entire script there (tty.js), so I'm not sure what exactly is triggering the bug. Will start to refactor the test to see where the problem is.

mmarchini commented 4 years ago

V8 minimal repro: https://chromium-review.googlesource.com/c/v8/v8/+/2080072 Upstream bug: https://bugs.chromium.org/p/v8/issues/detail?id=10287 First V8 commit with the issue (found with git bisect): https://chromium-review.googlesource.com/c/v8/v8/+/1903440

mmarchini commented 4 years ago

This is such an edge case I'm wondering if we should mark the test as flaky (and maybe add a test specific for this bug on known_issues) and remove this from blockers. My reasoning is:

  • This bug should not affect people running Node.js in production, since using the inspector to pause a production app is not recommended (pausing is a Debugger domain feature, and enabling that domain triggers several deoptimizations and slow paths on V8, so if someone is doing that on prod they have bigger problems anyway).
  • So far we only detected this bug when pausing at an exact moment while requiring a core module for the first time, so once the application is running for a while it shouldn't happen (in theory this could happen with vm.compileFunction, but I was not able to reproduce it)
  • It's extremely unlikely someone will hit this issue while debugging with Chrome DevTools, because of the timing issues I mentioned in a prior comment
gengjiawen commented 4 years ago

I am on adding it to known issue (also not a fan of mutli session in debugging)

mmarchini commented 4 years ago

also not a fan of mutli session in debugging

FWIW this bug is unrelated to multi-session. It was a coincidence this happened on this test.

gengjiawen commented 4 years ago

FWIW this bug is unrelated to multi-session. It was a coincidence this happened on this test.

Sorry for miss that part. Is there known issue part for Node.js ? seems we only mark test flaky.

mmarchini commented 4 years ago

It's a folder there (https://github.com/nodejs/node/tree/master/test/known_issues, I only found out about it a few days ago). Tests there are expected to always fail, so test-inspector-multisession-ws would stay where it is (but marked as flaky) and we could write another test that can reliably reproduce the issue (I have some ideas, will try later or tomorrow).

gengjiawen commented 4 years ago

test-inspector-multisession-ws always failed on my machine. It's not on your machine ?

Also, for anyone interested, v8 crashes in here

[err] #
[err] # Fatal error in ../../deps/v8/src/debug/debug-scopes.cc, line 454
[err] # Debug check failed: current_scope_->NeedsContext() implies context_->IsFunctionContext() || context_->IsDebugEvaluateContext().
mmarchini commented 4 years ago

test-inspector-multisession-ws always failed on my machine

It failed rather consistently, but it would succeed occasionally.

mmarchini commented 4 years ago

We should open a tracking issue on nodejs/node, since the underlying bug still exists on V8

gengjiawen commented 4 years ago

We should open a tracking issue on nodejs/node, since the underlying bug still exists on V8

Move this to issue to nodejs/node ?

mmarchini commented 4 years ago

I thought opening a new issue made more sense, but @targos was faster than me :)

  • © Githubissues.
  • Githubissues is a development platform for aggregating issues.