Description
Version: v12.14.1 v14.3.0
Platform: Linux somehost 3.10.0-1062.4.1.el7.x86_64 #1 SMP Fri Oct 18 17:15:30 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
Subsystem: async_hooks
What steps will reproduce the bug?
Node crashes with an assertion error whenever the fatal exception handler is called from an async resource' callback, when error domains are in use.
I've reduced the replication scenario down to:
require('domain')
.create().on('error', e => console.error(e))
.run(_ => setImmediate(_ => process._fatalException(new Error('CRASH!!!'))));
Our actual case involved an error thrown inside an async worker's done callback (wrapped inside an error domain of course). I can provide a repo with a minimal async worker replication scenario if you think it's necessary.
How often does it reproduce? Is there a required condition?
Every time the above scenario is met.
What is the expected behavior?
I'd expect it to log the error, then exit.
What do you see instead?
node[6594]: ../src/node_util.cc:216:static void node::util::WeakReference::DecRef(const v8::FunctionCallbackInfo<v8::Value>&): Assertion `(weak_ref->reference_count_) >= (1)' failed.
1: 0xaf5b70 node::Abort() [node]
2: 0xaf5c00 node::Assert(node::AssertionInfo const&) [node]
3: 0xb9753a [node]
4: 0xcc4d45 [node]
5: 0xcc6835 [node]
6: 0xcc6b56 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [node]
7: 0x140d8b9 [node]
Aborted
Additional information
Debug session log
(lldb) target create "node"
Current executable set to 'node' (x86_64).
(lldb) plugin load '/root/tmp/debug/llnode/llnode.so'
(lldb) settings set prompt '(llnode) '
(llnode) b node::util::WeakReference::DecRef
Breakpoint 1: where = node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&), address = 0x0000000000a697b0
(llnode) b node::util::WeakReference::IncRef
Breakpoint 2: where = node`node::util::WeakReference::IncRef(v8::FunctionCallbackInfo<v8::Value> const&), address = 0x0000000000a69570
(llnode) r index.js
Process 9624 launched: '/root/.nvm/versions/node/v12.14.1/bin/node' (x86_64)
init: 1 -> 2 :: dummy_asyncworker_resource{
name: 'my-resource',
[domain]: Domain {
[domain]: null,
_events: [Object: null prototype] {
removeListener: [Function: updateExceptionCapture] {
[length]: 0,
[name]: 'updateExceptionCapture',
[prototype]: updateExceptionCapture { [constructor]: [Circular] }
},
newListener: [Function: updateExceptionCapture] {
[length]: 0,
[name]: 'updateExceptionCapture',
[prototype]: updateExceptionCapture { [constructor]: [Circular] }
},
error: [Function] { [length]: 1, [name]: '' }
},
_eventsCount: 3,
_maxListeners: undefined,
members: [ [length]: 0 ],
[Symbol(kWeak)]: WeakReference {}
}
}
Process 9624 stopped
* thread #1, name = 'node', stop reason = breakpoint 2.1
frame #0: 0x0000000000a69570 node`node::util::WeakReference::IncRef(v8::FunctionCallbackInfo<v8::Value> const&)
node`node::util::WeakReference::IncRef:
-> 0xa69570 <+0>: pushq %rbp
0xa69571 <+1>: movq %rsp, %rbp
0xa69574 <+4>: pushq %rbx
0xa69575 <+5>: subq $0x8, %rsp
(llnode) v8 bt
* thread #1: tid = 9624, 0x0000000000a69570 node`node::util::WeakReference::IncRef(v8::FunctionCallbackInfo<v8::Value> const&), name = 'node', stop reason = breakpoint 2.1
* frame #0: 0x0000000000a69570 node`node::util::WeakReference::IncRef(v8::FunctionCallbackInfo<v8::Value> const&)
frame #1: 0x0000000000ba6fc9 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) + 457
frame #2: 0x0000000000ba8db7 node`v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) + 183
frame #3: node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit at base.tq:3028
frame #4: 0x00000000012f68a4 before(this=0xedc6d91bdc9:<Object: AsyncHook>, <Smi: 2>) at domain.js:1:10 fn=0x00000edc6d91bc29
frame #5: 0x00000000012f68a4 emitHook(this=0x42f4d8c04a9:<undefined>, 0x1ebc61bc3069:<unknown>, <Smi: 2>) at internal/async_hooks.js:1:10 fn=0x00000f51a3527689
frame #6: 0x00000000012f3e9d <internal>
frame #7: 0x00000000012f3c78 <entry>
frame #8: 0x0000000000c7c9d0 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 432
frame #9: 0x0000000000c7ce88 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>*) + 88
frame #10: 0x0000000000b4cf3b node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)
+ 363
frame #11: 0x000000000095459b node`node::AsyncWrap::EmitBefore(node::Environment*, double) + 171
frame #12: 0x000000000094ab10 node`node::InternalCallbackScope::InternalCallbackScope(node::Environment*, v8::Local<v8::Object>, node::async_context const&, node::InternalCallbackScope::ResourceExpectation) + 528
frame #13: 0x000000000094abff node`node::CallbackScope::CallbackScope(v8::Isolate*, v8::Local<v8::Object>, node::async_context)
+ 175
frame #14: 0x000000000094a58c node`node::AsyncResource::CallbackScope::CallbackScope(node::AsyncResource*) + 76
frame #15: 0x00000000009adb38 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 72
frame #16: node`uv__work_done(handle=0x00000000029fd670) at threadpool.c:313
frame #17: node`uv__async_io(loop=0x00000000029fd5c0, w=<unavailable>, events=<unavailable>) at async.c:147
frame #18: node`uv__io_poll(loop=0x00000000029fd5c0, timeout=-1) at linux-core.c:421
frame #19: node`uv_run(loop=0x00000000029fd5c0, mode=UV_RUN_DEFAULT) at core.c:375
frame #20: 0x0000000000a1ce80 node`node::NodeMainInstance::Run() + 928
frame #21: 0x00000000009acb68 node`node::Start(int, char**) + 664
frame #22: libc.so.6`__libc_start_main(main=(node`main), argc=2, argv=0x00007fffffffd778, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffd768) at libc-start.c:266
frame #23: 0x000000000094a115 node`_start + 41
(llnode) c
Process 9624 resuming
be4e: 2
TypeError: Cannot read property 'crash' of undefined
at Object.<anonymous> (/root/dev/other/node-crash-replication/index.js:32:20) {
[stack]: "TypeError: Cannot read property 'crash' of undefined\n" +
' at Object.<anonymous> (/root/dev/other/node-crash-replication/index.js:32:20)',
[message]: "Cannot read property 'crash' of undefined",
[domain]: Domain {
[domain]: null,
_events: [Object: null prototype] {
removeListener: [Function: updateExceptionCapture] {
[length]: 0,
[name]: 'updateExceptionCapture',
[prototype]: updateExceptionCapture { [constructor]: [Circular] }
},
newListener: [Function: updateExceptionCapture] {
[length]: 0,
[name]: 'updateExceptionCapture',
[prototype]: updateExceptionCapture { [constructor]: [Circular] }
},
error: [Function] { [length]: 1, [name]: '' }
},
_eventsCount: 3,
_maxListeners: undefined,
members: [ [length]: 0 ],
[Symbol(kWeak)]: WeakReference {}
},
domainThrown: true
}
init: 2 -> 3 :: ImmediateImmediate {
_idleNext: null,
_idlePrev: null,
_onImmediate: [Function: noop] {
[length]: 0,
[name]: 'noop',
[prototype]: noop { [constructor]: [Circular] }
},
_argv: undefined,
_destroyed: false,
[Symbol(refed)]: false,
[Symbol(asyncId)]: 3,
[Symbol(triggerId)]: 2
}
Process 9624 stopped
* thread #1, name = 'node', stop reason = breakpoint 1.1
frame #0: 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&)
node`node::util::WeakReference::DecRef:
-> 0xa697b0 <+0>: pushq %rbp
0xa697b1 <+1>: movq %rsp, %rbp
0xa697b4 <+4>: pushq %rbx
0xa697b5 <+5>: subq $0x8, %rsp
(llnode) v8 bt
* thread #1: tid = 9624, 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&), name = 'node', stop reason = breakpoint 1.1
* frame #0: 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&)
frame #1: 0x0000000000ba6fc9 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) + 457
frame #2: 0x0000000000ba8db7 node`v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) + 183
frame #3: node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit at base.tq:3028
frame #4: 0x00000000012f68a4 after(this=0xedc6d91bdc9:<Object: AsyncHook>, 0xedc6d9397a1:<Number: 2.000000>) at domain.js:1:10 fn=0x00000edc6d91bc61
frame #5: 0x00000000012f68a4 emitHook(this=0x42f4d8c04a9:<undefined>, 0x1ebc61bc3081:<unknown>, 0xedc6d9397a1:<Number: 2.000000>) at internal/async_hooks.js:1:10 fn=0x00000f51a3527689
frame #6: 0x00000000012f68a4 emitAfterScript(this=0x42f4d8c04a9:<undefined>, 0xedc6d9397a1:<Number: 2.000000>) at internal/async_hooks.js:1:10 fn=0x00000f51a3520c81
frame #7: 0x00000000012f68a4 (anonymous)(this=0x1184f5a00969:<Object: process>, 0xedc6d92e669:<Object: TypeError>, 0x42f4d8c06e1:<false>) at internal/process/execution.js:1:10 fn=0x00000f51a3539219
frame #8: 0x00000000012f3e9d <internal>
frame #9: 0x00000000012f3c78 <entry>
frame #10: 0x0000000000c7c9d0 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 432
frame #11: 0x0000000000c7ce88 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>*) + 88
frame #12: 0x0000000000b4cf3b node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 363
frame #13: 0x00000000009dc270 node`node::errors::TriggerUncaughtException(v8::Isolate*, v8::Local<v8::Value>, v8::Local<v8::Message>, bool) + 336
frame #14: 0x00000000009adbd8 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 232
frame #15: node`uv__work_done(handle=0x00000000029fd670) at threadpool.c:313
frame #16: node`uv__async_io(loop=0x00000000029fd5c0, w=<unavailable>, events=<unavailable>) at async.c:147
frame #17: node`uv__io_poll(loop=0x00000000029fd5c0, timeout=-1) at linux-core.c:421
frame #18: node`uv_run(loop=0x00000000029fd5c0, mode=UV_RUN_DEFAULT) at core.c:375
frame #19: 0x0000000000a1ce80 node`node::NodeMainInstance::Run() + 928
frame #20: 0x00000000009acb68 node`node::Start(int, char**) + 664
frame #21: libc.so.6`__libc_start_main(main=(node`main), argc=2, argv=0x00007fffffffd778, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffd768) at libc-start.c:266
frame #22: 0x000000000094a115 node`_start + 41
(llnode) c
Process 9624 resuming
aftr: 2
Process 9624 stopped
* thread #1, name = 'node', stop reason = breakpoint 1.1
frame #0: 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&)
node`node::util::WeakReference::DecRef:
-> 0xa697b0 <+0>: pushq %rbp
0xa697b1 <+1>: movq %rsp, %rbp
0xa697b4 <+4>: pushq %rbx
0xa697b5 <+5>: subq $0x8, %rsp
(llnode) v8 bt
* thread #1: tid = 9624, 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&), name = 'node', stop reason = breakpoint 1.1
* frame #0: 0x0000000000a697b0 node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&)
frame #1: 0x0000000000ba6fc9 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) + 457
frame #2: 0x0000000000ba8db7 node`v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) + 183
frame #3: node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit at base.tq:3028
frame #4: 0x00000000012f68a4 after(this=0xedc6d91bdc9:<Object: AsyncHook>, <Smi: 2>) at domain.js:1:10 fn=0x00000edc6d91bc61
frame #5: 0x00000000012f68a4 emitHook(this=0x42f4d8c04a9:<undefined>, 0x1ebc61bc3081:<unknown>, <Smi: 2>) at internal/async_hooks.js:1:10 fn=0x00000f51a3527689
frame #6: 0x00000000012f3e9d <internal>
frame #7: 0x00000000012f3c78 <entry>
frame #8: 0x0000000000c7c9d0 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 432
frame #9: 0x0000000000c7ce88 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>*) + 88
frame #10: 0x0000000000b4cf3b node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 363
frame #11: 0x000000000095717b node`node::AsyncWrap::EmitAfter(node::Environment*, double) + 171
frame #12: 0x000000000094a818 node`node::CallbackScope::~CallbackScope() + 632
frame #13: 0x00000000009adbf7 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 263
frame #14: node`uv__work_done(handle=0x00000000029fd670) at threadpool.c:313
frame #15: node`uv__async_io(loop=0x00000000029fd5c0, w=<unavailable>, events=<unavailable>) at async.c:147
frame #16: node`uv__io_poll(loop=0x00000000029fd5c0, timeout=-1) at linux-core.c:421
frame #17: node`uv_run(loop=0x00000000029fd5c0, mode=UV_RUN_DEFAULT) at core.c:375
frame #18: 0x0000000000a1ce80 node`node::NodeMainInstance::Run() + 928
frame #19: 0x00000000009acb68 node`node::Start(int, char**) + 664
frame #20: libc.so.6`__libc_start_main(main=(node`main), argc=2, argv=0x00007fffffffd778, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffd768) at libc-start.c:266
frame #21: 0x000000000094a115 node`_start + (llnode) c
Process 9624 resuming
/root/.nvm/versions/node/v12.14.1/bin/node[9624]: ../src/node_util.cc:201:static void node::util::WeakReference::DecRef(const v8::FunctionCallbackInfo<v8::Value>&): Assertion `(weak_ref->reference_count_) >= (1)' failed.
1: 0x9dab70 node::Abort() [/root/.nvm/versions/node/v12.14.1/bin/node]
2: 0x9dabf7 [/root/.nvm/versions/node/v12.14.1/bin/node]
3: 0xa6985a [/root/.nvm/versions/node/v12.14.1/bin/node]
4: 0xba6fc9 [/root/.nvm/versions/node/v12.14.1/bin/node]
5: 0xba8db7 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [/root/.nvm/versions/node/v12.14.1/bin/node]
6: 0x1376359 [/root/.nvm/versions/node/v12.14.1/bin/node]
Process 9624 stopped
* thread #1, name = 'node', stop reason = signal SIGABRT
frame #0: libc.so.6`__GI_raise(sig=6) at raise.c:55
52 if (__builtin_expect (pid <= 0, 0))
53 pid = (pid & INT_MAX) == 0 ? selftid : -pid;
54
-> 55 return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
56 }
57 libc_hidden_def (raise)
58 weak_alias (raise, gsignal)
<<<<<<<<<<<<<<<<<<< This is the same stack as above
(llnode) v8 bt
* thread #1: tid = 9624, 0x00007ffff6e04337 libc.so.6`__GI_raise(sig=6) at raise.c:55, name = 'node', stop reason = signal SIGABRT
* frame #0: libc.so.6`__GI_raise(sig=6) at raise.c:55
frame #1: libc.so.6`__GI_abort at abort.c:90
frame #2: 0x00000000009dab81 node`node::Abort() + 33
frame #3: 0x00000000009dabf7 node`node::Assert(node::AssertionInfo const&) + 103
frame #4: 0x0000000000a6985a node`node::util::WeakReference::DecRef(v8::FunctionCallbackInfo<v8::Value> const&) + 170
frame #5: 0x0000000000ba6fc9 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) + 457
frame #6: 0x0000000000ba8db7 node`v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) + 183
frame #7: node`Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit at base.tq:3028
frame #8: 0x00000000012f68a4 after(this=0xedc6d91bdc9:<Object: AsyncHook>, <Smi: 2>) at domain.js:1:10 fn=0x00000edc6d91bc61
frame #9: 0x00000000012f68a4 emitHook(this=0x42f4d8c04a9:<undefined>, 0x1ebc61bc3081:<unknown>, <Smi: 2>) at internal/async_hooks.js:1:10 fn=0x00000f51a3527689
frame #10: 0x00000000012f3e9d <internal>
frame #11: 0x00000000012f3c78 <entry>
frame #12: 0x0000000000c7c9d0 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) + 432
frame #13: 0x0000000000c7ce88 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>*) + 88
frame #14: 0x0000000000b4cf3b node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 363
frame #15: 0x000000000095717b node`node::AsyncWrap::EmitAfter(node::Environment*, double) + 171
frame #16: 0x000000000094a818 node`node::CallbackScope::~CallbackScope() + 632
frame #17: 0x00000000009adbf7 node`(anonymous namespace)::uvimpl::Work::AfterThreadPoolWork(int) + 263
frame #18: node`uv__work_done(handle=0x00000000029fd670) at threadpool.c:313
frame #19: node`uv__async_io(loop=0x00000000029fd5c0, w=<unavailable>, events=<unavailable>) at async.c:147
frame #20: node`uv__io_poll(loop=0x00000000029fd5c0, timeout=-1) at linux-core.c:421
frame #21: node`uv_run(loop=0x00000000029fd5c0, mode=UV_RUN_DEFAULT) at core.c:375
frame #22: 0x0000000000a1ce80 node`node::NodeMainInstance::Run() + 928
frame #23: 0x00000000009acb68 node`node::Start(int, char**) + 664
frame #24: libc.so.6`__libc_start_main(main=(node`main), argc=2, argv=0x00007fffffffd778, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffd768) at libc-start.c:266
frame #25: 0x000000000094a115 node`_start + 41
As can be seen from the above debug session log, the hooks are called from the uvimpl::Work::AfterThreadPoolWork
method in src/node_errors.cc
, where:
885 CallbackScope callback_scope(this);
886
887 _env->CallIntoModule([&](napi_env env) {
888 _complete(env, ConvertUVErrorCode(status), _data);
889 }, [](napi_env env, v8::Local<v8::Value> local_err) {
890 // If there was an unhandled exception in the complete callback,
891 // report it as a fatal exception. (There is no JavaScript on the
892 // callstack that can possibly handle it.)
893 v8impl::trigger_fatal_exception(env, local_err);
894 });
- line 885: The
CallbackScope
constructor will trigger the before hook, which will increment the domain weakref count, while it's destructor will call the after hook, which will decrement the ref count, when it goes out of scope (line 894). - line 888: The completion function will call back into js to our function which triggers the uncaught error.
- line 893: The
trigger_fatal_exception
function will callnode::errors::TriggerUncaughtException
which in turn will call into jsprocess._fatalException
.
Now, the js functionprocess._fatalException
will trigger some unhandled exception events and will continue to emit an after event. Note that theCallbackScope
above is not yet destroyed, meaning that it will emit yet another after event when it goes out of scope. The latter leading to our assertion failure.