Intermittent failure in ThreadSafe function #906

Activity

1. mhdawson commented on Feb 12, 2021

   

   mhdawson

   on Feb 12, 2021

   Last edited by mhdawson

   MemberAuthor

   More actions

   Also seeing occasional failure like this one: https://ci.nodejs.org/job/node-test-node-addon-api-new/nodes=ubuntu1604-64/3564/console

   Running test 'threadsafe_function/threadsafe_function'
   Running test 'threadsafe_function/threadsafe_function_ctx'
   Running test 'threadsafe_function/threadsafe_function_existing_tsfn'
   Running test 'threadsafe_function/threadsafe_function_ptr'
   Running test 'threadsafe_function/threadsafe_function_sum'
   Running test 'threadsafe_function/threadsafe_function_unref'
   Running test 'typed_threadsafe_function/typed_threadsafe_function'
   Running test 'typed_threadsafe_function/typed_threadsafe_function_ctx'
   Running test 'typed_threadsafe_function/typed_threadsafe_function_existing_tsfn'
   Running test 'typed_threadsafe_function/typed_threadsafe_function_ptr'
   Running test 'typed_threadsafe_function/typed_threadsafe_function_sum'
   Running test 'typed_threadsafe_function/typed_threadsafe_function_unref'
   Running test 'typedarray-bigint'
   Running test 'typedarray'
   Running test 'version_management'
   
   All tests passed!
   Tests aborted with SIGSEGV
   npm ERR! code 1
   npm ERR! path /home/iojs/build/workspace/node-test-node-addon-api-new/nodes/ubuntu1604-64/node-addon-api
   npm ERR! command failed
   npm ERR! command sh -c node test
   
   npm ERR! A complete log of this run can be found in:
   npm ERR!     /home/iojs/build/workspace/node-test-node-addon-api-new/nodes/ubuntu1604-64/npm-cache/_logs/2021-02-06T09_34_12_368Z-debug.log
   Build step 'Conditional steps (multiple)' marked build as failure
   Sending e-mails to: michael_dawson@ca.ibm.com gabriel.schulhof@intel.com Arunesh.Chandra@microsoft.com
   Collecting metadata...
   Metadata collection done.
   Notifying upstream projects of job completion
   Finished: FAILURE
2. gabrielschulhof commented on Feb 16, 2021

   

   gabrielschulhof

   on Feb 16, 2021

   Contributor

   More actions

   @mhdawson this looks like it's against Node.js nightly. Might it be a regression in core?
3. gabrielschulhof commented on Feb 16, 2021

   

   gabrielschulhof

   on Feb 16, 2021

   Contributor

   More actions

   The stack doesn't seem to contain any of our frames – unless I'm glossing over some.
4. gabrielschulhof commented on Feb 17, 2021

   

   gabrielschulhof

   on Feb 17, 2021

   Contributor

   More actions

   I built against nodejs/node@1c6484b and got

   Running test 'threadsafe_function/threadsafe_function'
   /home/nix/node/node/out/Release/node[3813]: ../src/api/callback.cc:121:void node::InternalCallbackScope::Close(): Assertion `(env_->execution_async_id()) == (0)' failed.
    1: 0xabc3c0 node::Abort() [/home/nix/node/node/out/Release/node]
    2: 0xabc43e  [/home/nix/node/node/out/Release/node]
    3: 0x9fcfe8 node::InternalCallbackScope::Close() [/home/nix/node/node/out/Release/node]
    4: 0x9fd3a3 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/home/nix/node/node/out/Release/node]
    5: 0x9fd52c node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/home/nix/node/node/out/Release/node]
    6: 0xa3dd13 node::Environment::CheckImmediate(uv_check_s*) [/home/nix/node/node/out/Release/node]
    7: 0x155f1b9  [/home/nix/node/node/out/Release/node]
    8: 0x15578b4 uv_run [/home/nix/node/node/out/Release/node]
    9: 0x9fe64e node::SpinEventLoop(node::Environment*) [/home/nix/node/node/out/Release/node]
   10: 0xb04537 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/home/nix/node/node/out/Release/node]
   11: 0xa7fc50 node::Start(int, char**) [/home/nix/node/node/out/Release/node]
   12: 0x7fea27c82f43 __libc_start_main [/lib64/libc.so.6]
   13: 0x9faaee _start [/home/nix/node/node/out/Release/node]
   Tests aborted with SIGABRT
   
5. gabrielschulhof commented on Feb 18, 2021

   

   gabrielschulhof

   on Feb 18, 2021

   Contributor

   More actions

   Hmmm ... I can't reproduce that crash.
6. gabrielschulhof commented on Feb 18, 2021

   

   gabrielschulhof

   on Feb 18, 2021

   Contributor

   More actions

   Trying to reproduce inside an Ubuntu 16.04 container.
7. mhdawson commented on Mar 22, 2021

   

   mhdawson

   on Mar 22, 2021

   MemberAuthor

   More actions

   The crash on shutdown with master ow seems to recreate consistently:

   All tests passed!
   
   Thread 1 "node" received signal SIGSEGV, Segmentation fault.
   0x0000000000e7acb0 in v8::internal::GlobalHandles::ClearWeakness(unsigned long*) ()
   Missing separate debuginfos, use: yum debuginfo-install libgcc-8.3.1-5.1.el8.x86_64 libstdc++-8.3.1-5.1.el8.x86_64
   (gdb) 
   

   @gabrielschulhof I'm wondering if that might be related to the change from nodejs/node#37616. Any chance you still have the environment you had for that PR to compare before/after the change?
8. mhdawson commented on Mar 22, 2021

   

   mhdawson

   on Mar 22, 2021

   MemberAuthor

   More actions

   Cutting down the test case this is the one that is failing:

   Starting program: /home/midawson/node/node-v16.0.0-nightly202103215318e53fd8-linux-x64/bin/node --expose-gc --no-concurrent-array-buffer-sweeping /home/midawson/newpull/land/node-addon-api/test/objectreference.js
   Missing separate debuginfos, use: yum debuginfo-install glibc-2.28-127.el8.x86_64
   warning: Loadable section ".note.gnu.property" outside of ELF segments
   warning: Loadable section ".note.gnu.property" outside of ELF segments
   [Thread debugging using libthread_db enabled]
   Using host libthread_db library "/lib64/libthread_db.so.1".
   [New Thread 0x7ffff6cbd700 (LWP 334846)]
   [New Thread 0x7ffff64bc700 (LWP 334847)]
   [New Thread 0x7ffff5cbb700 (LWP 334848)]
   [New Thread 0x7ffff54ba700 (LWP 334849)]
   [New Thread 0x7ffff4cb9700 (LWP 334850)]
   [New Thread 0x7ffff7ff6700 (LWP 334851)]
   
   Thread 1 "node" received signal SIGSEGV, Segmentation fault.
   0x0000000000e7acb0 in v8::internal::GlobalHandles::ClearWeakness(unsigned long*) ()
   Missing separate debuginfos, use: yum debuginfo-install libgcc-8.3.1-5.1.el8.x86_64 libstdc++-8.3.1-5.1.el8.x86_64
   (gdb) 
9. mhdawson commented on Mar 22, 2021

   

   mhdawson

   on Mar 22, 2021

   MemberAuthor

   More actions

   Cut down test case to these 2 and it still crashes:

     () => {
         binding.objectreference.setObjects("hello", "world", "javascript");
         const test = binding.objectreference.getFromValue();
         const test2 = binding.objectreference.getFromValue("hello");
   
         assert.deepEqual({ hello: "world" }, test);
         assert.deepEqual({ hello: "world" }, test2);
         assert.deepEqual(test, test2);
       },
       () => {
         binding.objectreference.setObjects(1, "hello world");
         const test = binding.objectreference.getFromValue();
         const test2 = binding.objectreference.getFromGetter(1);
   
         assert.deepEqual({ 1: "hello world"}, test);
         assert.equal("hello world", test2);
         assert.equal(test[1], test2);
       },
10. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    But not with just one of the 2
11. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    Just these 2 also seems to recreate

    () => {
          binding.objectreference.setObjects(1, "hello world");
          const test = binding.objectreference.getFromValue();
          const test2 = binding.objectreference.getFromGetter(1);
    
          assert.deepEqual({ 1: "hello world"}, test);
          assert.equal("hello world", test2);
          assert.equal(test[1], test2);
        },
    
        () => {
          binding.objectreference.setObjects(0, "hello");
          binding.objectreference.setObjects(1, "world");
          const test = binding.objectreference.getFromValue();
          const test2 = binding.objectreference.getFromGetter(0);
          const test3 = binding.objectreference.getFromGetter(1);
    
          assert.deepEqual({ 1: "world"}, test);
          assert.equal(undefined, test2);
          assert.equal("world", test3);
        },
    
12. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    May require 2 tests so that a gc is forced after one of the tests complete ?
13. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    Cutting down the tests to just:

    // info[0] is the key, which can be either a string or a number.
    // info[1] is the value.
    // info[2] is a flag that differentiates whether the key is a
    // C string or a JavaScript string.
    void SetObjects(const CallbackInfo& info) {
      Env env = info.Env();
      HandleScope scope(env);
    
     weak = Weak(Object::New(env));
     weak.SuppressDestruct();
    
     /* persistent = Persistent(Object::New(env));
      persistent.SuppressDestruct();
    
      reference = Reference<Object>::New(Object::New(env), 2);
      reference.SuppressDestruct();
      */
    
      if (info[0].IsString()) {
        if (info[2].As<String>() == String::New(env, "javascript")) {
    //      weak.Set(info[0].As<String>(), info[1]);
    //      persistent.Set(info[0].As<String>(), info[1]);
    //      reference.Set(info[0].As<String>(), info[1]);
        } else {
          weak.Set(info[0].As<String>().Utf8Value(), info[1]);
          persistent.Set(info[0].As<String>().Utf8Value(), info[1]);
          reference.Set(info[0].As<String>().Utf8Value(), info[1]);
        }
      } else if (info[0].IsNumber()) {
        weak.Set(info[0].As<Number>(), info[1]);
        persistent.Set(info[0].As<Number>(), info[1]);
        reference.Set(info[0].As<Number>(), info[1]);
      }
    }

        () => {
          binding.objectreference.setObjects("hello", "world", "javascript");
     //     const test = binding.objectreference.getFromValue();
     //     const test2 = binding.objectreference.getFromValue("hello");
    
       //   assert.deepEqual({ hello: "world" }, test);
    //      assert.deepEqual({ hello: "world" }, test2);
      //    assert.deepEqual(test, test2);
        },
        () => {
    //      binding.objectreference.setObjects(1, "hello world");
    //      const test = binding.objectreference.getFromValue();
    //      const test2 = binding.objectreference.getFromGetter(1);
    
    //      assert.deepEqual({ 1: "hello world"}, test);
    //      assert.equal("hello world", test2);
    //      assert.equal(test[1], test2);
        },

    still recreates

    So it seems like just creating a Weak causes it? The strange thing is that I would have thought the C node-api tests would have caught an issue like that.
14. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    I've got to think its related to nodejs/node#37616, give the output of the crash being:Thread 1 "node" received signal SIGSEGV, Segmentation fault.
    0x0000000000e7acb0 in v8::internal::GlobalHandles::ClearWeakness(unsigned long*) ()
15. mhdawson commented on Mar 22, 2021

    

    mhdawson

    on Mar 22, 2021

    MemberAuthor

    More actions

    I'm done today and booked for most of tomorrow. @gabrielschulhof I also changed nodejs/node#37802 (review) to "requested changes" so that we don't land until we figure this out.
16. 68 remaining items

    Load more

17. mhdawson commented on May 4, 2021

    

    mhdawson

    on May 4, 2021

    MemberAuthor

    More actions

    Ok so another 4604 runs with the debug version of Node.js over a few days and no recreate of the 1 byte invalid read. At this point I'm going to focus on getting nodejs/node#38492 into a shape where it can land.

    We should also start working on getting the other PRs from main backported to master. Those include:

    • nodejs/node@4afcd55
    • nodejs/node@fc20e83
    • nodejs/node@52f9aaf
    • nodejs/node@03806a0
18. mhdawson

    added a commit that references this issue on May 20, 2021

    node-api: fix shutdown crashes

    ...

    c32c5f0
19. targos

    added a commit that references this issue on May 30, 2021

    node-api: fix shutdown crashes

    ...

    5ed4b9d
20. danielleadams

    added a commit that references this issue on May 31, 2021

    node-api: fix shutdown crashes

    ...

    496f7ea
21. targos

    added 3 commits that reference this issue on Jun 5, 2021

    node-api: fix shutdown crashes

    ...

    e60acd7

    node-api: fix shutdown crashes

    ...

    8ccd867

    node-api: fix shutdown crashes

    ...

    5995221
22. github-actions commented on Aug 3, 2021

    

    github-actionsBot

    on Aug 3, 2021

    Contributor

    More actions

    This issue is stale because it has been open many days with no activity. It will be closed soon unless the stale label is removed or a comment is made.
23. github-actions

    added

    stale

    on Aug 3, 2021
24. mhdawson commented on Aug 3, 2021

    

    mhdawson

    on Aug 3, 2021

    MemberAuthor

    More actions

    Should have closed this issue as the PR to resolve was landed.
25. mhdawson

    closed this as completedon Aug 3, 2021
26. legendecas

    added 2 commits that reference this issue on Mar 29, 2022

    node-api: fix crash in finalization

    ...

    affb8b2

    node-api: fix shutdown crashes

    ...

    3939bba
27. richardlau

    added 2 commits that reference this issue on Mar 30, 2022

    node-api: fix crash in finalization

    ...

    2aa9ca1

    node-api: fix shutdown crashes

    ...

    a7224c9