8.2.0 crashes test when using shot #14386

mcollina · 2017-07-20T09:49:16Z

Version: 8.2.0
Platform: Mac OS X
Subsystem: http, async_hooks

/Users/matteo/.nvm/versions/node/v8.2.0/bin/node[65260]: ../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: 0x297938e840bd
Abort trap: 6

Stacktrace as described by in #14381 (comment):

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

lldb output:

(llnode) run
Process 65335 launched: '/Users/matteo/.nvm/versions/node/v8.2.0/bin/node' (x86_64)
/Users/matteo/.nvm/versions/node/v8.2.0/bin/node[65335]: ../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: 0x774135840bd
Process 65335 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
    frame #0: 0x00007fffb7bbfd42 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill:
->  0x7fffb7bbfd42 <+10>: jae    0x7fffb7bbfd4c            ; <+20>
    0x7fffb7bbfd44 <+12>: movq   %rax, %rdi
    0x7fffb7bbfd47 <+15>: jmp    0x7fffb7bb8caf            ; cerror_nocancel
    0x7fffb7bbfd4c <+20>: retq
(llnode) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
  * frame #0: 0x00007fffb7bbfd42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffb7cad457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fffb7b25420 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: 0x000000010017b0c2 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 466
    frame #7: 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 #8: 0x00000001001e6449 node`v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 281
    frame #9: 0x00000774135840bd
    frame #10: 0x00000774137abfce
    frame #11: 0x00000774137ab65a
    frame #12: 0x0000077413590290
    frame #13: 0x000007741365646d
    frame #14: 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 #15: 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 #16: 0x00000001001619ef node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
    frame #17: 0x0000000100a759eb node`node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 1104
    frame #18: 0x0000000100a75cba node`node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 108
    frame #19: 0x0000000100a7ee7a node`node::CheckImmediate(uv_check_s*) + 80
    frame #20: 0x0000000100be4b43 node`uv__run_check + 167
    frame #21: 0x0000000100bdfaef node`uv_run + 329
    frame #22: 0x0000000100a8481c node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 736
    frame #23: 0x0000000100a7f7c1 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
    frame #24: 0x0000000100a7edb5 node`node::Start(int, char**) + 331
    frame #25: 0x0000000100000e34 node`start + 52

Let me know if you need anything more.

cc @nodejs/async_hooks

The text was updated successfully, but these errors were encountered:

AndreasMadsen · 2017-07-20T10:17:24Z

Looks like it didn't resolve the JS stack correctly. I'm suspecting that

    frame #9: 0x00000774135840bd
    frame #10: 0x00000774137abfce
    frame #11: 0x00000774137ab65a
    frame #12: 0x0000077413590290
    frame #13: 0x000007741365646d

contains the critical information.

AndreasMadsen · 2017-07-20T10:22:08Z

Let me know if you need anything more.

It would be awesome if you could reproduce it as a standard test case. I can't work on it today and @refack is debugging another async_hooks issue.

mcollina · 2017-07-20T10:23:22Z

Any direction on how to get that information from llnode? I'm running node through lldb to get that, as --abort-on-uncaught-exception does not generate the core dump in this case.

AndreasMadsen · 2017-07-20T10:34:48Z

Not sure. I only started using llnode a week ago :p

Are you using lldb directly? In that case you should use llnode -- /path/to/bin/node script.js instead.

mcollina · 2017-07-20T10:37:29Z

@AndreasMadsen that does not work either.

bnoordhuis · 2017-07-20T10:39:48Z

Assuming llnode is installed properly, v8 bt in lldb should print a C++ + JS stack trace.

edit: and start it like this: lldb -- node script.js

mcollina · 2017-07-20T10:41:28Z

Thanks @bnoordhuis.

 * thread #1: tid = 0x0000, 0x00007fffb7bbfd42 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fffb7bbfd42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffb7cad457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fffb7b25420 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: 0x000000010017b0c2 node`v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) + 466
    frame #7: 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 #8: 0x00000001001e6449 node`v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) + 281
    frame #9: 0x0000149eb7d840bd <exit>
    frame #10: 0x0000149eb7fac80e emitBeforeScript(this=0x0000354efc582241:<undefined>, 0x00001a908148a5b1:<Number: 21.000000>, 0x0000354efc582241:<undefined>) at async_hooks.js:364:26 fn=0x000030bee72fff61
    frame #11: 0x0000149eb7fabe9a _tickCallback(this=0x000030bee7287859:<Object: process>) at internal/process/next_tick.js:151:25 fn=0x00002261dfb85a71
    frame #12: 0x0000149eb7d90290 <internal>
    frame #13: 0x0000149eb7e5646d <entry>
    frame #14: 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 #15: 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 #16: 0x00000001001619ef node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
    frame #17: 0x0000000100a759eb node`node::MakeCallback(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 1104
    frame #18: 0x0000000100a75cba node`node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) + 108
    frame #19: 0x0000000100a7ee7a node`node::CheckImmediate(uv_check_s*) + 80
    frame #20: 0x0000000100be4b43 node`uv__run_check + 167
    frame #21: 0x0000000100bdfaef node`uv_run + 329
    frame #22: 0x0000000100a8481c node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 736
    frame #23: 0x0000000100a7f7c1 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
    frame #24: 0x0000000100a7edb5 node`node::Start(int, char**) + 331
    frame #25: 0x0000000100000e34 node`start + 52

AndreasMadsen · 2017-07-20T10:46:36Z

@mcollina Thanks. Appears to be the same issue as in #14381, although it might hit the issue on _write instead of _writeRaw.

mcollina · 2017-07-20T10:53:36Z

https://github.com/nodejs/node/blob/master/lib/_http_server.js#L157-L165 needs to attach a new asyncId if one was not there. Should I do that with async_hooks.initTriggerId()?

AndreasMadsen · 2017-07-20T10:59:55Z

https://github.com/nodejs/node/blob/master/lib/_http_server.js#L157-L165 needs to attach a new asyncId if one was not there. Should I do that with async_hooks.initTriggerId()?

I only have time for a quick look. I think async_hooks.newUid() is the correct value to use. Maybe it requires a full call to emitInit as well.

socket[async_id_symbol] = async_hooks.newUid();
async_hooks.emitInit(socket[async_id_symbol], type /* not sure, maybe just invent a new value */,
                     async_hooks.initTriggerId(), socket);

edit: and async_hooks.emitDestroy(socket[async_id_symbol]) will have to be called when the socket is destroyed :/

refack · 2017-07-20T11:06:55Z

I only have time for a quick look. I think async_hooks.newUid() is the correct value to use. Maybe it requires a full call to emitInit as well.

[Also just from a quick look] if this is actually a "reuse" of a previous socket maybe asyncReset() is needed like in https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L171

refack · 2017-07-20T11:08:30Z

Do we have a reproduction snippet? (even with 3rd party dependencies)

mcollina · 2017-07-20T11:09:30Z

@refack this is done just over a plain stream. It's not a socket at all.

PR is on the way:

$ cat test/parallel/test-http-server-response-inheritance.js

'use strict'

const common = require('../common')
const { ServerResponse } = require('http')
const { Writable } = require('stream')
const assert = require('assert')

// check that ServerResponse can be inherited correctly

class Response extends ServerResponse {
  constructor() {
    super({ method: 'GET', httpVersionMajor: 1, httpVersionMinor: 1 });
  }
}

const res = new Response()
const ws = new Writable({
  write: common.mustCall((chunk, encoding, callback) => {
    assert(chunk.toString().match(/hello world/))
    setImmediate(callback);
  })
});

res.assignSocket(ws);

res.end('hello world');

refack · 2017-07-20T11:12:54Z

Windows is not being helpful 😞:

D:\code\3party\shot>node8.2 node_modules\lab\bin\lab -a code -t 100 -L
C:\bin\dev\node\node8.2.exe: c:\ws\src\env-inl.h:131: Assertion `(trigger_id) >= (0)' failed.

refack · 2017-07-20T11:17:07Z

Just putting some pieces together, please correct me if I'm wrong:

shot fiddles with the HTTP flow
it attached a "non-socket" to the response via ServerResponse.prototype.assignSocket
hilarity ensues

AndreasMadsen · 2017-07-20T11:23:40Z

[Also just from a quick look] if this is actually a "reuse" of a previous socket maybe asyncReset() is needed like in https://github.com/nodejs/node/blob/master/lib/_http_agent.js#L171

If it is a reuse and asyncReset() is available then I agree.

OutgoingMessage needs a async-hooks enabled socket to work, but we support also basic streams. This PR init the async-hooks bits for the passed stream if it is needed. PR-URL: nodejs#14389 Fixes: nodejs#14386 Fixes: nodejs#14381

mscdex · 2017-07-20T15:32:09Z

Isn't this the same as #14381 ?

Fixes: nodejs#14386 Fixes: nodejs#14381

mcollina · 2017-07-20T16:59:04Z

@mscdex I think so, yes.

Fixes: #14386 Fixes: #14381 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

mcollina mentioned this issue Jul 20, 2017

Add Shot to the mix nodejs/citgm#457

Closed

mcollina mentioned this issue Jul 20, 2017

async_hooks: triggerAsyncId can be undefined #14387

Closed

3 tasks

mcollina mentioned this issue Jul 20, 2017

http: set async_id_symbol to any socket set #14389

Closed

3 tasks

mscdex added the v8.x label Jul 20, 2017

mscdex added async_hooks Issues and PRs related to the async hooks subsystem. async_wrap labels Jul 20, 2017

mcollina added a commit to mcollina/node that referenced this issue Jul 20, 2017

process: triggerAsyncId can be undefined

1a49a5c

Fixes: nodejs#14386 Fixes: nodejs#14381

Fishrock123 closed this as completed in 107db33 Jul 20, 2017

Uh oh!

8.2.0 crashes test when using shot #14386

8.2.0 crashes test when using shot #14386

Comments

mcollina commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

AndreasMadsen commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

bnoordhuis commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

refack commented Jul 20, 2017

Uh oh!

refack commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

refack commented Jul 20, 2017

Uh oh!

refack commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017

Uh oh!

mscdex commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017 •

edited

Loading

bnoordhuis commented Jul 20, 2017 •

edited

Loading

AndreasMadsen commented Jul 20, 2017 •

edited

Loading

AndreasMadsen commented Jul 20, 2017 •

edited

Loading