Skip to content

8.2.0 crashes test #14381

Closed
Closed
8.2.0 crashes test#14381
Labels
async_hooksIssues and PRs related to the async hooks subsystem.

Description

@crespowang
crespowang
opened on Jul 20, 2017
  • 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.

Activity

  1. AndreasMadsen commented on Jul 20, 2017

    @AndreasMadsen
    AndreasMadsen
    on Jul 20, 2017
    Member

    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.

  2. AndreasMadsen
    added
    async_hooksIssues and PRs related to the async hooks subsystem.
    on Jul 20, 2017

  3. AndreasMadsen commented on Jul 20, 2017

    @AndreasMadsen
    AndreasMadsen
    on Jul 20, 2017
    Member

    /cc @nodejs/async_hooks

  4. mscdex
    added
    v8.x
    async_wrap
    on Jul 20, 2017

  5. crespowang commented on Jul 20, 2017

    @crespowang
    crespowang
    on Jul 20, 2017
    Author

    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

  6. AndreasMadsen commented on Jul 20, 2017

    @AndreasMadsen
    AndreasMadsen
    on Jul 20, 2017
    Member

    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.

  7. mcollina commented on Jul 20, 2017

    @mcollina
    mcollina
    on Jul 20, 2017
    SponsorMember

    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.

  8. mcollina commented on Jul 20, 2017

    @mcollina
    mcollina
    on Jul 20, 2017
    SponsorMember

    @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)

  9. AndreasMadsen commented on Jul 20, 2017

    @AndreasMadsen
    AndreasMadsen
    on Jul 20, 2017
    Member

    @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.

  10. akanass commented on Jul 20, 2017

    @akanass
    akanass
    on Jul 20, 2017

    @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.

  11. crespowang commented on Jul 20, 2017

    @crespowang
    crespowang
    on Jul 20, 2017
    Author

    Hey @AndreasMadsen, did you want me to add the code in the test? If yes, then this is the output

    init { asyncId: 1271, type: 'Immediate', triggerAsyncId: 0 }
Error: bad async id
    at AsyncHook.init (/Users/crespowang/Projects/project-x/server/routes/account-verification.test.js:15:13)
    at emitInitNative (async_hooks.js:420:43)
    at emitInitScript (async_hooks.js:328:3)
    at new Immediate (timers.js:808:5)
    at createImmediate (timers.js:848:19)
    at setImmediate (timers.js:835:10)
    at Async._schedule (/Users/crespowang/Projects/project-x/server/node_modules/objection/node_modules/bluebird/js/release/schedule.js:12:53)
    at Async._queueTick (/Users/crespowang/Projects/project-x/server/node_modules/objection/node_modules/bluebird/js/release/async.js:152:14)
    at AsyncInvoke [as invoke] (/Users/crespowang/Projects/project-x/server/node_modules/objection/node_modules/bluebird/js/release/async.js:83:10)
    at Promise._then (/Users/crespowang/Projects/project-x/server/node_modules/objection/node_modules/bluebird/js/release/promise.js:261:15)
    at Promise.then (/Users/crespowang/Projects/project-x/server/node_modules/objection/node_modules/bluebird/js/release/promise.js:125:17)
    at eval (eval at createHookCaller (/Users/crespowang/Projects/project-x/server/node_modules/objection/lib/queryBuilder/QueryBuilder.js:1163:18), <anonymous>:5:22)
    at /Users/crespowang/Projects/project-x/server/node_modules/objection/lib/queryBuilder/QueryBuilder.js:1175:17
    at QueryBuilder.execute (/Users/crespowang/Projects/project-x/server/node_modules/objection/lib/queryBuilder/QueryBuilder.js:563:15)
    at QueryBuilder.then (/Users/crespowang/Projects/project-x/server/node_modules/objection/lib/queryBuilder/QueryBuilder.js:398:24)
  12. mcollina
    added 3 commits that reference this issue on Jul 20, 2017

    http: set async_id_symbol to any socket set

    9977354

    process: triggerAsyncId can be undefined

    1a49a5c

  13. AndreasMadsen commented on Jul 20, 2017

    @AndreasMadsen
    AndreasMadsen
    on Jul 20, 2017
    Member

    @crespowang Thanks. Looks like this revealed another (less significant issue). Given the number of issues regarding _write and _writeRaw I think we are just going to assume that it is the same issue. If that doesn't fix it, then we can look into this again.

  14. refack commented on Jul 20, 2017

    @refack
    refack
    on Jul 20, 2017
    Contributor

    @crespowang if you happen to have a testcase that consistently fails (independent of any npm modules), or alternatively, know of a public npm module whose tests fail, please post here, so we can add it to our regression tests.

  15. Fishrock123
    closed this as completedin 107db33on Jul 20, 2017
  16. Fishrock123
    added a commit that references this issue on Jul 20, 2017

    process: triggerAsyncId can be undefined

    302c19b

  17. crespowang commented on Jul 21, 2017

    @crespowang
    crespowang
    on Jul 21, 2017
    Author

    thanks for fixing this so quickly, v8.2.1 fixed the problem, as a node newbie can I ask how long does it take for a new version to appear in docker hub?

  18. mcollina commented on Jul 21, 2017

    @mcollina
    mcollina
    on Jul 21, 2017
    SponsorMember

    See nodejs/docker-node#470

  19. addaleax
    added a commit that references this issue on Jul 22, 2017

    process: triggerAsyncId can be undefined

    949fa81
  20. sjarmak
    added a commit that references this issue on Jul 27, 2026

    process: triggerAsyncId can be undefined

    107db33
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    async_hooksIssues and PRs related to the async hooks subsystem.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions