async_hooks.currentId() sometimes reports the wrong id during PromiseReactionJob

[hayes]

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

[mscdex]

/cc @nodejs/async_hooks

[AndreasMadsen]

I investigated the issue, it is because AsyncHooks::ExecScope exec_scope is never created in kBefore and exec_scope.Dispose() is never called in kAfter. The issue should only exist for promises.

[AndreasMadsen]

So here is a conundrum, how can we make the following work without having PromiseHooks for async_hooks be consistently enabled?

const p = new Promise((resolve) => resolve(1));
p.then(function () {
  async_hooks.currentId();
});

/cc @matthewloring

[addaleax]

So here is a conundrum, how can we make the following work without having PromiseHooks for async_hooks be consistently enabled?

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]

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?

The user can still listen to just before and after. That would be relevant for domain or if one wants to just measure sync timing.

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.

Hmm, how expensive are the internal fields? Could we consistently have a cheap PromiseHook that just assign the id and memorizes the triggerId (parent promise id)? This requires incrementing a counter and looking up a value, running exec_scope in kBefore and kAfter also shouldn't be expensive, it's just push and pop.

If async_hooks is enabled we then do the expensive resource setup, before emit, and after emit.

[matthewloring]

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

#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 when async_hooks doesn't have enabled hooks.

[Trott]

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

@Trott No, it is a limitation of PromiseHooks and unfortunately it is not a big priority to fix it :(

[Trott]

I'm going to close this. PR welcome. Feel free to re-open or comment if you think this should remain open.

[AndreasMadsen]

I’m reopening. It is a valid bug, it is just very hard to fix.

[apapirovski]

As far as I can tell this is resolved in the latest version of v8.x. Closing.