EXC_BAD_ACCESS: Environment::GetCurrent returns nullptr in node::EmitAsyncDestroy

[markandrus]

• Version: v10.11.0
• Platform: macOS
• Subsystem: async_hooks

Hi, I'm porting my Native Addon from NAN to N-API and I've hit an issue. I have some objects which make use of node-addon-api's Napi::ObjectWrap and Napi::AsyncContext classes; however, I'm raising an issue here, because I'm not sure these are specific to node-addon-api. I actually hit a similar issue with NAN a while back (nodejs/nan#772).

What I see is that the call to Environment::GetCurrent(isolate) in node::EmitAsyncDestroy returns nullptr. I believe that is because this call to isolate->GetCurrentContext() returns nullptr. This results in an EXC_BAD_ACCESS.

You can see how I worked around this issue (starting with Node 9) when using NAN, although 1. it's probably incorrect and 2. it relies on v8 APIs that I don't want to use when porting to N-API.

Is this a bug? Am I doing something wrong? Thanks in advance!

[bnoordhuis]

Am I doing something wrong?

Possibly. isolate->GetCurrentContext() returns an empty handle when no V8 context is currently active.

What is the reason for that? It's unusual enough that something is probably amiss.

[addaleax]

I think this might be an N-API bug, or at least something that could be partially addressed there. In napi_async_destroy(), we call node::EmitAsyncDestroy(isolate, *node_async_context);, and try to figure out the current context from the Isolate; however, we store the Node.js Context that we’re using in the napi_env as well, and should be able to get it from there.

This may apply to the other napi_async_* methods as well, but I imagine one difference is that we need to be able to call napi_async_destroy() when we’re unable to run JS code, e.g. during GC – and I assume that the reason for the lack of a current context here is that your addon calls into N-API during GC.

[markandrus]

Here's a trace back if it's of any use. I'm trying to find a minimal repro, but it's proving elusive.

Traceback

Process 87620 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x58c0)
    frame #0: 0x00000001006b454c node`v8::internal::Isolate::context(this=0x0000000000000000) at isolate.h:592
   589 	  Address get_address_from_id(IsolateAddressId id);
   590 	
   591 	  // Access to top context (where the current function object was created).
-> 592 	  Context* context() { return thread_local_top_.context_; }
   593 	  inline void set_context(Context* context);
   594 	  Context** context_address() { return &thread_local_top_.context_; }
   595 	
Target 0: (node) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x58c0)
  * frame #0: 0x00000001006b454c node`v8::internal::Isolate::context(this=0x0000000000000000) at isolate.h:592
    frame #1: 0x00000001006dfb1d node`v8::Isolate::GetCurrentContext(this=0x0000000000000000) at api.cc:8107
    frame #2: 0x0000000100014f05 node`node::Environment::GetCurrent(isolate=0x0000000000000000) at env-inl.h:301
    frame #3: 0x000000010001517f node`node::EmitAsyncDestroy(isolate=0x0000000000000000, asyncContext=(async_id = 24, trigger_async_id = 0)) at async_wrap.cc:732
    frame #4: 0x00000001000dfd96 node`::napi_async_destroy(env=0x0000000105d121d0, async_context=0x0000000105912430) at node_api.cc:3300
    frame #5: 0x000000010a8037ee wrtc.node`Napi::AsyncContext::~AsyncContext(this=0x0000000105913880) at napi-inl.h:3461
    frame #6: 0x000000010a803835 wrtc.node`Napi::AsyncContext::~AsyncContext(this=0x0000000105913880) at napi-inl.h:3459
    frame #7: 0x000000010a803859 wrtc.node`Napi::AsyncContext::~AsyncContext(this=0x0000000105913880) at napi-inl.h:3459
    frame #8: 0x000000010aaaa1e5 wrtc.node`node_webrtc::napi::AsyncObjectWrap<node_webrtc::MediaStreamTrack>::DestroyAsyncContext(this=0x00000001059136a0) at napi_async_object_wrap.h:24
    frame #9: 0x000000010aaa9633 wrtc.node`node_webrtc::napi::AsyncObjectWrap<node_webrtc::MediaStreamTrack>::~AsyncObjectWrap(this=0x00000001059136a0) at napi_async_object_wrap.h:39
    frame #10: 0x000000010aaa401f wrtc.node`node_webrtc::napi::AsyncObjectWrapWithLoop<node_webrtc::MediaStreamTrack>::~AsyncObjectWrapWithLoop(this=0x00000001059136a0) at napi_async_object_wrap_with_loop.h:16
    frame #11: 0x000000010aaa413c wrtc.node`node_webrtc::MediaStreamTrack::~MediaStreamTrack(this=0x00000001059136a0) at media_stream_track.cc:50
    frame #12: 0x000000010aaa42b5 wrtc.node`node_webrtc::MediaStreamTrack::~MediaStreamTrack(this=0x00000001059136a0) at media_stream_track.cc:47
    frame #13: 0x000000010aaa4319 wrtc.node`node_webrtc::MediaStreamTrack::~MediaStreamTrack(this=0x00000001059136a0) at media_stream_track.cc:47
    frame #14: 0x000000010aaaad0b wrtc.node`Napi::ObjectWrap<node_webrtc::MediaStreamTrack>::FinalizeCallback((null)=0x0000000105d121d0, data=0x00000001059136a0, (null)=0x0000000000000000) at napi-inl.h:3347
    frame #15: 0x00000001000e6ea5 node`(anonymous namespace)::v8impl::Reference::FinalizeCallback(data=0x00007ffeefbfcbc0)::v8impl::Reference> const&) at node_api.cc:446
    frame #16: 0x00000001011a134c node`v8::internal::GlobalHandles::PendingPhantomCallback::Invoke(this=0x00007ffeefbfcca0, isolate=0x0000000106006400) at global-handles.cc:905
    frame #17: 0x00000001011a27ce node`v8::internal::GlobalHandles::DispatchPendingPhantomCallbacks(this=0x000000010590f5b0, synchronous_second_pass=true) at global-handles.cc:870
    frame #18: 0x00000001011a2fa2 node`v8::internal::GlobalHandles::PostGarbageCollectionProcessing(this=0x000000010590f5b0, collector=MARK_COMPACTOR, gc_callback_flags=kGCCallbackFlagForced) at global-handles.cc:930
    frame #19: 0x0000000101216783 node`v8::internal::Heap::PerformGarbageCollection(this=0x0000000106006420, collector=MARK_COMPACTOR, gc_callback_flags=kGCCallbackFlagForced) at heap.cc:1773
    frame #20: 0x00000001012134f7 node`v8::internal::Heap::CollectGarbage(this=0x0000000106006420, space=OLD_SPACE, gc_reason=kTesting, gc_callback_flags=kGCCallbackFlagForced) at heap.cc:1391
    frame #21: 0x0000000101211d09 node`v8::internal::Heap::CollectAllGarbage(this=0x0000000106006420, flags=2, gc_reason=kTesting, gc_callback_flags=kGCCallbackFlagForced) at heap.cc:1156
    frame #22: 0x000000010071245e node`v8::Isolate::RequestGarbageCollectionForTesting(this=0x0000000106006400, type=kFullGarbageCollection) at api.cc:8256
    frame #23: 0x000000010115f083 node`v8::internal::GCExtension::GC(args=0x00007ffeefbfd6a0) at gc-extension.cc:20
    frame #24: 0x00000001008610f1 node`v8::internal::FunctionCallbackArguments::Call(this=0x00007ffeefbfd810, handler=0x000019e50089fd81) at api-arguments-inl.h:94
    frame #25: 0x000000010085ed7e node`v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(isolate=0x0000000106006400, function=Handle<v8::internal::HeapObject> @ 0x00007ffeefbfd920, new_target=Handle<v8::internal::HeapObject> @ 0x00007ffeefbfd918, fun_data=Handle<v8::internal::FunctionTemplateInfo> @ 0x00007ffeefbfd910, receiver=Handle<v8::internal::Object> @ 0x00007ffeefbfd908, args=BuiltinArguments @ 0x00007ffeefbfd940) at builtins-api.cc:109
    frame #26: 0x000000010085d3ea node`v8::internal::Builtin_Impl_HandleApiCall(args=BuiltinArguments @ 0x00007ffeefbfda70, isolate=0x0000000106006400) at builtins-api.cc:139
    frame #27: 0x000000010085cf1d node`v8::internal::Builtin_HandleApiCall(args_length=5, args_object=0x00007ffeefbfdb48, isolate=0x0000000106006400) at builtins-api.cc:127
    frame #28: 0x00002baa73f41c44
    frame #29: 0x00002baa73e20b76
    frame #30: 0x00002baa742056ec
    frame #31: 0x00002baa73ee9657
    frame #32: 0x00002baa73e5973c
    frame #33: 0x00002baa73e05401
    frame #34: 0x000000010115d86d node`v8::internal::GeneratedCode<v8::internal::Object*, v8::internal::Object*, v8::internal::Object*, v8::internal::Object*, int, v8::internal::Object***>::Call(this=0x00007ffeefbfde58, args=0x000019e5141826f1, args=0x000019e5141826f1, args=0x000019e5141826f1, args=0, args=0x0000000000000000) at simulator.h:113
    frame #35: 0x000000010115b296 node`v8::internal::(anonymous namespace)::Invoke(isolate=0x0000000106006400, is_construct=false, target=Handle<v8::internal::Object> @ 0x00007ffeefbfdf70, receiver=Handle<v8::internal::Object> @ 0x00007ffeefbfdf68, argc=0, args=0x0000000000000000, new_target=Handle<v8::internal::Object> @ 0x00007ffeefbfdf60, message_handling=kReport, execution_target=kRunMicrotasks) at execution.cc:155
    frame #36: 0x000000010115aae9 node`v8::internal::(anonymous namespace)::CallInternal(isolate=0x0000000106006400, callable=Handle<v8::internal::Object> @ 0x00007ffeefbfe040, receiver=Handle<v8::internal::Object> @ 0x00007ffeefbfe038, argc=0, argv=0x0000000000000000, message_handling=kReport, target=kRunMicrotasks) at execution.cc:191
    frame #37: 0x000000010115b50f node`v8::internal::Execution::TryCall(isolate=0x0000000106006400, callable=Handle<v8::internal::Object> @ 0x00007ffeefbfe120, receiver=Handle<v8::internal::Object> @ 0x00007ffeefbfe118, argc=0, args=0x0000000000000000, message_handling=kReport, exception_out=0x00007ffeefbfe220, target=kRunMicrotasks) at execution.cc:241
    frame #38: 0x000000010115b781 node`v8::internal::Execution::RunMicrotasks(isolate=0x0000000106006400, message_handling=kReport, exception_out=0x00007ffeefbfe220) at execution.cc:272
    frame #39: 0x000000010144e8a9 node`v8::internal::Isolate::RunMicrotasks(this=0x0000000106006400) at isolate.cc:3925
    frame #40: 0x0000000100714181 node`v8::Isolate::RunMicrotasks(this=0x0000000106006400) at api.cc:8637
    frame #41: 0x0000000100023ae2 node`node::InternalCallbackScope::Close(this=0x00007ffeefbfe5d0) at callback_scope.cc:104
    frame #42: 0x00000001000b98af node`node::InternalMakeCallback(env=0x00007ffeefbfeb80, recv=(val_ = 0x0000000108019620), callback=(val_ = 0x000000010681d1a0), argc=1, argv=0x00007ffeefbfe8c0, asyncContext=(async_id = 45, trigger_async_id = 0)) at node.cc:692
    frame #43: 0x0000000100014e79 node`node::AsyncWrap::MakeCallback(this=0x0000000105d3b3f0, cb=(val_ = 0x000000010681d1a0), argc=1, argv=0x00007ffeefbfe8c0) at async_wrap.cc:669
    frame #44: 0x00000001002c3bdc node`node::(anonymous namespace)::TimerWrap::OnTimeout(handle=0x0000000105d3b440) at timer_wrap.cc:146
    frame #45: 0x0000000101c2b63f node`uv__run_timers(loop=0x0000000103265950) at timer.c:174
    frame #46: 0x0000000101c32c14 node`uv_run(loop=0x0000000103265950, mode=UV_RUN_DEFAULT) at core.c:361
    frame #47: 0x00000001000ce745 node`node::Start(isolate=0x0000000106006400, isolate_data=0x0000000106813800, args=size=2, exec_args=size=1) at node.cc:2921
    frame #48: 0x00000001000c9579 node`node::Start(event_loop=0x0000000103265950, args=size=2, exec_args=size=1) at node.cc:3020
    frame #49: 0x00000001000c8abf node`node::Start(argc=3, argv=0x000000010590e3e0) at node.cc:3071
    frame #50: 0x0000000101eab12e node`main(argc=3, argv=0x00007ffeefbff940) at node_main.cc:124
    frame #51: 0x0000000100001034 node`start + 52

[bnoordhuis]

Anna's explanation sounds plausible. I thought you were still using NAN but I see there's also a templated instance that uses n-api.

Napi::AsyncContext::~AsyncContext() calls napi_async_destroy() and is itself sometimes called from a post-GC hook because your class also inherits from Napi::ObjectWrap<T>, which turns the object into a weak reference (makes it eligible for garbage collection.)

I think the design flaw here is that node::EmitAsyncDestroy() should take a v8::Local<v8::Context>, not a v8::Isolate*.

Just bailing out when there's no active context is probably not a proper fix because it means you lose events. Maybe that's acceptable as a temporary workaround, I don't know.

Having said all that, are you sure v8::Isolate::GetCurrentContext() indeed returns an empty handle? V8 doesn't exit contexts when performing a GC, AFAIK. Maybe a context has been entered that doesn't have a node::Environment attached to it?

[addaleax]

Having said all that, are you sure v8::Isolate::GetCurrentContext() indeed returns an empty handle? V8 doesn't exit contexts when performing a GC, AFAIK. Maybe a context has been entered that doesn't have a node::Environment attached to it?

Fwiw, I’ve double-checked, and yes, during a regular GC run it’s an empty handle.

[markandrus]

Thanks @bnoordhuis and @addaleax,

Anna's explanation sounds plausible. I thought you were still using NAN but I see there's also a templated instance that uses n-api.

Yes, I'm mid-conversion to N-API. After I hit this issue I just continued converting class by class from NAN to N-API thinking the bug could be from my NAN code (which was also using libuv directly), but the bug still manifests in my N-API branch (which I haven't updated yet).

Napi::AsyncContext::~AsyncContext() calls napi_async_destroy() and is itself sometimes called from a post-GC hook because your class also inherits from Napi::ObjectWrap<T>, which turns the object into a weak reference (makes it eligible for garbage collection.)

Thanks for explaining. Just to clarify: this isn't a "disallowed" usage? AsyncContext and ObjectWrap together?

Just bailing out when there's no active context is probably not a proper fix because it means you lose events. Maybe that's acceptable as a temporary workaround, I don't know.

These events are the async_hook events, right? I don't think consumers of my API care about these—I mainly use them to ensure I'm not leaking memory, that destructors actually fire, etc. I'm open to working around this in the shortterm if it means I can convert to N-API and drastically cut down my build matrix.

Fwiw, I’ve double-checked, and yes, during a regular GC run it’s an empty handle.

Thanks for checking @addaleax.

@addaleax I see your PR addressing this issue. I will try it out soon. If it does fix my issue, what is the backport policy? Will your change only be applied to Node releases, or will it land in current non-EOL releases?