async_hooks: promise callbacks have no context unless init hook present

[ofrobots]

While going through some examples I ran into the following buggy behavior in async_hooks. Promise callbacks don't seem to have context by default. Even more surprisingly Adding a dummy init makes the context appears as if by magic!

I intend to look at this in detail later, but opening the issue now in case someone else wants to take a peek.

const ah = require('async_hooks');

let hooks;
switch (process.argv[2]) {
  default:
  console.log('run this test with a numeric argument');
  process.exit(1);

  case '1':
    hooks = {}; // no hooks
    break;

  case '2':
    hooks = { init() {} }; // empty init hook
    break;
}

ah.createHook(hooks).enable();
Promise.resolve(1729).then(() => {
  console.log(`then callback ran with eid ${ah.executionAsyncId()} tid ${ah.triggerAsyncId()}`);
});

Unlike timers, and other Node.js async APIs (e.g. fs.read), by default the triggerAsyncId is always 0 (i.e. missing context) inside the then callback. The behaviour is the same when no hooks are present or an empty set of hooks are present.

❯ node p2.js 1
then callback ran with eid 1 tid 0

Attaching an empty init hook magically makes the context appear:

❯ node p2.js 2
then callback ran with eid 7 tid 6

Replacing the promise example with a setTimeout or fs.readFile has the things working correctly in all scenarios.

// the rest of the code is the same
setTimeout(() => {
  console.log(`timeout callback ran with eid ${ah.executionAsyncId()} tid ${ah.triggerAsyncId()}`);
}, 1);

~/tmp/ah
❯ node p2.js 1
timeout callback ran with eid 6 tid 1

~/tmp/ah
❯ node p2.js 2
timeout callback ran with eid 6 tid 1

[ofrobots]

/cc @nodejs/diagnostics @nodejs/async_hooks

[AndreasMadsen]

@ofrobots Yep, it is a known issue. It is because PromiseWrap isn't setup unless a hook is used and for executionAsyncId or triggerAsyncId we need context information form PromiseWrap.

Unfortunately, we can't enable PromiseWrap constantly because assigning the asyncId to the promise resource object is too expensive.

As I have suggested previously, it would be nice if PromiseWrap allowed us to assign an asyncId and replaced the parentPromise with triggerAsyncId.

[ofrobots]

Yep, got it. The overhead of promise hooks is quite a bummer indeed. I agree that we should not add the promise hook overhead to applications that are not interested in monitoring asynchronous flow. This was not clear in the docs, so I have gone ahead and opened #18540 to fix this.

[ofrobots]

/cc @gsathya, @bmeurer for the feedback above about assigning asyncId.

[bmeurer]

If we reorganize the PromiseHook API, we could teach V8 to assign these IDs for all promises, always (at least when running in Node).

[gsathya]

Unfortunately, we can't enable PromiseWrap constantly because assigning the asyncId to the promise resource object is too expensive.

Sorry for not having the complete context here, but why is assigning an ID to a promise object too expensive?

[ofrobots]

@gsathya assigning the id requires us to enable promise hooks; which are expensive. Basically we need the init hook to be called so that we can assign an id to the promise, and record the trigger (causal) context.

[gsathya]

Ah, so enabling promise hooks to know when to assign an ID is expensive. Assigning an ID isn't.