Async Hooks do not recognize execution contexts created when processing thenables

[medikoo]

Promise.all to observe input promises, invokes promise.then in next event loop, at least it's what stack traces show in both Node.js and Google Chrome.

Still Async Hooks see it as same execution context, it can be seen by running following code:

const async_hooks = require('async_hooks');

async_hooks.createHook({ init() {} }).enable();

Promise.all([
  {
    then() {
      console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'thenable.then invoked by Promise.all');
      console.trace('thenable.then invoked by Promise.all');
    },
  },
]);

console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'Main');
console.trace('Main');

The outcome is:

1 0 'Main'
Trace: Main
    at Object.<anonymous> (/Users/medikoo/Projects/maas/maas-backend/test.js:15:9)
    at Module._compile (internal/modules/cjs/loader.js:689:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Function.Module._load (internal/modules/cjs/loader.js:530:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:266:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:596:3)
1 0 'promise.then invoked by Promise.all'
Trace: promise.then invoked by Promise.all
    at Object.then (/Users/medikoo/Projects/maas/maas-backend/test.js:9:15)
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at Function.Module.runMain (internal/modules/cjs/loader.js:745:11)
    at startup (internal/bootstrap/node.js:266:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:596:3)

I've stumbled on that when trying to configure long stack trace solution for Node.js, and was dealing with custom promise implementations.

I believe that's not expected.

• Version: v10.9.0 (observable also on v8)
• Platform: macOs 10.13.6 (17G65)

[medikoo]

As I see, it goes down to Promise.resolve:

const async_hooks = require('async_hooks');

async_hooks.createHook({ init() {} }).enable();

Promise.resolve({
  then() {
    console.log(
      async_hooks.executionAsyncId(),
      async_hooks.triggerAsyncId(),
      'thenable.then invoked by Promise.resolve'
    );
    console.trace('thenable.then invoked by Promise.resolve');
  },
});

console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'Main');
console.trace('Main');

Produces:

1 0 'Main'
Trace: Main
    at Object.<anonymous> (/Users/medikoo/Projects/maas/maas-backend/test.js:17:9)
    at Module._compile (internal/modules/cjs/loader.js:689:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Function.Module._load (internal/modules/cjs/loader.js:530:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:266:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:596:3)
1 0 'promise.then invoked by Promise.resolve'
Trace: promise.then invoked by Promise.resolve
    at Object.then (/Users/medikoo/Projects/maas/maas-backend/test.js:12:13)
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at Function.Module.runMain (internal/modules/cjs/loader.js:745:11)
    at startup (internal/bootstrap/node.js:266:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:596:3)

[firedfox]

1. Installing async hooks via async_hooks.createHook enables promise execution tracking.
   As described here.

2. Passing { then: Function } to Promise.all or Promise.resolve triggers then in current event loop because there is no Promise before then.

I think this is how to produce what you expected:

const async_hooks = require('async_hooks');

async_hooks.createHook({ init() {} }).enable();

console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'Main');
Promise.all([
  Promise.resolve().then(() => {
    console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'promise.then invoked by Promise.all');
    console.trace('promise.then invoked by Promise.all');
  }),
]);

Produces:

1 0 'Main'
7 6 'promise.then invoked by Promise.all'
Trace: promise.then invoked by Promise.all
    at Promise.all.Promise.resolve.then (/Users/firedfox/tmp/test.js:9:13)
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at Function.Module.runMain (internal/modules/cjs/loader.js:745:11)
    at startup (internal/bootstrap/node.js:236:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:560:3)

[medikoo]

@firedfox indeed I forgot about async_hooks.createHook({..}).enable() to make posted test case fully reliable. Still it was just mistake in code example (I've reedited it to avoid further confusion), adding that initialization doesn't help, outcome remains same.

Note: it's about an extra event loop in which then method is executed and not its callback. Your example tests the latter, that works without issues and it's not a concern here.

[medikoo]

I've updated examples a bit more to better expose that we deal with different event loop, which is not reflected by async_hooks.executionAsyncId()

[firedfox]

IMO, it's because { then: Function } you used is not a promise.then but just plain object.then.
The Promise.resolve() method returns a Promise object. So Promise.resolve().then gives us a promise.then. All other ways that return a Promise object should produce the same result.

Sorry I finally understand what you mean. You are right. It seems to be a problem.

const async_hooks = require('async_hooks');

async_hooks.createHook({ init() {} }).enable();

Promise.all([
  {
    then() {
      console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'promise.then invoked by Promise.all');
      console.trace('promise.then invoked by Promise.all');
    },
  },
]);

process.nextTick(() => {
  console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'nextTick');
  console.trace('nextTick');
});

console.log(async_hooks.executionAsyncId(), async_hooks.triggerAsyncId(), 'Main');

Produces:

1 0 'Main'
Trace: Main
    at Object.<anonymous> (/Users/firedfox/tmp/test.js:20:9)
    at Module._compile (internal/modules/cjs/loader.js:689:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Function.Module._load (internal/modules/cjs/loader.js:530:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:236:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:560:3)
8 1 'nextTick'
Trace: nextTick
    at process.nextTick (/Users/firedfox/tmp/test.js:16:11)
    at process._tickCallback (internal/process/next_tick.js:61:11)
    at Function.Module.runMain (internal/modules/cjs/loader.js:745:11)
    at startup (internal/bootstrap/node.js:236:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:560:3)
1 0 'promise.then invoked by Promise.all'
Trace: promise.then invoked by Promise.all
    at Object.then (/Users/firedfox/tmp/test.js:9:15)
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at Function.Module.runMain (internal/modules/cjs/loader.js:745:11)
    at startup (internal/bootstrap/node.js:236:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:560:3)

[medikoo]

@firedfox I don't understand how your comment is relevant to this report?

Again, bug is that async contexts in which thenable.then is called by any native Promise method is not exposed by async_hooks as expected.

This bug makes async_hooks unreliable for cases when we work with custom thenables, and that's not that uncommon, e.g. you can find them in quite popular knex library.
With current state of things, it's not possible to get information about trigger async context, within scope of that then method invocation (when invoked by native Promise method)

As long as it's the case, reliable long stack trace solution cannot be configured using async_hooks.

[jasnell]

I believe the issue here is more about the fact that async_hooks does not currently track thenables in the same way that it tracks actual Promise instances. Because the thenable here is not actually visible to async_hooks, it is not able to do the appropriate context association.

[medikoo]

Because the thenable here is not actually visible to async_hooks, it is not able to do the appropriate context association.

I'm not sure if it's a valid explanation, as here it's native Promise.all that's responsible for introduction of new async context, and not thenable that's passed to it.

I suppose that if async_hooks can monitor moments in which callbacks passed to promise.then are invoked (by promise.then internals), same way it should be able to monitor invocations of thenable.then (which are made within Promise.resolve internals)

I take that code responsible for that is in C++ layer (?)

[jasnell]

The state of Promise resolution is tracked using an API at the C++ layer. Thenables do not tap into that mechanism and therefore cannot be tracked the same way as normal promises.

You can visualize the difference using the clinic bubbleprof tool

thenable:

Promise.all([
  {
    then() {
      console.log('a')
    }
  }
])

https://upload.clinicjs.org/public/7c8bcbc1db0fdaf015a34941a1fbfa0b32db378f8d6b5b06db9031df7cd48f76/171215.clinic-bubbleprof.html

promise:

Promise.all([
  Promise.resolve('a').then(console.log)
])

https://upload.clinicjs.org/public/8a263182a3c9a50c2d4066aa22eae417cb5c6366e9977e2fef6560d7ff6f87e7/171277.clinic-bubbleprof.html

If you explore the differences between the two call graphs, you'll see that the thenable is not seen by V8 or Node.js as a promise and therefore cannot be tracked in the same way.

[medikoo]

I don't see those two examples equivalent. In first one console.log is within a body of then, and in second one it makes a body of a callback passed to then, and that's a quite big difference.
Technically first example involves two event loops, and second three event loops.

Anyway to make sure I understand you right - you acknowledge there's an event loop introduced by native Promise internals (so V8) to resolve thenables, but want to point that it's not exposed properly outside, so cannot picked by async_hooks, and therefore it's not possible to fix this issue?

[devsnek]

async_hooks tracks promises, not the event loop's promise job queue.

[medikoo]

async_hooks tracks promises, not the event loop's promise job queue.

Ok, clear, so event loops tracking is made purely by following promise instances, which in turn makes it not perfectly complete (as not all enqueued jobs within V8 are mapped to new async contexts).

Question is whether this should be considered a feature or a bug? :)

[stephenh]

@medikoo I'm just wandering by, but does this comment in the google stackdriver tracer address/work around your observation?

https://github.com/GoogleCloudPlatform/cloud-trace-nodejs/blob/master/src/cls/async-hooks.ts#L62

[medikoo]

@stephenh it doesn't look related to this issue. PROMISE type reflects promise initialization, and here issue is that we miss tracking of execution contexts created by V8 for processing thenables (those do not involve promise creation).

[Trott]

Question is whether this should be considered a feature or a bug? :)

@nodejs/async_hooks Thoughts? This is a bug that should be fixed and/or a feature that needs to be implemented? Or this is working as intended and can be closed?