second pass phantom callback leads to infinite recursion

[hashseed]

In my GN build, I'm observing this failure:

• Run ./node test/parallel/test-repl-tab-complete.js
• Observe assertion failure.

#
# Fatal error in ../../v8/src/execution.cc, line 224
# Check failed: AllowJavascriptExecution::IsAllowed(isolate).
#

The stack trace I get is this

[0 ] v8::base::OS::Abort()                                        ../../v8/src/base/platform/platform-posix.cc:400
[1 ] V8_Fatal(char const*, int, char const*, ...)                 ../../v8/src/base/logging.cc:171        
[2 ] v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) ../../v8/src/execution.cc:224           
[3 ] 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>*) ../../v8/src/execution.cc:358           
[4 ] v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) ../../v8/src/api.cc:4992                
[5 ] Emit                                                         ../../node/src/async_wrap.cc:122        
[6 ] node::AsyncWrap::EmitBefore(node::Environment*, double)      ../../node/src/async_wrap.cc:149        
[7 ] InternalCallbackScope                                        ../../node/src/api/callback.cc:65       
[8 ] InternalMakeCallback                                         ../../node/src/api/callback.cc:145      
[9 ] node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) ../../node/src/async_wrap.cc:692        
[10] OnMessage                                                    ../../node/src/inspector_js_api.cc:75   
[11] SendMessageToFrontend                                        ../../node/src/inspector_js_api.cc:56   
[12] node::inspector::(anonymous namespace)::ChannelImpl::sendMessageToFrontend(v8_inspector::StringView const&) ../../node/src/inspector_agent.cc:280   
[13] node::inspector::(anonymous namespace)::ChannelImpl::sendNotification(std::__1::unique_ptr<v8_inspector::StringBuffer, std::__1::default_delete<v8_inspector::StringBuffer> >) ../../node/src/inspector_agent.cc:274   
[14] v8_inspector::V8InspectorSessionImpl::sendProtocolNotification(std::__1::unique_ptr<v8_inspector::protocol::Serializable, std::__1::default_delete<v8_inspector::protocol::Serializable> >) ../../v8/src/inspector/v8-inspector-session-impl.cc:182
[15] v8_inspector::protocol::Runtime::Frontend::executionContextDestroyed(int) gen/v8/src/inspector/protocol/Runtime.cpp:1337
[16] v8_inspector::V8RuntimeAgentImpl::reportExecutionContextDestroyed(v8_inspector::InspectedContext*) ../../v8/src/inspector/v8-runtime-agent-impl.cc:820
[17] v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1::operator()(v8_inspector::V8InspectorSessionImpl*) const ../../v8/src/inspector/v8-inspector-impl.cc:236
[18] std::__1::__invoke<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*> ../../buildtools/third_party/libc++/trunk/include/type_traits:4399
[19] void std::__1::__invoke_void_return_wrapper<void>::__call<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*>(v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*&&) ../../buildtools/third_party/libc++/trunk/include/__functional_base:348
[20] std::__1::__function::__alloc_func<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1, std::__1::allocator<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1>, void (v8_inspector::V8InspectorSessionImpl*)>::operator()(v8_inspector::V8InspectorSessionImpl*&&) ../../buildtools/third_party/libc++/trunk/include/functional:1531
[21] void std::__1::__function::__policy_invoker<void (v8_inspector::V8InspectorSessionImpl*)>::__call_impl<std::__1::__function::__alloc_func<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1, std::__1::allocator<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1>, void (v8_inspector::V8InspectorSessionImpl*)> >(std::__1::__function::__policy_storage const*, v8_inspector::V8InspectorSessionImpl*) ../../buildtools/third_party/libc++/trunk/include/functional:2014
[22] std::__1::__function::__policy_func<void (v8_inspector::V8InspectorSessionImpl*)>::operator()(v8_inspector::V8InspectorSessionImpl*&&) const ../../buildtools/third_party/libc++/trunk/include/functional:2127
[23] std::__1::function<void (v8_inspector::V8InspectorSessionImpl*)>::operator()(v8_inspector::V8InspectorSessionImpl*) const ../../buildtools/third_party/libc++/trunk/include/functional:2351
[24] v8_inspector::V8InspectorImpl::forEachSession(int, std::__1::function<void (v8_inspector::V8InspectorSessionImpl*)> const&) ../../v8/src/inspector/v8-inspector-impl.cc:392
[25] v8_inspector::V8InspectorImpl::contextCollected(int, int)    ../../v8/src/inspector/v8-inspector-impl.cc:235
[26] v8_inspector::InspectedContext::WeakCallbackData::callContextCollected(v8::WeakCallbackInfo<v8_inspector::InspectedContext::WeakCallbackData> const&) ../../v8/src/inspector/inspected-context.cc:38
[27] v8::internal::GlobalHandles::PendingPhantomCallback::Invoke(v8::internal::Isolate*, v8::internal::GlobalHandles::PendingPhantomCallback::InvocationType) ../../v8/src/global-handles.cc:1098     
[28] v8::internal::GlobalHandles::InvokeSecondPassPhantomCallbacks() ../../v8/src/global-handles.cc:968      
[29] v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) ../../v8/src/heap/heap.cc:1337          
[30] v8::internal::Heap::AllocateRawWithLightRetry(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) ../../v8/src/heap/heap.cc:4514          
[31] v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) ../../v8/src/heap/heap.cc:4528          
[32] v8::internal::Factory::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) ../../v8/src/heap/factory.cc:136        
[33] v8::internal::Factory::NewRawOneByteString(int, v8::internal::AllocationType) ../../v8/src/heap/factory.cc:1000       
[34] v8::internal::Factory::NewStringFromTwoByte(unsigned short const*, int, v8::internal::AllocationType) ../../v8/src/heap/factory.cc:779        
[35] v8::internal::Factory::NewStringFromTwoByte(v8::internal::Vector<unsigned short const>, v8::internal::AllocationType) ../../v8/src/heap/factory.cc:796        
[36] v8::(anonymous namespace)::NewString(v8::internal::Factory*, v8::NewStringType, v8::internal::Vector<unsigned short const>) ../../v8/src/api.cc:6363                
[37] v8::String::NewFromTwoByte(v8::Isolate*, unsigned short const*, v8::NewStringType, int) ../../v8/src/api.cc:6428                
[38] SendMessageToFrontend                                        ../../node/src/inspector_js_api.cc:53   
[39] node::inspector::(anonymous namespace)::ChannelImpl::sendMessageToFrontend(v8_inspector::StringView const&) ../../node/src/inspector_agent.cc:280   
[40] node::inspector::(anonymous namespace)::ChannelImpl::sendNotification(std::__1::unique_ptr<v8_inspector::StringBuffer, std::__1::default_delete<v8_inspector::StringBuffer> >) ../../node/src/inspector_agent.cc:274   
[41] v8_inspector::V8InspectorSessionImpl::sendProtocolNotification(std::__1::unique_ptr<v8_inspector::protocol::Serializable, std::__1::default_delete<v8_inspector::protocol::Serializable> >) ../../v8/src/inspector/v8-inspector-session-impl.cc:182
[42] v8_inspector::protocol::Runtime::Frontend::executionContextDestroyed(int) gen/v8/src/inspector/protocol/Runtime.cpp:1337
[43] v8_inspector::V8RuntimeAgentImpl::reportExecutionContextDestroyed(v8_inspector::InspectedContext*) ../../v8/src/inspector/v8-runtime-agent-impl.cc:820
[44] v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1::operator()(v8_inspector::V8InspectorSessionImpl*) const ../../v8/src/inspector/v8-inspector-impl.cc:236
[45] std::__1::__invoke<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*> ../../buildtools/third_party/libc++/trunk/include/type_traits:4399
[46] void std::__1::__invoke_void_return_wrapper<void>::__call<v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*>(v8_inspector::V8InspectorImpl::contextCollected(int, int)::$_1&, v8_inspector::V8InspectorSessionImpl*&&) ../../buildtools/third_party/libc++/trunk/include/__functional_base:348

I think the assertion failure is actually a red herring.

What actually happens is that during GC, we trigger a second-pass-phantom-callback. That sends a notification to the inspector, which in inspector_js_api.cc tries to allocate a string to pass that along. Only, allocating the string fails, because we are not done with GC yet. So we perform GC.

That triggers a recursion until we run out of stack, in which case things start to behave weirdly and we get this assertion failure. This weirdness does not reproduce on the regular Node build. The following patch helps with reproducing this on the regular Node build though:

diff --git a/deps/v8/src/heap/heap.cc b/deps/v8/src/heap/heap.cc
index e72269d40a..9e02bab258 100644
--- a/deps/v8/src/heap/heap.cc
+++ b/deps/v8/src/heap/heap.cc
@@ -1335,7 +1335,11 @@ bool Heap::CollectGarbage(AllocationSpace space,
   }
 
   // Ensure that all pending phantom callbacks are invoked.
-  isolate()->global_handles()->InvokeSecondPassPhantomCallbacks();
+  {
+    DCHECK(AllowHeapAllocation::IsAllowed());
+    DisallowHeapAllocation no_allocation_during_gc;
+    isolate()->global_handles()->InvokeSecondPassPhantomCallbacks();
+  }
 
   // The VM is in the GC state until exiting this function.
   VMState<GC> state(isolate());

[addaleax]

@hashseed Just to verify – the PR description of #25992 is wrong in that the second pass callback is not a safe place to execute JS, right?

[hashseed]

I'm wondering about this myself as well. My impression is that the second pass callback is safe to execute JS. But that could easily cause another GC, which would lead to this recursion.

[hashseed]

I just cleared it up with the GC folks. The second pass callback is safe. It should run asynchronously, so that it would not lead to recursion.

Interestingly I can't reproduce this issue anymore after a clean rebuild.

[addaleax]

@hashseed I think this is a real bug, and not necessarily related to your GN build. I don’t know if it’s related to GC, but I can reproduce this with a standard Node.js debug build, but only a) consistently when run under valgrind or b) 2 out of 100 runs without valgrind.

[addaleax]

Fully deterministic reproduction using a debug build:

// --gc-interval=10 --expose-gc
'use strict';
const vm = require('vm');
const inspector = require('inspector');

const session = new inspector.Session();
session.connect();
session.post('Runtime.enable');

const kContextCount = 3;  // kContextCount = 2 fails differently

let contexts = [];
for (let i = 0; i < kContextCount; i++)
  contexts.push(vm.runInNewContext('Object'));
contexts = null;

setImmediate(() => {
  global.gc();
});

I’ll try to work on a solution somewhere along these lines (but Debug builds reaaaally take forever for me so it might take a while just to confirm that it solves the issue and everything):

diff --git a/deps/v8/src/global-handles.cc b/deps/v8/src/global-handles.cc
index 350380b23ce6..58987926dc13 100644
--- a/deps/v8/src/global-handles.cc
+++ b/deps/v8/src/global-handles.cc
@@ -995,11 +995,19 @@ void GlobalHandles::InvokeSecondPassPhantomCallbacksFromTask() {
 }
 
 void GlobalHandles::InvokeSecondPassPhantomCallbacks() {
+  // The callbacks may execute JS, which in turn may lead to another GC run.
+  // If we are already processing the callbacks, we do not want to start over
+  // from within the inner GC.
+  if (running_second_pass_callbacks_) return;
+  running_second_pass_callbacks_ = true;
+
+  AllowJavascriptExecution allow_js(isolate());
   while (!second_pass_callbacks_.empty()) {
     auto callback = second_pass_callbacks_.back();
     second_pass_callbacks_.pop_back();
     callback.Invoke(isolate(), PendingPhantomCallback::kSecondPass);
   }
+  running_second_pass_callbacks_ = false;
 }
 
 size_t GlobalHandles::PostScavengeProcessing(unsigned post_processing_count) {
diff --git a/deps/v8/src/global-handles.h b/deps/v8/src/global-handles.h
index 8caa3c33ce72..f1abc9326974 100644
--- a/deps/v8/src/global-handles.h
+++ b/deps/v8/src/global-handles.h
@@ -231,6 +231,7 @@ class GlobalHandles final {
       traced_pending_phantom_callbacks_;
   std::vector<PendingPhantomCallback> second_pass_callbacks_;
   bool second_pass_callbacks_task_posted_ = false;
+  bool running_second_pass_callbacks_ = false;
 
   // Counter for recursive garbage collections during callback processing.
   unsigned post_gc_processing_count_ = 0;

[hashseed]

That solution look alright to me :)

[addaleax]

Finally got around to writing regression tests that reproduce this, CL is open at https://chromium-review.googlesource.com/c/v8/v8/+/1607762 :)

[evanlucas]

It looks like this was released in V8 7.6.173~2, which is included in >= Node 12.11.0.

Going to go ahead and close this, but feel free to re-open if closing is premature. Thanks!