Haraka test suite crashes with

[baudehlo]

• 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

[refack]

/cc @nodejs/async_hooks

[AndreasMadsen]

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.

[refack]

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 #13348 ?

[AndreasMadsen]

I debugged it, this will reproduce the error:

const net = require('net');
const server = net.createServer();
server.getConnections(() => {});

[AndreasMadsen]

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;

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

[AndreasMadsen]

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.

[refack]

Maybe investigate removing this[async_id_symbol] as per #13348 (comment)?

[addaleax]

@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’t have a handle yet whose ID we could use.

[refack]

@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’t 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

[AndreasMadsen]

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