async_hooks.triggerAsyncId() don't return the expected value in context of the connection callback of net.Server

[tingshao]

• Version: 8.x and 10.x
• Platform: all supported
• Subsystem:

async_hooks.triggerAsyncId() is expected to return the async id of the connection in the onconnection callback of server. This was specifically declared in the example of the async_hooks documentation which can be found here.

However, after testing the example using both node 10.3.0 and 8.11.2, I found the result was different. Below is the code and output of my test.
my code:

let net = require('net');
let async_hooks = require('async_hooks');
let fs = require('fs');

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
  	fs.writeSync(1, `init hook: ${type}, asyncID: ${asyncId}, triggerID: ${triggerAsyncId}\n`);
  },
  before(asyncId) {
    fs.writeSync(1, `before hook: asyncID: ${asyncId}\n`);
  },
  after(asyncId) {
    fs.writeSync(1, `after hook: asyncId: ${asyncId}\n`);
  },
}).enable();
const server = net.createServer((conn) => {
  // The resource that caused (or triggered) this callback to be called
  // was that of the new connection. Thus the return value of triggerAsyncId()
  // is the asyncId of "conn".
  // fs.wriateSync(1, '-- conn callback, triggerAsyncId:', async_hooks.triggerAsyncId());
  let tid = async_hooks.triggerAsyncId();
  let eid = async_hooks.executionAsyncId();
  fs.writeSync(1, `-- conn callback, triggerAsyncId: ${tid}, executionAsyncId: ${eid}\n`);
}).listen(8000, () => {
  // Even though all callbacks passed to .listen() are wrapped in a nextTick()
  // the callback itself exists because the call to the server's .listen()
  // was made. So the return value would be the ID of the server.
  let tid = async_hooks.triggerAsyncId();
  let eid = async_hooks.executionAsyncId();
  fs.writeSync(1, `-- listen callback, triggerAsyncId: ${tid}, executionAsyncId: ${eid}\n`);
});

if I connect the server with another terminal by connect localhost 8000, then the output is:

init hook: TCPSERVERWRAP, asyncID: 5, triggerID: 1
init hook: TickObject, asyncID: 6, triggerID: 5
before hook: asyncID: 6
-- listen callback, triggerAsyncId: 5, executionAsyncId: 6
after hook: asyncId: 6
init hook: TCPWRAP, asyncID: 7, triggerID: 5
before hook: asyncID: 5
-- conn callback, triggerAsyncId: 1, executionAsyncId: 5
after hook: asyncId: 5
before hook: asyncID: 7
init hook: TickObject, asyncID: 8, triggerID: 7
after hook: asyncId: 7
before hook: asyncID: 8
init hook: TickObject, asyncID: 9, triggerID: 8
init hook: TickObject, asyncID: 10, triggerID: 8
after hook: asyncId: 8
before hook: asyncID: 9
after hook: asyncId: 9
before hook: asyncID: 10
after hook: asyncId: 10
before hook: asyncID: 7
after hook: asyncId: 7

Please note the line -- conn callback, triggerAsyncId: 1, executionAsyncId: 5. It means in the connection callback, the triggerAsyncId is 1 instead of 7 which is expected.

I investigated the code, and found the root cause is:
When the callback is made, it was made on the TCPWrap instance of the server, and the server's triggerId (1) and asyncId (5) were pushed into the stack, thus lead to this result. While It seems that this mechanism is ok most of the time for normal callbacks, but for this new connection callback, I think we should add some logic to pass the triggerId of the new connection (actually a new TCPWrap instance) to push into the stack. I made a change based on that and verified the result, it could work.

So, I doubt is the issue due to document obsoleted or the code should be changed?
I'd like to make a PR if it is confirmed, thanks.

[apapirovski]

ping @nodejs/async_hooks — not sure what the correct outcome here is. I can see validity to both, depending on how one thinks about it. Either way, seems like the documentation doesn't match the reality so one of the two needs to be updated.

[Jeff-Lewis]

This has broken cls-hooked since 8.10.0. It's been raised as an issue in cls-hooked and it's probably affecting more people who are unaware of it.

Just to confirm what @tingshao stated above, when I compare logs of 8.9.4 (left) to 8.10.0 (right), the change from TCPWRAP to TCPSERVERWRAP can be seen.

[Jeff-Lewis]

@nodejs/async_hooks @AndreasMadsen @addaleax What are your thoughts on this? It appears the documentation doesn't match the behavior or are we missing something?

If so, do we have more options than this?

1. Update the documentation and support the current behavior going forward.
   or
2. Change the behavior and then potentially back-port the fix to node 8?

Thank you!

[kibertoad]

@AndreasMadsen @addaleax Looks like this was never addressed. I assume at this point it's too late to expect behaviour change, so probably simple documentation change would suffice?

[addaleax]

@kibertoad Well, basically what @apapirovski said … I can see the validity of either point of view. I think what this issue is waiting for is for somebody to have a strong enough opinion to either change the docs or change the behavior here, but yeah, a documentation change would definitely suffice.