Scripts are sent in a non-existent `executionContextId`

[connor4312]

Version

19.8.1

Platform

Darwin MacBook-Pro-2.guest.corp.microsoft.com 22.4.0 Darwin Kernel Version 22.4.0: Mon Mar 6 21:00:17 PST 2023; root:xnu-8796.101.5~3/RELEASE_X86_64 x86_64

Subsystem

inspector

What steps will reproduce the bug?

Run the following script:

const { Session } = require('node:inspector');

const session = new Session();
const executionContexts = new Map();
session.on('Runtime.executionContextCreated', call => {
  console.log(call);
  executionContexts.set(call.params.context.id, call.params.context);
});
session.on('Debugger.scriptParsed', call => {
  console.log(call);
  if (!executionContexts.has(call.params.executionContextId)) {
    console.error(`Got script in execution context ${call.params.executionContextId}, but have only ${[...executionContexts.keys()].join()}`);
    process.exit(1);
  }
});

session.connect();

session.post('Runtime.enable', () => {
  console.log('Runtime enabled')

  session.post('Debugger.enable', () => {
    console.log('Debugger enabled')
  });
});

How often does it reproduce? Is there a required condition?

100% of the time

What is the expected behavior? Why is that the expected behavior?

The script should run successfully. All execution contexts should come in Runtime.executionContextCreated events before Runtime.enable returns.

What do you see instead?

{
  method: 'Runtime.executionContextCreated',
  params: {
    context: {
      id: 1,
      origin: '',
      name: '/Users/connor/.asdf/installs/nodejs/19.8.1/bin/node[90017]',
      uniqueId: '-8333824095165494686.-3638729329792817601',
      auxData: [Object]
    }
  }
}
Runtime enabled
{
  method: 'Debugger.scriptParsed',
  params: {
    scriptId: '6',
    url: 'node:internal/per_context/primordials',
    startLine: 0,
    startColumn: 0,
    endLine: 737,
    endColumn: 0,
    executionContextId: 0,
    hash: 'bc07b5754e60d05f0e36aee626f46b4561cc1d342c7c84e1655eca736753f7f8',
    isLiveEdit: false,
    sourceMapURL: '',
    hasSourceURL: false,
    isModule: false,
    length: 21457,
    stackTrace: { callFrames: [Array] },
    scriptLanguage: 'JavaScript',
    embedderName: 'node:internal/per_context/primordials'
  }
}
Got script in execution context 0, but have only 1

Additional information

Later scripts are in the execution context ID of 1, but earlier ones are in the non-existent 0 context.

Originally came up in vscode-js-debug as a result of adding more intended correctness around how execution contexts are handled microsoft/vscode-js-debug#1643

[bnoordhuis]

Pull request welcome. What probably needs to happen is a call to env->inspector_agent()->ContextCreated() right after the V8 context is created with Context::New() or Context::FromSnapshot() so the context gets assigned an execution context ID by the V8 inspector.

node::Environment::AssignToContext() usually takes care of that but it's possible the inspector agent hasn't been started yet. There's also no inspector agent when snapshotting, which may be the root cause here.

See also node::CreateEnvironment() and node::Environment::InitializeInspector(). Grep for should_create_inspector and kNoCreateInspector.

[debadree25]

@bnoordhuis

There's also no inspector agent when snapshotting, which may be the root cause here.

I think this indeed could be the issue here, I think this is a relevant comment I found while looking through the code:

node/src/api/embed_helpers.cc

Lines 180 to 183 in 67fdb74

	// It's not guaranteed that a context that goes through
	// v8_inspector::V8Inspector::contextCreated() is runtime-independent,
	// so do not start the inspector on the main context when building
	// the default snapshot.

note that running test code only shows that the code involving primordials doesnt have correct executionId? which I believe is snapshotted while building? Seems kind of like a dead end 😅 any pointers on where else one could proceed could be helpful!

Thank You!

[bnoordhuis]

So, I'm not 100% sure, but I think it can be fixed by calling ContextCreated() after the snapshot has been deserialized with Context::FromSnapshot().

[debadree25]

IIUC ContextCreated() already seems to be called no?
in

node/src/api/environment.cc

Lines 452 to 469 in 67fdb74

	if (use_snapshot) {
	context = Context::FromSnapshot(isolate,
	SnapshotData::kNodeMainContextIndex,
	{DeserializeNodeInternalFields, env})
	.ToLocalChecked();
	CHECK(!context.IsEmpty());
	Context::Scope context_scope(context);
	if (InitializeContextRuntime(context).IsNothing()) {
	FreeEnvironment(env);
	return nullptr;
	}
	SetIsolateErrorHandlers(isolate, {});
	}
	Context::Scope context_scope(context);
	env->InitializeMainContext(context, env_snapshot_info);

here after creating context from snapshot we call InitializeMainContext which in turn calls

node/src/env.cc

Line 818 in 67fdb74

AssignToContext(context, principal_realm_.get(), ContextInfo(""));

which should call contextCreated? is there any other place we should call it again?

[bnoordhuis]

It calls it too early. CreateEnvironment() calls InitializeMainContext() - which calls AssignToContext() - before the inspector agent is started.

[debadree25]

ok I tried something like this

diff --git a/src/api/environment.cc b/src/api/environment.cc
index c9bb4bdf16..6804ee6f90 100644
--- a/src/api/environment.cc
+++ b/src/api/environment.cc
@@ -478,6 +478,8 @@ Environment* CreateEnvironment(
       env->InitializeInspector({});
     }
   }
+  std::cout << "context created" << std::endl;
+  env->inspector_agent()->ContextCreated(context, ContextInfo(""));
 #endif
 
   if (!use_snapshot && env->principal_realm()->RunBootstrapping().IsEmpty()) {
diff --git a/src/env.cc b/src/env.cc
index 571a8ed5ce..4b134a8a47 100644
--- a/src/env.cc
+++ b/src/env.cc
@@ -582,10 +582,6 @@ void Environment::AssignToContext(Local<v8::Context> context,
   // This must not be done before other context fields are initialized.
   ContextEmbedderTag::TagNodeContext(context);
 
-#if HAVE_INSPECTOR
-  inspector_agent()->ContextCreated(context, info);
-#endif  // HAVE_INSPECTOR
-
   this->async_hooks()->InstallPromiseHooks(context);
   TrackContext(context);
 }
diff --git a/src/node.cc b/src/node.cc
index 66b7ef5ec5..f35b4d81a8 100644
--- a/src/node.cc
+++ b/src/node.cc
@@ -199,7 +199,7 @@ void Environment::InitializeInspector(
   if (inspector_agent_->options().break_node_first_line) {
     inspector_agent_->PauseOnNextJavascriptStatement("Break at bootstrap");
   }
-
+  std::cout << "Inspector started" << std::endl;
   return;
 }
 #endif  // HAVE_INSPECTOR

(some couts to track things)

the output now looks like this

Inspector started
context created
Runtime.executionContextCreated
{
  method: 'Runtime.executionContextCreated',
  params: {
    context: {
      id: 2,
      origin: '',
      name: '',
      uniqueId: '2734271943675504607.6360033039428185957',
      auxData: [Object]
    }
  }
}
Runtime.executionContextCreated
{
  method: 'Runtime.executionContextCreated',
  params: {
    context: {
      id: 1,
      origin: '',
      name: 'out/Release/node[54719]',
      uniqueId: '-9125050196401512131.4619138934371537908',
      auxData: [Object]
    }
  }
}
Runtime enabled
Debugger.scriptParsed
{
  method: 'Debugger.scriptParsed',
  params: {
    scriptId: '6',
    url: 'node:internal/per_context/primordials',
    startLine: 0,
    startColumn: 0,
    endLine: 737,
    endColumn: 0,
    executionContextId: 0,
    hash: 'bc07b5754e60d05f0e36aee626f46b4561cc1d342c7c84e1655eca736753f7f8',
    isLiveEdit: false,
    sourceMapURL: '',
    hasSourceURL: false,
    isModule: false,
    length: 21457,
    stackTrace: { callFrames: [Array] },
    scriptLanguage: 'JavaScript',
    embedderName: 'node:internal/per_context/primordials'
  }
}
Got script in execution context 0, but have only 2,1
Debugger.scriptParsed
{
  method: 'Debugger.scriptParsed',
  params: {
    scriptId: '431',
    url: 'node:internal/modules/esm/handle_process_exit',
    startLine: 0,
    startColumn: 0,
    endLine: 14,
    endColumn: 0,
    executionContextId: 2,
    hash: '84163086c39d7e2b604473cf0a4d87c61ccf8d210cfbac4336bfb23348612f6f',
    executionContextAuxData: { isDefault: false },
    isLiveEdit: false,
    sourceMapURL: '',
    hasSourceURL: false,
    isModule: false,
    length: 424,
    stackTrace: { callFrames: [Array] },
    scriptLanguage: 'JavaScript',
    embedderName: 'node:internal/modules/esm/handle_process_exit'
  }
}

One more executionId in the mix somehow?

[debadree25]

So far no success, tried to debug why #47438 (comment), overall can't really understand the flow additional contexts are coming out of and somehow the original '0' executionId also comes in 😕😓

[connor4312]

I got a report of a behavior that I can't work around and may have the same root cause: #51067