How are Ref and Unref supposed to work? by markandrus · Pull Request #869 · nodejs/node-addon-api

markandrus · 2020-12-29T02:59:01Z

I've landed a little test for ObjectWrap, Ref, and Unref in order to try and understand some behavior I'm seeing. Is it expected that failing to call Unref should lead to a "pointer being freed was not allocated" error? In the test I've added, un-commenting the call to unref causes the test to pass. Is it wrong to expect that Node.js should remain running so long as the reference count is non-zero?

% ~/src/node/node_g -v
v15.5.0

% lldb -e ~/src/node/node_g
(lldb) target create "/Users/mark/src/node/node_g"
Current executable set to '/Users/mark/src/node/node_g' (x86_64).
(lldb) run --expose-gc test/objectwrap_ref.js
Process 28088 launched: '/Users/mark/src/node/node_g' (x86_64)
node_g(28088,0x10737fe00) malloc: *** error for object 0x107439860: pointer being freed was not allocated
node_g(28088,0x10737fe00) malloc: *** set a breakpoint in malloc_error_break to debug
Process 28088 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
    frame #0: 0x00007fff202e2462 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fff202e2462 <+10>: jae    0x7fff202e246c            ; <+20>
    0x7fff202e2464 <+12>: movq   %rax, %rdi
    0x7fff202e2467 <+15>: jmp    0x7fff202dc6a1            ; cerror_nocancel
    0x7fff202e246c <+20>: retq   
Target 0: (node_g) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
  * frame #0: 0x00007fff202e2462 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff20310610 libsystem_pthread.dylib`pthread_kill + 263
    frame #2: 0x00007fff20263720 libsystem_c.dylib`abort + 120
    frame #3: 0x00007fff20144430 libsystem_malloc.dylib`malloc_vreport + 548
    frame #4: 0x00007fff201474c8 libsystem_malloc.dylib`malloc_report + 151
    frame #5: 0x000000010010f198 node_g`v8impl::(anonymous namespace)::RefBase::~RefBase(this=0x0000000107439860) at js_native_api_v8.cc:223:22
    frame #6: 0x0000000100109659 node_g`v8impl::(anonymous namespace)::RefBase::Delete(reference=0x0000000107439860)::RefBase*) at js_native_api_v8.cc:248:7
    frame #7: 0x000000010010f02e node_g`v8impl::(anonymous namespace)::RefBase::Finalize(this=0x0000000107439860, is_env_teardown=true) at js_native_api_v8.cc:281:7
    frame #8: 0x00000001001409c1 node_g`v8impl::RefTracker::FinalizeAll(list=0x0000000107428258) at js_native_api_v8.h:43:20
    frame #9: 0x0000000100140925 node_g`napi_env__::~napi_env__(this=0x0000000107428220) at js_native_api_v8.h:66:5
    frame #10: 0x0000000100140b48 node_g`node_napi_env__::~node_napi_env__(this=0x0000000107428220) at node_api.cc:17:8
    frame #11: 0x00000001001405f5 node_g`node_napi_env__::~node_napi_env__(this=0x0000000107428220) at node_api.cc:17:8
    frame #12: 0x000000010014061c node_g`node_napi_env__::~node_napi_env__(this=0x0000000107428220) at node_api.cc:17:8
    frame #13: 0x000000010010f311 node_g`napi_env__::Unref(this=0x0000000107428220) at js_native_api_v8.h:77:43
    frame #14: 0x000000010014379c node_g`v8impl::(anonymous namespace)::NewEnv(this=0x0000000107428220, arg=0x0000000107428220)::'lambda'(void*)::operator()(void*) const at node_api.cc:103:37
    frame #15: 0x0000000100143775 node_g`v8impl::(anonymous namespace)::NewEnv(arg=0x0000000107428220)::'lambda'(void*)::__invoke(void*) at node_api.cc:102:7
    frame #16: 0x00000001000b0343 node_g`node::Environment::RunCleanup(this=0x000000010803c200) at env.cc:669:7
    frame #17: 0x000000010000ffaa node_g`node::FreeEnvironment(env=0x000000010803c200) at environment.cc:387:10
    frame #18: 0x000000010000d079 node_g`node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))>::operator(this=0x00007ffeefbff5e0, pointer=0x000000010803c200)(node::Environment*) const at util.h:636:39
    frame #19: 0x000000010024eadf node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::reset(this=0x00007ffeefbff5e0, __p=0x0000000000000000) at memory:2623:7
    frame #20: 0x0000000100250ac9 node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::~unique_ptr(this=0x00007ffeefbff5e0) at memory:2577:19
    frame #21: 0x000000010024e9d5 node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::~unique_ptr(this=0x00007ffeefbff5e0) at memory:2577:17
    frame #22: 0x000000010024e2e0 node_g`node::NodeMainInstance::Run(this=0x00007ffeefbff670, env_info=0x000000010491bb38) at node_main_instance.cc:168:1
    frame #23: 0x000000010013017a node_g`node::Start(argc=3, argv=0x00007ffeefbff828) at node.cc:1123:38
    frame #24: 0x0000000101cf015e node_g`main(argc=3, argv=0x00007ffeefbff828) at node_main.cc:127:10
    frame #25: 0x00007fff2032b621 libdyld.dylib`start + 1
    frame #26: 0x00007fff2032b621 libdyld.dylib`start + 1

mhdawson · 2021-01-04T22:06:03Z

Is it wrong to expect that Node.js should remain running so long as the reference count is non-zero?

There reference count on an object being greater that 0 does not mean that Node.js will keep running, only that the object will not be collected by the GC.

it expected that failing to call Unref should lead to a "pointer being freed was not allocated" error?

Calling the Unref significantly changes where the object will be freed so I think that is likely the case that where you do the Unref the pointer that is being freed is still live, while if the object is freed later (during shutdown) the pointer is no longer live.

What version of Node.js are you using as :RefBase::~RefBase(this=0x0000000107439860) at js_native_api_v8.cc:223:22 does not seem to line up with master.

markandrus · 2021-01-04T23:43:06Z

@mhdawson thanks for taking a look!

There reference count on an object being greater that 0 does not mean that Node.js will keep running, only that the object will not be collected by the GC.

OK, thanks. And so Node may still destroy ObjectWrap instances with non-zero reference counts — it just won't do so via GC? Instead, it may happen at when the process is exiting? Or when the addon is being torn down?

What version of Node.js are you using as :RefBase::~RefBase(this=0x0000000107439860) at js_native_api_v8.cc:223:22 does not seem to line up with master.

I built from source at f978628b80:

% cd ~/src/node
% git branch -v               
* (HEAD detached at v15.5.0) f978628b80 2020-12-22, Version 15.5.0 (Current)
% ./node_g -v
v15.5.0

Sometimes I get different output from lldb. This output actually points to code in RefBase::Delete:

% lldb -e ~/src/node/node_g
(lldb) target create "/Users/mark/src/node/node_g"
Current executable set to '/Users/mark/src/node/node_g' (x86_64).
(lldb) run --expose-gc test/objectwrap_ref.js
Process 1754 launched: '/Users/mark/src/node/node_g' (x86_64)
Process 1754 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000100109656 node_g`v8impl::(anonymous namespace)::RefBase::Delete(reference=0x00000001074201d0)::RefBase*) at js_native_api_v8.cc:248:7
   245 	    if ((reference->RefCount() != 0) ||
   246 	        (reference->_delete_self) ||
   247 	        (reference->_finalize_ran)) {
-> 248 	      delete reference;
   249 	    } else {
   250 	      // defer until finalizer runs as
   251 	      // it may alread be queued
Target 0: (node_g) stopped.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x0000000100109656 node_g`v8impl::(anonymous namespace)::RefBase::Delete(reference=0x00000001074201d0)::RefBase*) at js_native_api_v8.cc:248:7
    frame #1: 0x000000010010f02e node_g`v8impl::(anonymous namespace)::RefBase::Finalize(this=0x00000001074201d0, is_env_teardown=true) at js_native_api_v8.cc:281:7
    frame #2: 0x00000001001409c1 node_g`v8impl::RefTracker::FinalizeAll(list=0x0000000107406518) at js_native_api_v8.h:43:20
    frame #3: 0x0000000100140925 node_g`napi_env__::~napi_env__(this=0x00000001074064e0) at js_native_api_v8.h:66:5
    frame #4: 0x0000000100140b48 node_g`node_napi_env__::~node_napi_env__(this=0x00000001074064e0) at node_api.cc:17:8
    frame #5: 0x00000001001405f5 node_g`node_napi_env__::~node_napi_env__(this=0x00000001074064e0) at node_api.cc:17:8
    frame #6: 0x000000010014061c node_g`node_napi_env__::~node_napi_env__(this=0x00000001074064e0) at node_api.cc:17:8
    frame #7: 0x000000010010f311 node_g`napi_env__::Unref(this=0x00000001074064e0) at js_native_api_v8.h:77:43
    frame #8: 0x000000010014379c node_g`v8impl::(anonymous namespace)::NewEnv(this=0x00000001074064e0, arg=0x00000001074064e0)::'lambda'(void*)::operator()(void*) const at node_api.cc:103:37
    frame #9: 0x0000000100143775 node_g`v8impl::(anonymous namespace)::NewEnv(arg=0x00000001074064e0)::'lambda'(void*)::__invoke(void*) at node_api.cc:102:7
    frame #10: 0x00000001000b0343 node_g`node::Environment::RunCleanup(this=0x0000000107812400) at env.cc:669:7
    frame #11: 0x000000010000ffaa node_g`node::FreeEnvironment(env=0x0000000107812400) at environment.cc:387:10
    frame #12: 0x000000010000d079 node_g`node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))>::operator(this=0x00007ffeefbff5f0, pointer=0x0000000107812400)(node::Environment*) const at util.h:636:39
    frame #13: 0x000000010024eadf node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::reset(this=0x00007ffeefbff5f0, __p=0x0000000000000000) at memory:2623:7
    frame #14: 0x0000000100250ac9 node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::~unique_ptr(this=0x00007ffeefbff5f0) at memory:2577:19
    frame #15: 0x000000010024e9d5 node_g`std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::~unique_ptr(this=0x00007ffeefbff5f0) at memory:2577:17
    frame #16: 0x000000010024e2e0 node_g`node::NodeMainInstance::Run(this=0x00007ffeefbff680, env_info=0x000000010491bb38) at node_main_instance.cc:168:1
    frame #17: 0x000000010013017a node_g`node::Start(argc=3, argv=0x00007ffeefbff838) at node.cc:1123:38
    frame #18: 0x0000000101cf015e node_g`main(argc=3, argv=0x00007ffeefbff838) at node_main.cc:127:10
    frame #19: 0x00007fff2032b621 libdyld.dylib`start + 1
    frame #20: 0x00007fff2032b621 libdyld.dylib`start + 1

mhdawson · 2021-01-05T16:12:04Z

Looking at the code I think what is going on is that although ObjectWrap happens to have the Ref() and Unref() methods due to the hierarchy, calling them has the potential to mess up the ObjectWrap.

An ObjectWrap maintains the liveness of a JavaScript Object and the C level structure associated with it so that they have the same lifetime and are destroyed in the correct sequence. Calling Ref or Unref will mess that up such that the C level structure and JavaScript Object no longer share the same lifespan/liveness a which can easily results in crashes.

In terms of understanding how Refs/Unrefs work I suggest you create a separate Ref versus using the ObjectWrap.

mhdawson · 2021-03-10T23:13:27Z

@markandrus I think we may have resolved this. Is it ok to close?

mhdawson · 2021-03-22T20:43:18Z

Going to close, please let us know if that was not the right thing to do.

markandrus · 2021-03-24T19:34:06Z

Sorry for the delay, @mhdawson -- yes, thank you for closing.

markandrus mentioned this pull request Dec 29, 2020

Cannot Ref and throw exception in ObjectWrap constructor #868

Closed

markandrus force-pushed the objectwrap-ref-and-finalize branch from ecb30fd to 0981b54 Compare December 29, 2020 03:09

Add ObjectWrapRef test

af31099

markandrus force-pushed the objectwrap-ref-and-finalize branch from 0981b54 to af31099 Compare December 29, 2020 03:11

markandrus mentioned this pull request Jan 4, 2021

Followup on #661 node-webrtc/node-webrtc#672

Open

16 of 17 tasks

Base automatically changed from master to main January 26, 2021 22:43

mhdawson closed this Mar 22, 2021

Matt-Esch mentioned this pull request Apr 19, 2022

Segfault on shutdown with ObjectWrap #1153

Closed

Navigation Menu

Repository navigation

How are Ref and Unref supposed to work? - #869

How are Ref and Unref supposed to work?#869
markandrus wants to merge 1 commit into
nodejs:mainfrom
markandrus:objectwrap-ref-and-finalize

markandrus commented Dec 29, 2020

Uh oh!

mhdawson commented Jan 4, 2021

Uh oh!

markandrus commented Jan 4, 2021 •

edited

Loading

Uh oh!

mhdawson commented Jan 5, 2021

Uh oh!

mhdawson commented Mar 10, 2021

Uh oh!

mhdawson commented Mar 22, 2021

Uh oh!

markandrus commented Mar 24, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Conversation

markandrus commented Dec 29, 2020

Uh oh!

mhdawson commented Jan 4, 2021

Uh oh!

markandrus commented Jan 4, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mhdawson commented Jan 5, 2021

Uh oh!

mhdawson commented Mar 10, 2021

Uh oh!

mhdawson commented Mar 22, 2021

Uh oh!

markandrus commented Mar 24, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

markandrus commented Jan 4, 2021 •

edited

Loading