8.2.0 crashes test

[crespowang]

• Version: 8.2.0
• Platform: macOS 10.12.5 (16F73) Kernel Version: Darwin 16.6.0
• Subsystem:

After upgrading node to v8.2.0 from v7, some of my tests are failing

/usr/local/Cellar/node/8.2.0/bin/node[11673]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
 1: node::Abort() [/usr/local/Cellar/node/8.2.0/bin/node]
 2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, node::async_context) [/usr/local/Cellar/node/8.2.0/bin/node]
 3: node::AsyncWrap::PopAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/Cellar/node/8.2.0/bin/node]
 4: 0xf8bfaa97725
 5: 0xf8bfaeef65c

I see the discussion here #13325 and #13548, not sure if they are related.

[AndreasMadsen]

Fascinating, we rolled out a lot of fixes for this issue in 8.2.0. Did you get a core dump that you can share with us?

If you don't like to share it, could you run the following and show us the output:

npm install -g llnode
llnode /path/to/bin/node -c /path/to/coredump
v8 bt

I hope I got that correct, see https://github.com/nodejs/llnode for more info. Also, it assumes that you have xCode installed.

[AndreasMadsen]

/cc @nodejs/async_hooks

[crespowang]

I have two files under /cores

* thread #1: tid = 0x0000, 0x00007fffb72b267e libsystem_kernel.dylib`__kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fffb72b267e libsystem_kernel.dylib`__kill + 10
    frame #1: 0x0000000100be603d node`uv_kill + 9
    frame #2: 0x0000000100a7bde7 node`node::Kill(v8::FunctionCallbackInfo<v8::Value> const&) + 184
    frame #3: 0x000000010017b0c2 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 466
    frame #4: 0x00000001001e6eef 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) + 911
    frame #5: 0x00000001001e6449 node`v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 281
    frame #6: 0x00002e97947840bd <exit>
    frame #7: 0x00002e9794906a0c process.kill(this=0x0000267fe3403b29:<Object: process>, <Smi: 1079>, 0x000038e29ea4a279:<String: "SIGABRT">) at internal/process.js:161:26 fn=0x000026b150155d11
    frame #8: 0x00002e9794906675 (anonymous)(this=0x0000267fe3403b29:<Object: process>) at /Users/crespowang/Projects/inquisitive-app/server/node_modules/mocha/bin/mocha:70:31 fn=0x000038e29ea4a381
    frame #9: 0x00002e9794786bbb <adaptor>
    frame #10: 0x00002e9794906360 emitOne(this=0x000032afe3082241:<undefined>, 0x000038e29ea4a381:<function: (anonymous) at /Users/crespowang/Projects/inquisitive-app/server/node_modules/mocha/bin/mocha:70:31>, 0x000032afe30822c1:<true>, 0x0000267fe3403b29:<Object: process>, <Smi: 0>) at events.js:113:17 fn=0x000027097d088ac9
    frame #11: 0x00002e97948c6fd4 emit(this=0x0000267fe3403b29:<Object: process>, 0x000032afe3098a71:<String: "exit">) at events.js:155:44 fn=0x000026b15010d821
    frame #12: 0x00002e9794786bbb <adaptor>
    frame #13: 0x00002e9794790290 <internal>
    frame #14: 0x00002e979485646d <entry>
    frame #15: 0x0000000100559626 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 #16: 0x0000000100559283 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 #17: 0x00000001001619ef node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
    frame #18: 0x0000000100a756e3 node`node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 328
    frame #19: 0x0000000100a75cba node`node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 108
    frame #20: 0x0000000100a7eb05 node`node::EmitExit(node::Environment*) + 188
    frame #21: 0x0000000100a84894 node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 856
    frame #22: 0x0000000100a7f7c1 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
    frame #23: 0x0000000100a7edb5 node`node::Start(int, char**) + 331
    frame #24: 0x0000000100000e34 node`start + 52

and

* thread #1: tid = 0x0000, 0x00007fffb72b2d42 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fffb72b2d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffb73a0457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fffb7218420 libsystem_c.dylib`abort + 129
    frame #3: 0x0000000100a76ca5 node`node::Abort() + 34
    frame #4: 0x0000000100a75b63 node`node::Assert(char const* const (*) [4]) + 251
    frame #5: 0x0000000100a640e2 node`node::AsyncWrap::PushAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) + 296
    frame #6: 0x000015f9639eda85 <exit>
    frame #7: 0x000015f963cf401c emitBeforeScript(this=0x0000185274c02241:<undefined>, 0x00000838e7a59ec1:<Number: 3078.000000>, 0x0000185274c02241:<undefined>) at async_hooks.js:364:26 fn=0x00003955864ff5a1
    frame #8: 0x000015f963cbd1c3 _tickDomainCallback(this=0x0000395586483b29:<Object: process>) at internal/process/next_tick.js:193:31 fn=0x000025bc00342fb1
    frame #9: 0x000015f963310290 <internal>
    frame #10: 0x000015f9633d646d <entry>
    frame #11: 0x0000000100559626 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: 0x0000000100559283 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: 0x00000001001619ef node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
    frame #14: 0x0000000100a759eb node`node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 1104
    frame #15: 0x0000000100a75cba node`node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 108
    frame #16: 0x0000000100a7ee7a node`node::CheckImmediate(uv_check_s*) + 80
    frame #17: 0x0000000100be4b43 node`uv__run_check + 167
    frame #18: 0x0000000100bdfaef node`uv_run + 329
    frame #19: 0x0000000100a8481c node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 736
    frame #20: 0x0000000100a7f7c1 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
    frame #21: 0x0000000100a7edb5 node`node::Start(int, char**) + 331
    frame #22: 0x0000000100000e34 node`start + 52

[AndreasMadsen]

Thanks, that is a huge help. If the issue is easily reproducible, could you add the following code such it runs before anything else? That should output a stack trace that I would like to see.

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

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

For @nodejs/async_hooks: This is fascinating, it appears that the triggerAsyncId is undefined when calling the internal process.nextTick. I don't know why that would happen.

[mcollina]

Confirmed, same here:

/Users/matteo/.nvm/versions/node/v8.2.0/bin/node[63926]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
 1: node::Abort() [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, node::async_context) [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 3: node::AsyncWrap::PopAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 4: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 5: 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) [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 6: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/matteo/.nvm/versions/node/v8.2.0/bin/node]
 7: 0x25cdb2f840bd
 8: 0x25cdb3252a8e
Abort trap: 6

The error comes from https://www.npmjs.com/package/shot, just running npm test can help reproduce that. That library uses some internals.

[mcollina]

@AndreasMadsen this is the stacktrace you are looking for:

async_hooks.js:326
    throw new RangeError('triggerAsyncId must be an unsigned integer');
    ^

RangeError: triggerAsyncId must be an unsigned integer
    at emitInitScript (async_hooks.js:326:11)
    at internalNextTick (internal/process/next_tick.js:305:7)
    at Response._writeRaw (_http_outgoing.js:280:9)
    at Response._send (_http_outgoing.js:256:15)
    at Response.end (_http_outgoing.js:780:16)
    at Response.end (/Users/matteo/Repositories/fastify/node_modules/shot/lib/response.js:64:15)
    at Immediate.wrapReplyEnd [as _onImmediate] (/Users/matteo/Repositories/fastify/lib/reply.js:146:13)
    at runCallback (timers.js:785:20)
    at tryOnImmediate (timers.js:743:5)
    at processImmediate [as _immediateCallback] (timers.js:714:5)

[AndreasMadsen]

@mcollina there are so many different causes for this error, it is rarely the same issue. Could you open a new issue and also show the backtrace for the coredump.

@crespowang I would still like to see the stack trace.

For @nodejs/async_hooks: I'm suspecting the 0fd4c73 fix is showing some issues that were previously hidden.

[akanass]

@AndreasMadsen same problem for me

/usr/local/Cellar/node/8.2.0/bin/node[68190]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
 1: node::Abort() [/usr/local/Cellar/node/8.2.0/bin/node]
 2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, node::async_context) [/usr/local/Cellar/node/8.2.0/bin/node]
 3: node::AsyncWrap::PushAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/Cellar/node/8.2.0/bin/node]
 4: 0x3720c4438525

Node installed with Homebrew today.