Node: Haraka test suite crashes with

Created on 8 Jun 2017  路  27Comments  路  Source: nodejs/node
  • Version: v8.1.0
  • Platform: Debian (Travis)
  • Subsystem:

This looks similar to #13325

Full logs can be found here: https://travis-ci.org/haraka/Haraka/jobs/239765834

Test suite exits with:

/home/travis/.nvm/versions/node/v8.1.0/bin/node[3346]: ../src/env-inl.h:131:void node::Environment::AsyncHooks::push_ids(double, double): Assertion `(trigger_id) >= (0)' failed.
 1: node::Abort() [node]
 2: node::Assert(char const* const (*) [4]) [node]
 3: node::AsyncWrap::PushAsyncIds(v8::FunctionCallbackInfo<v8::Value> const&) [node]
 4: v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) [node]
 5: 0xb43f48 [node]
 6: v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) [node]
 7: 0x26285a08437d
Aborted (core dumped)

Test being run is here: https://github.com/haraka/Haraka/blob/master/tests/server.js#L93

async_hooks async_wrap confirmed-bug regression
Source
picture baudehlo

All 27 comments

/cc @nodejs/async_hooks

refack picture refack on 8 Jun 2017

Using similar script as in #13325, I get the following error:

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 end (net.js:1547:5)
    at Server.getConnections (net.js:1551:12)
    at Object.gets a net server object (/Users/Andreas/Sites/Haraka/tests/server.js:119:16)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:232:20
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:168:13
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:131:25
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:165:17
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:463:34
    at Object.setUp (/Users/Andreas/Sites/Haraka/tests/server.js:102:9)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:260:35
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:458:21
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:163:13
    at iterate (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:123:13)
    at async.forEachSeries (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:139:9)
    at _asyncMap (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:162:9)
    at Object.mapSeries (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:152:23)
    at Object.async.series (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:456:19)
    at Object.<anonymous> (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:264:22)
    at Object.<anonymous> (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:228:19)
    at Object.<anonymous> (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:236:16)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:236:16
    at Object.exports.runTest (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:70:9)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:118:25
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:513:13
    at iterate (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:123:13)
    at async.forEachSeries (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:139:9)
    at _concat (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:512:9)
    at Object.concatSeries (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:152:23)
    at Object.exports.runSuite (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:96:11)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/core.js:125:21
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:513:13
    at iterate (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:123:13)
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:134:25
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:515:17
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:518:13
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:131:25
    at /Users/Andreas/Sites/Haraka/node_modules/nodeunit/deps/async.js:515:17
    at Immediate._onImmediate (/Users/Andreas/Sites/Haraka/node_modules/nodeunit/lib/types.js:146:17)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)

Somehow the self[async_id_symbol] asyncId at https://github.com/nodejs/node/blob/master/lib/net.js#L1549 is not correct.

AndreasMadsen picture AndreasMadsen on 8 Jun 2017

Somehow the self[async_id_symbol] asyncId at https://github.com/nodejs/node/blob/master/lib/net.js#L1549 is not correct.

Any chance it's a reused socket like in https://github.com/nodejs/node/pull/13348 ?

refack picture refack on 8 Jun 2017

I debugged it, this will reproduce the error:

const net = require('net');
const server = net.createServer();
server.getConnections(() => {});
AndreasMadsen picture AndreasMadsen on 8 Jun 2017
👍1

More explanation:

when the server is created it sets the [async_id_symbol] to -1. The [async_id_symbol] isn't set before the server handle is created, this happens in server.listen().

Best fix I can think of is:

const asyncId = this._handle ? this[async_id_symbol] : null;
AndreasMadsen picture AndreasMadsen on 8 Jun 2017
👍1

Maybe we should just keep separate async ids for the JS net.Socket/net.Server instances and the handle? It seems like that might make things a bit easier?

addaleax picture addaleax on 8 Jun 2017

Maybe we should just keep separate async ids for the JS net.Socket/net.Server instances and the handle? It seems like that might make things a bit easier?

I like the idea of creating a primary resource for the server and a secondary resource for .listen()/handle, it also solves the odd behavior where the resource isn't created before .listen() is called. However, there are likely a few things we need to think about. For example, we need to change the triggerId of the onconnection sockets such it points to the server.

AndreasMadsen picture AndreasMadsen on 8 Jun 2017

Maybe investigate removing this[async_id_symbol] as per https://github.com/nodejs/node/pull/13348#discussion_r119967730?

refack picture refack on 8 Jun 2017

@refack I think this is a good example of why that is not as simple as the comment suggests; we need a proper async ID to pass to nextTick here, but we don鈥檛 have a handle yet whose ID we could use.

addaleax picture addaleax on 8 Jun 2017

@refack I think this is a good example of why that is not as simple as the comment suggests; we need a proper async ID to pass to nextTick here, but we don鈥檛 have a handle yet whose ID we could use.

You are actually making me read the code (and stop talking out of my **) 馃摐

As I see it this is an example why this[async_id_symbol] is unreliable, if the code was this._handle.getAsyncId() the error would have been in JS 

TypeError: Cannot read property 'getAsyncId' of undefined
   at Server.prototype.getConnections (net.js:1549:14)
   ...

which is less scary than the OP.
Maybe even easier to spot that this._handle might be undefined... 馃

[another bad idea]
init all _handles with { getAsyncId() {return null;} }

[maybe less bad]
init all this[async_id_symbol] = null
this will hide bugs but be less explosive for people who don't use async_hooks

refack picture refack on 8 Jun 2017

[maybe less bad]
init all this[async_id_symbol] = null
this will hide bugs but be less explosive for people who don't use async_hooks

I think there are better ways to do that if we want to go there, such as don't assert in push/pop at all if async_hooks isn't used.

AndreasMadsen picture AndreasMadsen on 8 Jun 2017

@AndreasMadsen

I think there are better ways to do that if we want to go there, such as don't assert in push/pop at all if async_hooks isn't used.

Are you referring to https://github.com/nodejs/node/blob/v8.1.0/src/env-inl.h#L130-L131 and https://github.com/nodejs/node/blob/v8.1.0/src/env-inl.h#L146-L160 ? Those checks saved my sanity while developing async_hooks and I believe they should always run. The argument of "async_hooks not being used" is difficult because they can be enabled at any time, and if the stack is corrupt when that happens then the user will be getting bad information.

@addaleax

Maybe we should just keep separate async ids for the JS net.Socket/net.Server instances and the handle? It seems like that might make things a bit easier?

The question is, how would the before/after calls work? And what would the asyncId and triggerId be in the init of the TCPWrap? Example:

const print = process._rawDebug;
const hook = async_hooks.createHook({
  before(id) { print('>', id) },
  after(id) { print('<', id) },
});

const s = net.createServer((conn) => {
  print('<<', conn.getAsyncId() ,'>>');
  print('<<', conn._handle.getAsyncId() ,'>>');
}).listen();

s.getAsyncId();  // 3
s._handle.getAsyncId();  // 4

Here's what receiving a new connection may look like:

> 4
> 3
<< 7 >>
<< 6 >>
< 3
< 4

But on the init(asyncId, type, triggerId) for the new connection, which id would be the asyncId and the triggerId? This becomes even more complicated when attempting to create graphs from callbacks to write() depending on whether the data was able to be flushed to the kernel or not.

My solution would be do something simple like:

diff --git a/lib/net.js b/lib/net.js
index 67c231e..1a2c54a 100644
--- a/lib/net.js
+++ b/lib/net.js
@@ -183,7 +183,7 @@ function Socket(options) {
   // Problem with this is that users can supply their own handle, that may not
   // have _handle.getAsyncId(). In this case an[async_id_symbol] should
   // probably be supplied by async_hooks.
-  this[async_id_symbol] = -1;
+  this[async_id_symbol] = 0;
   this._hadError = false;
   this._handle = null;
   this._parent = null;
@@ -1186,7 +1186,7 @@ function Server(options, connectionListener) {
     configurable: true, enumerable: false
   });

-  this[async_id_symbol] = -1;
+  this[async_id_symbol] = 0;
   this._handle = null;
   this._usingSlaves = false;
   this._slaves = [];

Reason is because I originally set this[async_id_symbol] = -1; as a way to find bugs. It was intentionally over cautious to make sure I didn't overlook anything. But at this point a net.Server/net.Socket instance without a _handle should simply be treated as an EventEmitter instance (since by itself it can't do anything asynchronous.

Thought: Allow AsyncWrap to accept an asyncId instead of always assigning a new one. Then the id could be created when net.Server() is instantiated and still be the same in the call graph even after the TCPWrap is assigned after the .listen() is called. There are a couple things we'd need go guard against, but I think this may be the best approach.

/cc @AndreasMadsen @addaleax @refack

If everyone thinks being able to pass an existing asyncId to AsyncWrap is a good approach I'll get started on the PR immediately.

trevnorris picture trevnorris on 8 Jun 2017

If everyone thinks being able to pass an existing asyncId to AsyncWrap is a good approach I'll get started on the PR immediately.

I had the same thought. :) I think that would be the best approach, yes.

addaleax picture addaleax on 9 Jun 2017

If everyone thinks being able to pass an existing asyncId to AsyncWrap is a good approach I'll get started on the PR immediately.

I think we might also need that if we are going to completely fix https://github.com/nodejs/node/issues/13427

AndreasMadsen picture AndreasMadsen on 19 Jun 2017

Also the second half of https://github.com/nodejs/node/issues/13045 has come up (http Agent non-cohesive API)

refack picture refack on 21 Jun 2017

If this needs to be discussed further, I think we should use const asyncId = this._handle ? this[async_id_symbol] : null; for now.

AndreasMadsen picture AndreasMadsen on 21 Jun 2017

@AndreasMadsen

I think we might also need that if we are going to completely fix #13427

I'm working on the patch now, but running into some issues (which should be expected by now).

If this needs to be discussed further, I think we should use const asyncId = this._handle ? this[async_id_symbol] : null; for now.

I believe that approach would be an appropriate short term fix.

trevnorris picture trevnorris on 21 Jun 2017

Anything I can do to help with this?

baudehlo picture baudehlo on 25 Jun 2017

@baudehlo Yes, you can make a pull request that adds:

const asyncId = this._handle ? this[async_id_symbol] : null;
nextTick(asyncId cb, err, connections);

here https://github.com/nodejs/node/blob/master/lib/net.js#L1561.

And add a test case with:

const net = require('net');
const server = net.createServer();
server.getConnections(() => { /* test return value */ });
AndreasMadsen picture AndreasMadsen on 25 Jun 2017

@AndreasMadsen does

nextTick(null, cb, err, connections);

work? On the one hand I remember it should, on the other I vaguely remember it throwing in https://github.com/nodejs/node/pull/13839

refack picture refack on 26 Jun 2017

That is how it is supposed to work https://github.com/nodejs/node/blob/master/lib/internal/process/next_tick.js#L300

In reality, it is a bit more flexible https://github.com/nodejs/node/blob/master/lib/async_hooks.js#L322

AndreasMadsen picture AndreasMadsen on 26 Jun 2017

But what is https://github.com/nodejs/node/blob/master/lib/async_hooks.js#L323L324 about? If it is an attempt to make triggerAsyncId optional, shouldn't it then be if (triggerAsyncId === undefined). But I don't see why that code would even be there.

AndreasMadsen picture AndreasMadsen on 26 Jun 2017

You should consult with the person who wrote it
image
馃槙 馃樀

refack picture refack on 26 Jun 2017

@refack that commit just renamed the variable, https://github.com/nodejs/node/blame/448c4c62d2b413226dfdef03d6f8d243de0984a3/lib/async_hooks.js#L311-L312 is the git blame you are looking for ;)

aqrln picture aqrln on 26 Jun 2017
👍1

@refack that commit just renamed the variable

I know, just wanted to make a funny 馃ぃ

Good call on adding actually informative context!

refack picture refack on 26 Jun 2017

@AndreasMadsen

But what is https://github.com/nodejs/node/blob/master/lib/async_hooks.js#L323L324 about?

I have no idea, and it looks incorrect. It's assigning what was probably an object to a number. So never mind, it's definitely incorrect.

trevnorris picture trevnorris on 30 Jun 2017

I have no idea, and it looks incorrect. It's assigning what was probably an object to a number. So never mind, it's definitely incorrect.

Fixed in https://github.com/nodejs/node/pull/14026

AndreasMadsen picture AndreasMadsen on 1 Jul 2017
Was this page helpful?
0 / 5 - 0 ratings

Related issues

akdor1154 picture akdor1154  路  3Comments
vsemozhetbyt picture vsemozhetbyt  路  3Comments
dfahlander picture dfahlander  路  3Comments
filipesilvaa picture filipesilvaa  路  3Comments
Icemic picture Icemic  路  3Comments