Right now I don't know exactly what is causing the problem.... (I guess posting a http request to some endpoints)
The process exits with this:
/usr/local/bin/node[27084]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
1: node::Abort() [/usr/local/bin/node]
2: node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, char const*, int, v8::Local<v8::Value>*, double, double) [/usr/local/bin/node]
3: node::AsyncWrap::PopAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/bin/node]
4: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [/usr/local/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) [/usr/local/bin/node]
6: v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/usr/local/bin/node]
7: 0x528d1b8437d
[1] 27084 abort node server.js
Any guess?
/cc @addaleax @trevnorris @AndreasMadsen ?
Any chance you could provide a core dump, or code to reproduce?
right now not... not so easy but will try in a couple of hours
Ok seems I have a core dump 1.49 GB and 264 MB zipped
Where should I upload it?
Wherever you want – if you don’t want to share it with everyone (i.e. because your program contains non-public code or data), you can also send it or a link to it to my email address that’s listed in the readme (I’ll take a look at that in a few hours then).
Thanks a lot... I've sent you an email.
Hmm … maybe somebody from @nodejs/platform-macos would be able to take a look, too? Right now I don’t have the tooling to deal with macos core dumps beyond pretty trivial things.
A full disassembly of the 8.0.0 macos executable might be helpful as well; the stack trace as it is shown in the original issue should not really be possible, because I don’t see any way for AsyncWrap::PopAsyncIds to call MakeCallback in such a way that it shows up like this (so there’s definitely sth weird going on).
@adrai Where did you install your node binary from?
from https://github.com/tj/n
https://twitter.com/adrirai/status/869645398016765952 ;-)
I have got the coredump from @addaleax (who got this from @adrai) and opened it. I am not familiar with the async hooks enough to know why the assertion failed but there could be an overflow which caused triggered_id to be -1..I guess?
See the stacktrace
(lldb) v8 bt
* thread #1: tid = 0x0000, 0x00007fffd5dd0d42 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
* frame #0: 0x00007fffd5dd0d42 libsystem_kernel.dylib`__pthread_kill + 10
frame #1: 0x00007fffd5ebe5bf libsystem_pthread.dylib`pthread_kill + 90
frame #2: 0x00007fffd5d36420 libsystem_c.dylib`abort + 129
frame #3: 0x0000000100a741cd node`node::Abort() + 34
frame #4: 0x0000000100a7308b node`node::Assert(char const* const (*) [4]) + 251
frame #5: 0x0000000100a636b8 node`node::AsyncWrap::PushAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) + 296
frame #7: 0x000013fe250e74cb nextTickEmitBefore(this=0x0000138933582311:<undefined>, 0x0000232e2b4be931:<Number: 942.000000>, 0x0000232e2b4be941:<Number: -1.000000>) at internal/process/next_tick.js:117:30 fn=0x00001a29492b0959
frame #8: 0x000013fe24ffe4d7 _tickCallback(this=0x00003e642f80d441:<Object: process>) at internal/process/next_tick.js:133:25 fn=0x00003e642f810151
frame #11: 0x0000000100558e36 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: 0x0000000100558a93 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: 0x00000001001611ff node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 559
frame #14: 0x0000000100a658e5 node`node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) + 789
frame #15: 0x0000000100ac24ae node`node::StreamBase::EmitData(long, v8::Local<v8::Object>, v8::Local<v8::Object>) + 214
frame #16: 0x0000000100ac4820 node`node::StreamWrap::OnReadImpl(long, uv_buf_t const*, uv_handle_type, void*) + 524
frame #17: 0x0000000100ac4d29 node`node::StreamWrap::OnReadCommon(uv_stream_s*, long, uv_buf_t const*, uv_handle_type) + 127
frame #18: 0x0000000100be21b4 node`uv__stream_io + 1261
frame #19: 0x0000000100be99d1 node`uv__io_poll + 1621
frame #20: 0x0000000100bda85b node`uv_run + 321
frame #21: 0x0000000100a81999 node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 741
frame #22: 0x0000000100a7cd67 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 462
frame #23: 0x0000000100a7c35a node`node::Start(int, char**) + 331
frame #24: 0x0000000100000d34 node`start + 52
@joyeecheung If you're feeling adventurous give https://github.com/nodejs/llnode a try:
./gyp_llnode && make -C out BUILDTYPE=Release && make install-osxv8 bt in lldb to get a stack trace with JS frames (including arguments)@bnoordhuis Yeah I've been using it, frame #6-10 in the stacktrace above are patched with v8 info.
Thanks, now we now it's the second argument on this line: https://github.com/nodejs/node/blob/v8.0.0/lib/internal/process/next_tick.js#L145
cc @AndreasMadsen @trevnorris (we don't have a async-hooks group yet, right?)
@adrai could I get you to add this code to the beginning of your script (perhaps using the node -r flag) and the show us the error stack?
const async_hooks = require('async_hooks');
async_hooks.createHook({
init(id, type, triggerId, resource) {
if (triggerId < 0) {
process._rawDebug('init', {id, type, triggerId});
Error.stackTraceLimit = Infinity;
throw new Error('bad trigger id');
}
}
}).enable();
@AndreasMadsen Good idea. I would also turn the if (triggerId < 0) { line into if (triggerId < 0 || id < 0) { (for the case that initTriggerId defaults to async_uid_fields[kCurrentAsyncId]).
@addaleax Sure.
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});
Error.stackTraceLimit = Infinity;
throw new Error('bad trigger id');
}
}
}).enable();
I run to my notebook... :-)
Is this ok?
[2017-05-31T13:23:09.118Z] FATAL: iot/11226 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
[2017-05-31T13:23:09.127Z] FATAL: iot/11226 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
[2017-05-31T13:23:09.291Z] FATAL: iot/11226 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
[2017-05-31T13:23:09.296Z] FATAL: iot/11226 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
@adrai Yes, I think so, but unfortunately the stack trace is truncated – if you set Error.stackTraceLimit = Infinity; right at the beginning of your program it might run quite a bit slower but it has a much better chance of showing where the invalid value is coming from
[2017-05-31T13:41:20.300Z] FATAL: iot/20739 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at ClientRequest.onSocket (/Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/http_client.js:225:13)
at Object.onceWrapper (events.js:312:19)
at emitOne (events.js:120:20)
at ClientRequest.emit (events.js:210:7)
at tickOnSocket (_http_client.js:666:7)
at onSocketNT (_http_client.js:682:5)
at _combinedTickCallback (internal/process/next_tick.js:102:11)
at process._tickCallback (internal/process/next_tick.js:161:9)
[2017-05-31T13:41:20.321Z] FATAL: iot/20739 on Raianos-MacBook-Pro.local: triggerId must be an unsigned integer (app_id="")
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at ClientRequest.onSocket (/Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/http_client.js:225:13)
at Object.onceWrapper (events.js:312:19)
at emitOne (events.js:120:20)
at ClientRequest.emit (events.js:210:7)
at tickOnSocket (_http_client.js:666:7)
at onSocketNT (_http_client.js:682:5)
at _combinedTickCallback (internal/process/next_tick.js:102:11)
at process._tickCallback (internal/process/next_tick.js:161:9)
I can reproduce it like this:
You need a http server that enforces basic auth... (at least I tested it that way)
... and you need to use the wrong credentials in the request (at least I tested it that way too)
const restify = require('restify');
const jsonTargetClient = restify.createJSONClient({
url: 'http://localhost:4999',
version: '*'
});
jsonTargetClient.basicAuth('wrong', 'creds');
setInterval(() => {
console.log('send the request...');
jsonTargetClient.post({
path: '/the/path'
}, { a: 'bit of data' }, (err) => {
console.log('responded...');
console.error(err);
});
}, 1000);
the output is:
send the request...
responded...
{ UnauthorizedError
at ClientRequest.onResponse (/Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/http_client.js:169:26)
at Object.onceWrapper (events.js:312:19)
at emitOne (events.js:115:13)
at ClientRequest.emit (events.js:210:7)
at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:563:21)
at HTTPParser.parserOnHeadersComplete (_http_common.js:116:23)
at Socket.socketOnData (_http_client.js:452:20)
at emitOne (events.js:115:13)
at Socket.emit (events.js:210:7)
at addChunk (_stream_readable.js:250:12)
at readableAddChunk (_stream_readable.js:237:11)
at Socket.Readable.push (_stream_readable.js:195:10)
at TCP.onread (net.js:586:20)
jse_shortmsg: '',
jse_info: {},
message: 'Unauthorized',
statusCode: 401,
body: {} }
send the request...
async_hooks.js:322
throw new RangeError('triggerId must be an unsigned integer');
^
RangeError: triggerId must be an unsigned integer
at emitInitS (async_hooks.js:322:11)
at setupInit (internal/process/next_tick.js:225:7)
at internalNextTick (internal/process/next_tick.js:269:5)
at ClientRequest._writeRaw (_http_outgoing.js:279:9)
at ClientRequest._send (_http_outgoing.js:255:15)
at ClientRequest.end (_http_outgoing.js:780:16)
at /Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/string_client.js:108:17
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at FunctionCall.doCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:162:20)
at FunctionCall.handleFunctionCallback_ (/Users/adrai/Projects/iot-cloud/service-out/node_modules/backoff/lib/function_call.js:181:14)
at f (/Users/adrai/Projects/iot-cloud/service-out/node_modules/once/once.js:25:25)
at ClientRequest.onSocket (/Users/adrai/Projects/iot-cloud/service-out/node_modules/restify/lib/clients/http_client.js:225:13)
at Object.onceWrapper (events.js:312:19)
at emitOne (events.js:120:20)
at ClientRequest.emit (events.js:210:7)
at tickOnSocket (_http_client.js:666:7)
at onSocketNT (_http_client.js:682:5)
at _combinedTickCallback (internal/process/next_tick.js:102:11)
at process._tickCallback (internal/process/next_tick.js:161:9)
Perhaps @retrohacker has an idea?
With the following script:
const http = require('http');
const restify = require('restify');
const stringClient = restify.createStringClient({
url: 'http://localhost:4999',
version: '*'
});
http.createServer(function (req, res) {
res.writeHead(401, {'Content-Type': 'text/plain'});
res.end('error');
}).listen(4999, function () {
setInterval(() => {
console.log('send the request...');
stringClient.post({
path: '/the/path'
}, 'data', () => {
console.log('responded...');
});
}, 100);
});
I can reproduce the crash with Node 8.0.0 but NOT with master.
correlated with https://github.com/nodejs/node/issues/13237 ?
Weird: I am unable to reproduce with a fresh build of v8.x.
I can reproduce this, too (only on 8.0.0 as well, not master).
correlated with #13237 ?
I don’t think so – that should be fixed in 8.0.0, and only affects you if you use async_hooks actively.
Hmmm, the binary on nodejs.org aborts for me but a custom build of v8.x@HEAD works fine.
This still is an issue on master; this fails only in releases because restify v4.x does version sniffing, and apparently semver.satisfies('v8.0.0-pre', '>=0.11.6') === false (but only with the -pre tag).
So, as far as I can tell, the problem is related to existing HTTP agents not knowing how to handle async_hooks integration eeh, it’s the other way around … in some way … I’m not quite sure how to tacke this (or what exactly the bug here is). @nodejs/http
So in theory semver.satisfies('v8.0.0', '>=0.11.6') should work like semver.satisfies('v6.10.0', '>=0.11.6') is working and semver.satisfies('v8.0.0-pre', '>=0.11.6') should not... right?
PS. daily fun fact @isaacs introduced this fix in restify => https://github.com/restify/node-restify/commit/1fca266f377e9bc3544c826e1283a29709f6e16b
@adrai I was confused at first too, and I can’t really tell you what the right behaviour of semver is (I assume somebody has given this a lot of thought and decided that 0 > 8 makes sense, somehow). The problem is that v8.0.0 makes restify use Node’s built-in agent, which seems to mess up things; with v8.0.0-pre, restify reverts to the keep-alive-agent userland implementation which works fine. :/
I hope there is someone who knows what would be the best for everyone...
so for other userland modules like https://github.com/request/request and https://github.com/visionmedia/superagent
We had a suspicion this could happen with a custom Agent https://github.com/nodejs/node/issues/13045#issuecomment-302270303
@refack Sorry, my initial comment above was wrong, this is about not using a custom Agent.
So I see a race on the kept alive socket between
this[async_id_symbol] = -1 @ https://github.com/nodejs/node/blob/master/lib/internal/process/next_tick.js#L217
and
this.socket[async_id_symbol] @ https://github.com/nodejs/node/blob/master/lib/_http_outgoing.js#L279
The Socket does not pass through the constructor to reset it's this[async_id_symbol] =
Somewhere we need to do another this[async_id_symbol] = this._handle.getAsyncId();
Maybe second one should be this.socket._handle.getAsyncId()?
@refack I don’t think there’s a race condition involved here, the test case here fails reliably (but I don’t quite get what you are referencing, maybe I’m misunderstanding).
After tracking it all down, this is hard to reproduce but it seems like a pretty simple logic bug with an easy fix: https://github.com/nodejs/node/pull/13348
Any update? ETA on next 8.x release ;-)
@adrai The fix should be ready to be merged tomorrow (we have a minimum waiting time for that kind of thing), and I think we’re planning for a release next week to fix up some things after the 8.0.0 release.
thx a lot
I use node.js since early 0.4 versions (I think 2011) but I'm always surprised by the awesome node.js community!
Note this fix did not fix the issue in Haraka (which isn't using http).
@baudehlo can you open an issue and show us the error? (also if it appears to be exactly the same.) Since you are not using http it can't be the same issue.
Will do.
@AndreasMadsen - I am running into this in my backend servers on all 8.x versions to included 8.1.4.
/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
@d3viant0ne please open a new issue. It is the same assert but most likely a different issue.
No problem, thanks :)
Updating to Node v9.4 seems to have solved my problem.
Most helpful comment
thx a lot
I use node.js since early 0.4 versions (I think 2011) but I'm always surprised by the awesome node.js community!