APM tracing with async_hooks broken on Node 10.

[mcollina]

• Version: 10.0.0 and master
• Platform: all
• Subsystem: async_hooks

The following represent a pattern very commonly used by APMs:

'use strict'

const http = require('http')
const sleep = require('util').promisify(setTimeout)
const asyncHooks = require('async_hooks')
const asyncHook = asyncHooks.createHook({init, destroy})
const transactions = new Map()

asyncHook.enable()

function getCLS () {
  const asyncId = asyncHooks.executionAsyncId()
  return transactions.has(asyncId) ? transactions.get(asyncId) : null
}

function setCLS (value) {
  const asyncId = asyncHooks.executionAsyncId()
  transactions.set(asyncId, value)
}

function init (asyncId, type, triggerAsyncId, resource) {
  transactions.set(asyncId, getCLS())
}

function destroy (asyncId) {
  transactions.delete(asyncId)
}

http.createServer(function (req, res) {
  handler().then(function (data) {
    res.end(JSON.stringify(data))
  }).catch(function (err) {
    res.statusCode = 500
    res.end(err.stack)
  })
}).listen(3000)

var counter = 0

async function handler () {
  setCLS(counter++)
  await sleep(10)
  return { cls: getCLS() }
}

Correct behavior (node 8.11.1):

$ curl localhost:3000
{"cls":0}

master:

$ curl localhost:3000
{"cls":null}

[mcollina]

cc @nodejs/v8 @bmeurer @BridgeAR @nodejs/diagnostics

[AndreasMadsen]

Pretty sure it is because of #20274

[mcollina]

#20467 does not fix this. See my comment in the thread.

[ofrobots]

The problem is that after the await asyncHooks.executionAsyncId is 0.
EDIT: Actually the reduced test case might be red herring.. still looking.

```js 'use strict'; const asyncHooks = require('async_hooks'); const sleep = require('util').promisify(setTimeout);

async function main() {
console.log(asyncHooks.executionAsyncId());
await sleep(10);
console.log(asyncHooks.executionAsyncId());
}

main().catch(console.error);

</details>

[Qard]

I pointed out this exact issue already. #20274 (comment)

[mcollina]

#20274 (comment) from @bmeurer states that #20467 fixes it. @BridgeAR pointed out that it is a different bug in #20467 (comment).

I'm leaning towards this being a different bug. It would be better if you could verify that as well @Qard.

[ofrobots]

It is a separate issue. The fix from #20274 fix the async id being 0 after an await.

The choregraphy of async events seems to be slightly different in master, that causes the break even after the fix from #20274 is applied.

async function handler () {
  // this line executes in async id 12
  setCLS(counter++)
  await sleep(10)
  // this line executes in async id 14
  return { cls: getCLS() }
}

Adding a log to the init hook:

handler started in 12
init 15 triggerAsyncId 12 getCLS() null
eid: 12 setting transaction to 0
init 16 triggerAsyncId 12 getCLS() null
init 17 triggerAsyncId 12 getCLS() 0
init 18 triggerAsyncId 12 getCLS() 0
init 19 triggerAsyncId 12 getCLS() 0
init 20 triggerAsyncId 12 getCLS() 0
init 21 triggerAsyncId 12 getCLS() 0
init 22 triggerAsyncId 17 getCLS() null
resuming from await in 14
init 23 triggerAsyncId 14 getCLS() null

IOW, the resource 14 was created before the execution of handler started. The init for 14 runs a bit too early.

In Node 9 and older, the 'async resume' resource doesn't get initialized as early, so things end up working.

I think we need a bisect to figure out why this happened.

[MayaLekova]

Looking into this and will try to do a new fix soon, which will probably include a proper fix for #20274.

[mcollina]

@MayaLekova let me know when you have a patch to test. I can get it tested quickly.

[MayaLekova]

@mcollina Please take a look at this commit - it basically reverts @bmeurer 's optimizations related to the async hooks.

Some background: we tried implementing a fix on top of the current V8 head without success. So the current action plan is:

1. land this revert in V8 asap (if you confirm it fixes this bug and the previous one);
2. write detailed tests on V8 side;
3. redo the optimization, this time making sure we don't break async hooks' stability.

Thanks for the cooperation!

[mcollina]

@MayaLekova that commit does not land cleanly on recent master, can you rebase?

[MayaLekova]

@mcollina Does it merge cleanly now?
Still, please note that this introduces a lot of changes from V8 which are not currently in Node.js and this patch is only meant for local merge & verification, not committing any part of it yet.

[mcollina]

@MayaLekova https://github.com/MayaLekova/node/tree/fix-20516 is still diverging a lot from Node.js master. I suspect it's done on top of a newer version of V8. The PR fixes the bug, good job!

[bmeurer]

LGTM on including the backport from @mcollina

[MayaLekova]

@mcollina Currently not working on the backport, will be able to look at this again tomorrow.
Benedikt is the better source of truth on this issue, but the backport seems fine to me as well.

[mcollina]

Awesome :).