Node: Node servers crashing on upgrade to v8.x

[d3viant0ne]

• Version: 8.1.4
• Platform: Darwin deviantjs.local 16.7.0 Darwin Kernel Version 16.7.0: Sun Jun 25 17:14:55 PDT 2017; root:xnu-3789.70.16~9/RELEASE_X86_64 x86_64
• Subsystem:

/Users/d3viant0ne/.nvm/versions/node/v8.1.4/bin/node[60823]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
 1: node::Abort() [/Users/d3viant0ne/.nvm/versions/node/v8.1.4/bin/node]
 2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, double, double) [/Users/d3viant0ne/.nvm/versions/node/v8.1.4/bin/node]
 3: node::AsyncWrap::PopAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/d3viant0ne/.nvm/versions/node/v8.1.4/bin/node]
 4: 0x21e98413dd25

Core dump available in s3 bucket

Opening a new issue as requested in #13325

This is happening in all of our restful APIs when trying to run on 8.x ( lots of http ). Core dump attached. Please let me know if there is other useful information I can provide.

[AndreasMadsen]

/cc @nodejs/async_hooks

[refack]

@d3viant0ne fixed version 8.0.14 -> 8.1.14. Assuming that is correct.

[AndreasMadsen]

Assuming that is correct.

That is not released (yet :p), likely it is 8.1.4.

[AndreasMadsen]

Backtrace from core dump:

(llnode) v8 bt
 * thread #1: tid = 0x0000, 0x00007fffc56f7d42 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fffc56f7d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffc57e5457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fffc565d420 libsystem_c.dylib`abort + 129
    frame #3: 0x0000000100a7522d node`node::Abort() + 34
    frame #4: 0x0000000100a740eb node`node::Assert(char const* const (*) [4]) + 251
    frame #5: 0x0000000100a646a8 node`node::AsyncWrap::PushAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) + 296
    frame #6: 0x0000176134e60be5 <exit>
    frame #7: 0x00001761350d0d2b nextTickEmitBefore(this=0x000038c9f4a02241:<undefined>, 0x00003f713adbcee1:<Number: 410.000000>, 0x00003f713adbcef1:<Number: -1.000000>) at internal/process/next_tick.js:117:30 fn=0x00003140bddcacb9
    frame #8: 0x0000176134f38277 _tickCallback(this=0x00001a2f3aa07859:<Object: process>) at internal/process/next_tick.js:133:25 fn=0x00003140bdd88161
    frame #9: 0x0000176134990290 <internal>
    frame #10: 0x0000176134a5646d <entry>
    frame #11: 0x0000000100559e26 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, bool, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Handle<v8::internal::Object>, v8::internal::Execution::MessageHandling) + 742
    frame #12: 0x0000000100559a83 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>*) + 179
    frame #13: 0x00000001001621ef node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
    frame #14: 0x0000000100a668d9 node`node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) + 789
    frame #15: 0x0000000100aca155 node`node::(anonymous namespace)::TimerWrap::OnTimeout(uv_timer_s*) + 127
    frame #16: 0x0000000100be8342 node`uv__run_timers + 38
    frame #17: 0x0000000100bdd3ca node`uv_run + 580
    frame #18: 0x0000000100a829b6 node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 736
    frame #19: 0x0000000100a7dd89 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
    frame #20: 0x0000000100a7d37c node`node::Start(int, char**) + 331
    frame #21: 0x0000000100001634 node`start + 52

From this, it can be seen that the trigger_async_id to emitBefore is -1 and the emitBefore is called as a result of process.nextTick. If I remember correctly this can only happen because of lib/net.js#L187.

@d3viant0ne I think we need some more information to fully understand this. If this is easily reproducible, could you add the following code to the top of the entry script or use node -r debug-script.js my-entry-script.js. That should print a normal stack trace, please show us that.

debug-script.js:

Error.stackTraceLimit = Infinity;
const async_hooks = require('async_hooks');

async_hooks.createHook({
  init(id, type, triggerId, resource) {
    if (triggerId < 0 || id < 0) {
      process._rawDebug('init', {id, type, triggerId});
      throw new Error('bad id');
    }
  }
}).enable();

[refack]

This might be fixed by https://github.com/nodejs/node/pull/14026 or https://github.com/nodejs/node/pull/13839
@d3viant0ne Could you try with the latest nightly

[d3viant0ne]

@refack - I'll give the nightly a try and let you know.

[d3viant0ne]

@refack - Confirmed that's fixed in the nightly. You guys & gals are rockstars :)

I'm not familiar with your release process, will those two fixes find their way into an 8.x release at some point or do I need to wait for 9?

[addaleax]

@d3viant0ne The fixes are both included in the current proposal for 8.2.0 @ https://github.com/nodejs/node/pull/13744. We should have everything in there ready by the end of the week, so just wait until Tuesday or so. :)