Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Haraka test suite crashes with #13548

Closed
baudehlo opened this issue Jun 8, 2017 · 27 comments
Closed

Haraka test suite crashes with #13548

baudehlo opened this issue Jun 8, 2017 · 27 comments
Labels
async_hooks Issues and PRs related to the async hooks subsystem. confirmed-bug Issues with confirmed bugs. regression Issues related to regressions.

Comments

@baudehlo
Copy link

baudehlo commented Jun 8, 2017

  • 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 refack added async_hooks Issues and PRs related to the async hooks subsystem. async_wrap confirmed-bug Issues with confirmed bugs. regression Issues related to regressions. labels Jun 8, 2017
@refack
Copy link
Contributor

refack commented Jun 8, 2017

/cc @nodejs/async_hooks

@AndreasMadsen
Copy link
Member

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
Copy link
Contributor

refack commented Jun 8, 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 #13348 ?

@AndreasMadsen
Copy link
Member

I debugged it, this will reproduce the error:

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

@AndreasMadsen
Copy link
Member

AndreasMadsen commented Jun 8, 2017

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
Copy link
Member

addaleax commented Jun 8, 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?

@AndreasMadsen
Copy link
Member

AndreasMadsen commented Jun 8, 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.

@refack
Copy link
Contributor

refack commented Jun 8, 2017

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

@addaleax
Copy link
Member

addaleax commented Jun 8, 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’t have a handle yet whose ID we could use.

@refack
Copy link
Contributor

refack commented Jun 8, 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’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
Copy link
Member

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

@trevnorris
Copy link
Contributor

trevnorris commented Jun 8, 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.

@addaleax
Copy link
Member

addaleax commented Jun 9, 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.

@AndreasMadsen
Copy link
Member

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 #13427

@refack
Copy link
Contributor

refack commented Jun 21, 2017

Also the second half of #13045 has come up (http Agent non-cohesive API)

@AndreasMadsen
Copy link
Member

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

@trevnorris
Copy link
Contributor

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

@baudehlo
Copy link
Author

Anything I can do to help with this?

@AndreasMadsen
Copy link
Member

@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 */ });

@refack
Copy link
Contributor

refack commented Jun 25, 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 #13839

@AndreasMadsen
Copy link
Member

@AndreasMadsen
Copy link
Member

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.

@refack
Copy link
Contributor

refack commented Jun 26, 2017

You should consult with the person who wrote it
image
😕 😵

@aqrln
Copy link
Contributor

aqrln commented Jun 26, 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 ;)

@refack
Copy link
Contributor

refack commented Jun 26, 2017

@refack that commit just renamed the variable

I know, just wanted to make a funny 🤣

Good call on adding actually informative context!

@trevnorris
Copy link
Contributor

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

@AndreasMadsen
Copy link
Member

AndreasMadsen commented Jul 1, 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 #14026

AndreasMadsen pushed a commit to baudehlo/node that referenced this issue Jul 3, 2017
If the .listen() hasn't been called on the server, there is no handle
object. In this case use null as the triggerAsyncId.

Fixes: nodejs#13548
refack added a commit to refack/node that referenced this issue Jul 3, 2017
PR-URL: nodejs#13839
Fixes: nodejs#13045
Fixes: nodejs#13831
Refs: nodejs#13352
Refs: nodejs#13548 (comment)
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
addaleax pushed a commit to addaleax/node that referenced this issue Jul 3, 2017
PR-URL: nodejs#13839
Fixes: nodejs#13045
Fixes: nodejs#13831
Refs: nodejs#13352
Refs: nodejs#13548 (comment)
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
addaleax pushed a commit that referenced this issue Jul 11, 2017
PR-URL: #13839
Fixes: #13045
Fixes: #13831
Refs: #13352
Refs: #13548 (comment)
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
addaleax pushed a commit that referenced this issue Jul 11, 2017
If the .listen() hasn't been called on the server, there is no handle
object. In this case use null as the triggerAsyncId.

Fixes: #13548
PR-URL: #13938
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>
addaleax pushed a commit that referenced this issue Jul 11, 2017
In the case where triggerAsyncId is null it should default to the
current executionAsyncId. This worked but as a side-effect the resource
object was changed too.

This fix also makes the null check more strict. EmitInitS is not a
documented API, thus there is no reason to be flexible in its input.

Ref: #13548 (comment)
PR-URL: #14026
Reviewed-By: Refael Ackermann <refack@gmail.com>
addaleax pushed a commit that referenced this issue Jul 18, 2017
PR-URL: #13839
Fixes: #13045
Fixes: #13831
Refs: #13352
Refs: #13548 (comment)
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
addaleax pushed a commit that referenced this issue Jul 18, 2017
If the .listen() hasn't been called on the server, there is no handle
object. In this case use null as the triggerAsyncId.

Fixes: #13548
PR-URL: #13938
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>
addaleax pushed a commit that referenced this issue Jul 18, 2017
In the case where triggerAsyncId is null it should default to the
current executionAsyncId. This worked but as a side-effect the resource
object was changed too.

This fix also makes the null check more strict. EmitInitS is not a
documented API, thus there is no reason to be flexible in its input.

Ref: #13548 (comment)
PR-URL: #14026
Reviewed-By: Refael Ackermann <refack@gmail.com>
Fishrock123 pushed a commit that referenced this issue Jul 19, 2017
PR-URL: #13839
Fixes: #13045
Fixes: #13831
Refs: #13352
Refs: #13548 (comment)
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
Fishrock123 pushed a commit that referenced this issue Jul 19, 2017
If the .listen() hasn't been called on the server, there is no handle
object. In this case use null as the triggerAsyncId.

Fixes: #13548
PR-URL: #13938
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>
Fishrock123 pushed a commit that referenced this issue Jul 19, 2017
In the case where triggerAsyncId is null it should default to the
current executionAsyncId. This worked but as a side-effect the resource
object was changed too.

This fix also makes the null check more strict. EmitInitS is not a
documented API, thus there is no reason to be flexible in its input.

Ref: #13548 (comment)
PR-URL: #14026
Reviewed-By: Refael Ackermann <refack@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
async_hooks Issues and PRs related to the async hooks subsystem. confirmed-bug Issues with confirmed bugs. regression Issues related to regressions.
Projects
None yet
Development

No branches or pull requests

6 participants