Skip to content

second pass phantom callback leads to infinite recursion #27577

Closed
Closed
second pass phantom callback leads to infinite recursion#27577
Labels
confirmed-bugIssues and PRs for confirmed bugs.inspectorIssues and PRs related to the V8 inspector protocol.v8 engineIssues and PRs related to the V8 dependency.

Description

@hashseed
hashseed
opened on May 6, 2019

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());

Activity

  1. addaleax commented on May 6, 2019

    @addaleax
    addaleax
    on May 6, 2019
    Member

    @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?

  2. addaleax
    added
    inspectorIssues and PRs related to the V8 inspector protocol.
    on May 6, 2019

  3. hashseed commented on May 6, 2019

    @hashseed
    hashseed
    on May 6, 2019
    MemberAuthor

    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.

  4. hashseed commented on May 6, 2019

    @hashseed
    hashseed
    on May 6, 2019
    MemberAuthor

    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.

  5. hashseed
    closed this as completedon May 6, 2019

  6. addaleax commented on May 6, 2019

    @addaleax
    addaleax
    on May 6, 2019
    Member

    @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.

  7. addaleax
    reopened this on May 6, 2019
  8. addaleax
    added
    confirmed-bugIssues and PRs for confirmed bugs.
    v8 engineIssues and PRs related to the V8 dependency.
    on May 6, 2019

  9. addaleax commented on May 6, 2019

    @addaleax
    addaleax
    on May 6, 2019
    Member

    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;

  10. hashseed commented on May 7, 2019

    @hashseed
    hashseed
    on May 7, 2019
    MemberAuthor

    That solution look alright to me :)

  11. addaleax commented on May 11, 2019

    @addaleax
    addaleax
    on May 11, 2019
    Member

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

  12. evanlucas commented on Apr 2, 2021

    @evanlucas
    evanlucas
    on Apr 2, 2021
    Contributor

    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!

  13. evanlucas
    closed this as completedon Apr 2, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    confirmed-bugIssues and PRs for confirmed bugs.inspectorIssues and PRs related to the V8 inspector protocol.v8 engineIssues and PRs related to the V8 dependency.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions