Repository navigation
async_hooks.currentId() sometimes reports the wrong id during PromiseReactionJob #13427
Description
- Version: v8.0.0
- Platform: Wed Dec 31 14:42:53 PST 2014 x86_64 x86_64 x86_64 GNU/Linux
- Subsystem: async_hooks
Sometimes async_hooks.currentId() returns the wrong id. as @AndreasMadsen pointed out here
The async_hooks.currentId() should just be the id from the latest before emit that hasn't been closed by the after emit.
Here is a simple example that shows this is not always working correctly with promises.
const async_hooks = require('async_hooks');
const fs = require('fs')
let indent = 0;
async_hooks.createHook({
init(asyncId, type, triggerId, obj) {
const cId = async_hooks.currentId();
fs.writeSync(1, ' '.repeat(indent) +
`${type}(${asyncId}): trigger: ${triggerId} scope: ${cId}\n`);
},
before(asyncId) {
fs.writeSync(1, ' '.repeat(indent) + `before: ${asyncId}\n`);
indent += 2;
},
after(asyncId) {
indent -= 2;
fs.writeSync(1, ' '.repeat(indent) + `after: ${asyncId}\n`);
},
destroy(asyncId) {
fs.writeSync(1, ' '.repeat(indent) + `destroy: ${asyncId}\n`);
},
}).enable();
setTimeout(function () {
Promise.resolve().then(() => {
fs.writeSync(1, ' '.repeat(indent) + `current id in then: ${async_hooks.currentId()}\n`);
})
})which outputs:
Timeout(2): trigger: 1 scope: 1
TIMERWRAP(3): trigger: 1 scope: 1
before: 3
before: 2
PROMISE(4): trigger: 2 scope: 2
PROMISE(5): trigger: 2 scope: 2
after: 2
after: 3
before: 5
current id in then: 0
after: 5
destroy: 2
Edited by @ChALkeR: mistype/spelling fix.
Activity
mscdex commentedon Jun 3, 2017
/cc @nodejs/async_hooks
[-]assync_hooks.currentId() sometimes reports the wrong id during PromiseReactionJob[/-][+]async_hooks.currentId() sometimes reports the wrong id during PromiseReactionJob[/+]AndreasMadsen commentedon Jun 3, 2017
I investigated the issue, it is because
AsyncHooks::ExecScope exec_scopeis never created inkBeforeandexec_scope.Dispose()is never called inkAfter. The issue should only exist for promises.AndreasMadsen commentedon Jun 3, 2017
So here is a conundrum, how can we make the following work without having PromiseHooks for
async_hooksbe consistently enabled?/cc @matthewloring
addaleax commentedon Jun 3, 2017
Since Node always runs the microtask queue manually, one thing that we could do is to only AsyncWrap the entire queue; that will give you slightly inconsistent async ids, because multiple Promises might share one, but since one can’t really attach any meaning to the ids that one didn’t witness
init()ing that should be okay?I’ll try to get some code together for that.
I think I’ve already said this a couple times, but I really would like to not use
PromiseHooks when we don’t know that we’ll use them, especially now that we’ve seemed to agree on creating extra resource objects for each single promise.AndreasMadsen commentedon Jun 3, 2017
The user can still listen to just
beforeandafter. That would be relevant fordomainor if one wants to just measure sync timing.Hmm, how expensive are the internal fields? Could we consistently have a cheap
PromiseHookthat just assign theidand memorizes thetriggerId(parent promiseid)? This requires incrementing a counter and looking up a value, runningexec_scopeinkBeforeandkAfteralso shouldn't be expensive, it's justpushandpop.If
async_hooksis enabled we then do the expensive resource setup,beforeemit, andafteremit.matthewloring commentedon Jun 4, 2017
@addaleax I don't think I fully understand your suggestion but the idea of slightly inconsistent ids is scary. When you say AsyncWrap the entire queue do you mean fire a single before/after event for all events processed in a single flush of the microtask queue?
AndreasMadsen commentedon Jun 16, 2017
#13585 was landed. Please keep this open, as it #13585 only solves some issues. In particular it doesn't solve that
async_hooks.currentId()/async_hooks.executionAsyncId()is wrong whenasync_hooksdoesn't have enabled hooks.Trott commentedon May 31, 2018
@AndreasMadsen or anyone else on @nodejs/async_hooks: Is there a PR or anything to watch (other than this issue) to fix the remaining issues mentioned in #13427 (comment)?
AndreasMadsen commentedon May 31, 2018
@Trott No, it is a limitation of PromiseHooks and unfortunately it is not a big priority to fix it :(
Trott commentedon May 31, 2018
I'm going to close this. PR welcome. Feel free to re-open or comment if you think this should remain open.
AndreasMadsen commentedon May 31, 2018
I’m reopening. It is a valid bug, it is just very hard to fix.
apapirovski commentedon Nov 29, 2018
As far as I can tell this is resolved in the latest version of v8.x. Closing.