Node: 8.2.0 crashes test when using shot

[mcollina]

• 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 https://github.com/nodejs/node/issues/14381#issuecomment-316633020:

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

[AndreasMadsen]

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]

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]

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]

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]

@AndreasMadsen that does not work either.

[bnoordhuis]

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]

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]

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

[mcollina]

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]

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]

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]

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

[mcollina]

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

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]

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]

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

[mscdex]

Isn't this the same as https://github.com/nodejs/node/issues/14381 ?

[mcollina]

@mscdex I think so, yes.