Failing test: test-inspector-multisession-ws

[targos]

=== 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]

@nodejs/inspector

[targos]

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

[mmarchini]

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]

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):

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x55a4e9a62fff]
Security context: 0x3a3408280545 <JSObject>#0#
    1: /* anonymous */(aka /* anonymous */) [0x3a340817e0c9] [internal/worker/io.js:1] [bytecode=0x3a340833c395 offset=-1](this=0x3a340804030d <undefined>,0x3a34080cce49 <Object map = 0x3a34082402d9>#1#,0x3a34080c301d <JSFunction nativeModuleRequire (sfi = 0x3a3408296629)>#2#,0x3a34080cce09 <NativeModule map = 0x3a3408244041>#3#,0x3a34080c213d <process map = 0x3a340825a7a1>#4#,0x3a34080c3ae1 <JSFunction internalBinding (sfi = 0x3a3408296709)>#5#,0x3a3408287121 <Object map = 0x3a34082412f1>#6#)
    2: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080cce09 <NativeModule map = 0x3a3408244041>#3#)
    3: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d <undefined>,0x3a3408339a15 <String[#18]: internal/worker/io>)
    4: /* anonymous */(aka /* anonymous */) [0x3a340817db0d] [internal/worker.js:34] [bytecode=0x3a340833a411 offset=376](this=0x3a340804030d <undefined>,0x3a34080ccdc5 <Object map = 0x3a34082402d9>#7#,0x3a34080c301d <JSFunction nativeModuleRequire (sfi = 0x3a3408296629)>#2#,0x3a34080ccd85 <NativeModule map = 0x3a3408244041>#8#,0x3a34080c213d <process map = 0x3a340825a7a1>#4#,0x3a34080c3ae1 <JSFunction internalBinding (sfi = 0x3a3408296709)>#5#,0x3a3408287121 <Object map = 0x3a34082412f1>#6#)
    5: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080ccd85 <NativeModule map = 0x3a3408244041>#8#)
    6: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d <undefined>,0x3a3408339985 <String[#15]: internal/worker>)
    7: /* anonymous */(aka /* anonymous */) [0x3a340816188d] [worker_threads.js:9] [bytecode=0x3a3408339899 offset=4](this=0x3a340804030d <undefined>,0x3a34080cda3d <Object map = 0x3a34082402d9>#9#,0x3a34080c301d <JSFunction nativeModuleRequire (sfi = 0x3a3408296629)>#2#,0x3a34080cd9fd <NativeModule map = 0x3a3408244041>#10#,0x3a34080c213d <process map = 0x3a340825a7a1>#4#,0x3a34080c3ae1 <JSFunction internalBinding (sfi = 0x3a3408296709)>#5#,0x3a3408287121 <Object map = 0x3a34082412f1>#6#)
    8: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080cd9fd <NativeModule map = 0x3a3408244041>#10#)
    9: nativeModuleRequire(aka nativeModuleRequire) [0x3a34080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x3a3408299d29 offset=79](this=0x3a340804030d <undefined>,0x3a340831dff1 <String[#14]: worker_threads>)
   10: /* anonymous */(aka /* anonymous */) [0x3a34081615a9] [inspector.js:29] [bytecode=0x3a3408338855 offset=253](this=0x3a340804030d <undefined>,0x3a34080c7a3d <Object map = 0x3a34082402d9>#11#,0x3a34080c301d <JSFunction nativeModuleRequire (sfi = 0x3a3408296629)>#2#,0x3a34080c79f9 <NativeModule map = 0x3a3408244041>#12#,0x3a34080c213d <process map = 0x3a340825a7a1>#4#,0x3a34080c3ae1 <JSFunction internalBinding (sfi = 0x3a3408296709)>#5#,0x3a3408287121 <Object map = 0x3a34082412f1>#6#)
   11: compileForInternalLoader [0x3a34080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x3a3408299ea1 offset=112](this=0x3a34080c79f9 <NativeModule map = 0x3a3408244041>#12#)
   12: compileForPublicLoader [0x3a34080c60fd] [internal/bootstrap/loaders.js:218] [bytecode=0x3a34083386f9 offset=49](this=0x3a34080c79f9 <NativeModule map = 0x3a3408244041>#12#)
   13: loadNativeModule(aka loadNativeModule) [0x3a340813e9ed] [internal/modules/cjs/helpers.js:24] [bytecode=0x3a3408332051 offset=48](this=0x3a340804030d <undefined>,0x3a3408295fa9 <String[#9]: inspector>,0x3a3408295fa9 <String[#9]: inspector>)
   14: _load [0x3a3408323c45] [internal/modules/cjs/loader.js:919] [bytecode=0x3a3408330ebd offset=224](this=0x3a340813599d <JSFunction Module (sfi = 0x3a340830950d)>#13#,0x3a3408295fa9 <String[#9]: inspector>,0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a340804044d <false>)
   15: require [0x3a3408323cb1] [internal/modules/cjs/loader.js:1093] [bytecode=0x3a3408338535 offset=85](this=0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a3408295fa9 <String[#9]: inspector>)
   16: require(aka require) [0x3a3408150ba5] [internal/modules/cjs/helpers.js:72] [bytecode=0x3a3408338441 offset=10](this=0x3a340804030d <undefined>,0x3a3408295fa9 <String[#9]: inspector>)
   17: /* anonymous */ [0x3a3408150919] [/tmp/aa/fooo.js:1] [bytecode=0x3a340833819d offset=15](this=0x3a340814fdc1 <Object map = 0x3a34082402d9>#15#,0x3a340814fdc1 <Object map = 0x3a34082402d9>#15#,0x3a3408150ba5 <JSFunction require (sfi = 0x3a3408337f71)>#16#,0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a340814f5cd <String[15]: /tmp/aa/fooo.js>,0x3a3408150b39 <String[7]: /tmp/aa>)
   18: InternalFrame [pc: 0x55a4e984081a]
   19: EntryFrame [pc: 0x55a4e98405f8]
   20: builtin exit frame: callAndPauseOnStart(this=0x3a34080c0121 <JSGlobal Object>#17#,0x3a3408150b39 <String[7]: /tmp/aa>,0x3a340814f5cd <String[15]: /tmp/aa/fooo.js>,0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a3408150ba5 <JSFunction require (sfi = 0x3a3408337f71)>#16#,0x3a340814fdc1 <Object map = 0x3a34082402d9>#15#,0x3a340814fdc1 <Object map = 0x3a34082402d9>#15#,0x3a3408150919 <JSFunction (sfi = 0x3a340833652d)>#18#,0x3a34080c0121 <JSGlobal Object>#17#)

   21: _compile [0x3a3408323cdd] [internal/modules/cjs/loader.js:1201] [bytecode=0x3a340833581d offset=417](this=0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a3408150739 <String[315]\: const { Session } = require('inspector');\nconst session = new Session();\nlet done = false;\n\nfunction lala() {\n  // process._rawDebug('hey oh');\n  setInterval(lala, 150);\n}\nlala();\nsession.on('Debugger.paused', () => {\n  // done = true;\n});\nsession.connect();\nsession.post('Debugger.enable');\nconsole.log('Ready');\n\n>,0x3a340814f5cd <String[15]: /tmp/aa/fooo.js>)
   22: .js [0x3a3408323d09] [internal/modules/cjs/loader.js:1224] [bytecode=0x3a3408333095 offset=155](this=0x3a3408147f91 <Object map = 0x3a3408242629>#19#,0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a340814f5cd <String[15]: /tmp/aa/fooo.js>)
   23: load [0x3a3408323c85] [internal/modules/cjs/loader.js:1053] [bytecode=0x3a3408332679 offset=189](this=0x3a340814fcc9 <Module map = 0x3a340825e8f1>#14#,0x3a340814f5cd <String[15]: /tmp/aa/fooo.js>)
   24: _load [0x3a3408323c45] [internal/modules/cjs/loader.js:948] [bytecode=0x3a3408330ebd offset=403](this=0x3a340813599d <JSFunction Module (sfi = 0x3a340830950d)>#13#,0x3a3408134d3d <String[15]: /tmp/aa/fooo.js>,0x3a3408040171 <null>,0x3a34080403e5 <true>)
   25: runMain(aka executeUserEntryPoint) [0x3a340814ebd5] [internal/modules/run_main.js:71] [bytecode=0x3a340832e075 offset=86](this=0x3a340813599d <JSFunction Module (sfi = 0x3a340830950d)>#13#,0x3a3408134d3d <String[15]: /tmp/aa/fooo.js>)
   26: /* anonymous */(aka /* anonymous */) [0x3a340812eda1] [internal/main/run_main_module.js:17] [bytecode=0x3a34083014e5 offset=61](this=0x3a340804030d <undefined>,0x3a34080c213d <process map = 0x3a340825a7a1>#4#,0x3a34080c301d <JSFunction nativeModuleRequire (sfi = 0x3a3408296629)>#2#,0x3a34080c3ae1 <JSFunction internalBinding (sfi = 0x3a3408296709)>#5#,0x3a3408287121 <Object map = 0x3a34082412f1>#6#,0x3a3408301239 <JSFunction (sfi = 0x3a3408301211)>#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:

let done = false;

function lala() {
  setInterval(lala, 150);
}
lala();
console.log('Ready');

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x55b79756afff]
Security context: 0x1d1108280545 <JSObject>#0#
    1: /* anonymous */(aka /* anonymous */) [0x1d11081621b5] [tty.js:1] [bytecode=0x1d1108339e95 offset=-1](this=0x1d110804030d <undefined>,0x1d11080cd725 <Object map = 0x1d11082402d9>#1#,0x1d11080c301d <JSFunction nativeModuleRequire (sfi = 0x1d1108296629)>#2#,0x1d11080cd6e5 <NativeModule map = 0x1d1108244041>#3#,0x1d11080c213d <process map = 0x1d110825a7a1>#4#,0x1d11080c3ae1 <JSFunction internalBinding (sfi = 0x1d1108296709)>#5#,0x1d1108287121 <Object map = 0x1d11082412f1>#6#)
    2: compileForInternalLoader [0x1d11080c6151] [internal/bootstrap/loaders.js:276] [bytecode=0x1d1108299ea1 offset=112](this=0x1d11080cd6e5 <NativeModule map = 0x1d1108244041>#3#)
    3: nativeModuleRequire(aka nativeModuleRequire) [0x1d11080c301d] [internal/bootstrap/loaders.js:305] [bytecode=0x1d1108299d29 offset=79](this=0x1d110804030d <undefined>,0x1d11082fe4f5 <String[#3]: tty>)
    4: createWritableStdioStream(aka createWritableStdioStream) [0x1d110812d5c9] [internal/bootstrap/switches/is_main_thread.js:42] [bytecode=0x1d1108339c05 offset=68](this=0x1d110804030d <undefined>,1)
    5: getStdout [0x1d110812d609] [internal/bootstrap/switches/is_main_thread.js:118] [bytecode=0x1d11083398d9 offset=19](this=0x1d11080c213d <process map = 0x1d110825a7a1>#4#)
    6: StubFrame [pc: 0x55b79737a90f]
    7: StubFrame [pc: 0x55b7977b928d]
    8: get [0x1d1108118445] [internal/console/constructor.js:164] [bytecode=0x1d1108339785 offset=10](this=0x1d1108116f59 <Object map = 0x1d1108256e21>#7#)
    9: StubFrame [pc: 0x55b79737a90f]
   10: StubFrame [pc: 0x55b7977b928d]
   11: /* anonymous */ [0x1d11082e4205] [internal/console/constructor.js:286] [bytecode=0x1d11083396c1 offset=9](this=0x1d1108116f59 <Object map = 0x1d1108256e21>#7#,0x1d1108161fed <JSArray[1]>#8#)
   12: log [0x1d11081165a1] [internal/console/constructor.js:297] [bytecode=0x1d11083395ed offset=29](this=0x1d1108116f59 <Object map = 0x1d1108256e21>#7#)
   13: arguments adaptor frame: 1->0
   14: InternalFrame [pc: 0x55b79734881a]
   15: EntryFrame [pc: 0x55b7973485f8]
   16: builtin exit frame: consoleCall(this=0x1d1108116f59 <Object map = 0x1d1108256e21>#7#,0x1d1108336411 <String[#5]: Ready>,0x1d110811725d <JSBoundFunction (BoundTargetFunction 0x1d11081165a1)>#9#,0x1d110828ed39 <JSFunction log (sfi = 0x1d11081cfa31)>#10#,0x1d1108116f59 <Object map = 0x1d1108256e21>#7#)

   17: /* anonymous */ [0x1d1108150881] [/tmp/aa/fooo2.js:8] [bytecode=0x1d1108338041 offset=36](this=0x1d110814fde5 <Object map = 0x1d11082402d9>#11#,0x1d110814fde5 <Object map = 0x1d11082402d9>#11#,0x1d1108150b0d <JSFunction require (sfi = 0x1d1108337e15)>#12#,0x1d110814fced <Module map = 0x1d110825e8f1>#13#,0x1d110814f5e9 <String[16]: /tmp/aa/fooo2.js>,0x1d1108150aa1 <String[7]: /tmp/aa>)
   18: InternalFrame [pc: 0x55b79734881a]
   19: EntryFrame [pc: 0x55b7973485f8]
   20: builtin exit frame: callAndPauseOnStart(this=0x1d11080c0121 <JSGlobal Object>#14#,0x1d1108150aa1 <String[7]: /tmp/aa>,0x1d110814f5e9 <String[16]: /tmp/aa/fooo2.js>,0x1d110814fced <Module map = 0x1d110825e8f1>#13#,0x1d1108150b0d <JSFunction require (sfi = 0x1d1108337e15)>#12#,0x1d110814fde5 <Object map = 0x1d11082402d9>#11#,0x1d110814fde5 <Object map = 0x1d11082402d9>#11#,0x1d1108150881 <JSFunction (sfi = 0x1d11083364a1)>#15#,0x1d11080c0121 <JSGlobal Object>#14#)

   21: _compile [0x1d1108323cdd] [internal/modules/cjs/loader.js:1201] [bytecode=0x1d1108335821 offset=417](this=0x1d110814fced <Module map = 0x1d110825e8f1>#13#,0x1d110815075d <String[129]\: let done = false;\n\nfunction lala() {\n  // process._rawDebug('hey oh');\n  setInterval(lala, 150);\n}\nlala();\nconsole.log('Ready');\n>,0x1d110814f5e9 <String[16]: /tmp/aa/fooo2.js>)
   22: .js [0x1d1108323d09] [internal/modules/cjs/loader.js:1224] [bytecode=0x1d1108333099 offset=155](this=0x1d1108147f91 <Object map = 0x1d1108242629>#16#,0x1d110814fced <Module map = 0x1d110825e8f1>#13#,0x1d110814f5e9 <String[16]: /tmp/aa/fooo2.js>)
   23: load [0x1d1108323c85] [internal/modules/cjs/loader.js:1053] [bytecode=0x1d110833267d offset=189](this=0x1d110814fced <Module map = 0x1d110825e8f1>#13#,0x1d110814f5e9 <String[16]: /tmp/aa/fooo2.js>)
   24: _load [0x1d1108323c45] [internal/modules/cjs/loader.js:948] [bytecode=0x1d1108330ec1 offset=403](this=0x1d11081359a5 <JSFunction Module (sfi = 0x1d110830950d)>#17#,0x1d1108134d45 <String[16]: /tmp/aa/fooo2.js>,0x1d1108040171 <null>,0x1d11080403e5 <true>)
   25: runMain(aka executeUserEntryPoint) [0x1d110814ebd5] [internal/modules/run_main.js:71] [bytecode=0x1d110832e075 offset=86](this=0x1d11081359a5 <JSFunction Module (sfi = 0x1d110830950d)>#17#,0x1d1108134d45 <String[16]: /tmp/aa/fooo2.js>)
   26: /* anonymous */(aka /* anonymous */) [0x1d110812eda1] [internal/main/run_main_module.js:17] [bytecode=0x1d11083014e5 offset=61](this=0x1d110804030d <undefined>,0x1d11080c213d <process map = 0x1d110825a7a1>#4#,0x1d11080c301d <JSFunction nativeModuleRequire (sfi = 0x1d1108296629)>#2#,0x1d11080c3ae1 <JSFunction internalBinding (sfi = 0x1d1108296709)>#5#,0x1d1108287121 <Object map = 0x1d11082412f1>#6#,0x1d1108301239 <JSFunction (sfi = 0x1d1108301211)>#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:

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) { }

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 <JSObject>#0#                                                                                                                                                                                                                                    
    1: /* anonymous */(aka /* anonymous */) [0xbec08162615] [net.js:1] [bytecode=0xbec0833ad51 offset=-1](this=0x0bec0804030d <undefined>,0x0bec080ccf71 <Object map = 0xbec082402d9>#1#,0x0bec080c3039 <JSFunction nativeModuleRequire (sfi = 0xbec08296629)>#2#,0x0bec080ccf31 <
NativeModule map = 0xbec08244041>#3#,0x0bec080c213d <process map = 0xbec0825a7a1>#4#,0x0bec080c3afd <JSFunction internalBinding (sfi = 0xbec08296709)>#5#,0x0bec08287121 <Object map = 0xbec082412f1>#6#)                                                                         
    2: compileForInternalLoader [0xbec080c616d] [internal/bootstrap/loaders.js:276] [bytecode=0xbec08299ea1 offset=112](this=0x0bec080ccf31 <NativeModule map = 0xbec08244041>#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 <JSObject>#0#
    2: /* anonymous */(aka /* anonymous */) [0x2e7b0817e061] [os.js:23] [bytecode=0x2e7b0836b2cd offset=147](this=0x2e7b0804030d <undefined>,0x2e7b080cd049 <Object map = 0x2e7b082402d9>#1#,0x2e7b080c308d <JSFunction nativeModuleRequire (sfi = 0x2e7b08296629)>#2#,0x2e7b080cd
009 <NativeModule map = 0x2e7b08244041>#3#,0x2e7b080c213d <process map = 0x2e7b0825a7a1>#4#,0x2e7b080c3b51 <JSFunction internalBinding (sfi = 0x2e7b08296709)>#5#,0x2e7b08287121 <Object map = 0x2e7b082412f1>#6#)
    3: compileForInternalLoader [0x2e7b080c61c1] [internal/bootstrap/loaders.js:276] [bytecode=0x2e7b08299ea1 offset=112](this=0x2e7b080cd009 <NativeModule map = 0x2e7b08244041>#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:

// 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!

$ 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::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::alloc
ator<std::unique_ptr<v8_inspector::protocol::Debugger::CallFrame, std::default_delete<v8_inspector::protocol::Debugger::CallFrame> > > > > >*) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node]
10: 0x56523e11ee77 v8_inspector::V8DebuggerAgentImpl::didPause(int, v8::Local<v8::Value>, std::vector<int, std::allocator<int> > 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<void (v8_inspector::V8InspectorSessionImpl*)> const&) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node]
13: 0x56523e1097ff v8_inspector::V8Debugger::handleProgramBreak(v8::Local<v8::Context>, v8::Local<v8::Value>, std::vector<int, std::allocator<int> > const&, v8::debug::ExceptionType, bool) [/home/mmarchini/workspace/nodejs/node-v8/out/Debug/node]
14: 0x56523d7bf06d v8::internal::Debug::OnDebugBreak(v8::internal::Handle<v8::internal::FixedArray>) [/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]

@mmarchini thanks a lot for looking into this!

[mmarchini]

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]

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

[mmarchini]

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]

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]

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]

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

[gengjiawen]

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

[mmarchini]

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]

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

[mmarchini]

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.