executionAsyncId doesn't return expected value in context of process.on('unhandledRejection')

[isaacs]

Version: 12.0.0-pre (78162ad)
Platform: Darwin geegaw.local 18.2.0 Darwin Kernel Version 18.2.0: Thu Dec 20 20:46:53 PST 2018; root:xnu-4903.241.1~1/RELEASE_X86_64 x86_64
Subsystem: async_hooks

https://gist.github.com/isaacs/1f8c5092ba7d67d9a5f4e342ff7778b7

I am building a domain-like implementation to catch errors using async_hooks. However, the executionAsyncId is reset to 0 on an unhandledRejection event, making it impossible for me to know if I ought to handle the error or crash.

The weird thing is that it only fails in this way when the promise rejection is within an async hop, such as a setTimeout. If the promise rejection happens at the top level, then I get the expected value of 1 as the executionAsyncId.

This is preventing me moving node-tap off of core domains. Fewer modules using domains means that it could be deprecated sooner :)

[isaacs]

This is still a problem in 13.3.0. It makes it really tricky to properly report errors when multiple promises are in use.

[ruyadorno]

/cc @jasnell @addaleax

[devsnek]

This is a problem for the unhandledRejection and rejectionHandled events. cc @nodejs/async_hooks

[jasnell]

Hmm yeah, we're not capturing the Async id when things like nextTick or a timer is created it seems. Will definitely need to investigate a fix

[addaleax]

Not sure how timers factor in here. It sounds more like we’d have to enter & exit the async context for the async resource associated with the Promise? That’s doable, but will have non-zero performance impact. Then again, for unhandled rejections a perf impact is maybe actually very acceptable? Also, not sure how #30959 factors in here yet, but i’ll take a look.

[coreyfarrell]

@addaleax According to Async Hooks | Promise execution tracking:

By default, promise executions are not assigned asyncIds due to the relatively expensive nature of the promise introspection API.

I would think unhandledRejection and rejectionHandled would only get accurate asyncId if an async_hook was already enabled, at that point the code has already opted in to the performance penalty?

[addaleax]

@coreyfarrell Right – I’m not suggesting to change that, only make it work when async_hooks are enabled

[isaacs]

Still broken in node 15.

[benjamingr]

@isaacs Makes sense, I am not aware of any work or attempts to fix it?

[benjamingr]

Also isn't this bug just because of the pooling of possibly unhandled rejections and the hop? If so - what happens if we wrap it in an AsyncResource.bind(?

Is context/ids "tracked" when we get the promise back from V8?

---

I am building a domain-like implementation to catch errors using async_hooks. However, the executionAsyncId is reset to 0 on an unhandledRejection event, making it impossible for me to know if I ought to handle the error or crash.

Wait actually I just read that and I'm terrified :D What is the motivation to not crash on unhandled rejections? Do you similarly not crash on uncaught exceptions? (You can always parse the stack trace but that's also pretty scary)

[isaacs]

It makes it impossible for tests to detect where the rejection came from, so it just looks like an unfinished test.

const t = require('tap')

t.test('reject promise', t => {
  Promise.resolve().then(() => {
    Promise.reject(new Error('boom'))
  })
})

/*
TAP version 13
Error: boom
    at /Users/isaacs/dev/npm/cli/throw.js:5:20
    at processTicksAndRejections (node:internal/process/task_queues:93:5)
# Subtest: reject promise
    not ok 1 - test unfinished
      ---
      stack: |
        Object.<anonymous> (throw.js:3:3)
      test: reject promise
      at:
        line: 3
        column: 3
        file: throw.js
        function: Object.<anonymous>
      source: |
      
        t.test('reject promise', t => {
        --^
          Promise.resolve().then(() => {
            Promise.reject(new Error('boom'))
      ...
    
    1..1
    # failed 1 test
not ok 1 - reject promise # time=16.584ms

1..1
# failed 1 test
# time=19.763ms
*/

When you have a lot of tests, and one of the promises gets rejected unexpectedly, it can be a huge pain to track down.

[isaacs]

Compare with tap's behavior when the error is trackable, either because the promise is returned to the test harness, or the error is thrown outside a promise chain:

const t = require('tap')

t.test('reject promise', t => {
  return Promise.reject(new Error('boom'))
})

t.test('throw error', t => {
  setTimeout(() => { throw new Error('boom') })
})

/*
TAP version 13
# Subtest: reject promise
    not ok 1 - boom
      ---
      stack: |
        Test.<anonymous> (throw.js:4:25)
      at:
        line: 4
        column: 25
        file: throw.js
        function: Test.<anonymous>
      tapCaught: returnedPromiseRejection
      test: reject promise
      source: |
        t.test('reject promise', t => {
          return Promise.reject(new Error('boom'))
        ------------------------^
        })
      ...
    
    1..1
    # failed 1 test
not ok 1 - reject promise # time=18.705ms

# Subtest: throw error
    not ok 1 - boom
      ---
      stack: |
        Timeout._onTimeout (throw.js:8:28)
      at:
        line: 8
        column: 28
        file: throw.js
        function: Timeout._onTimeout
      tapCaught: uncaughtException
      test: throw error
      source: |
        t.test('throw error', t => {
          setTimeout(() => { throw new Error('boom') })
        ---------------------------^
        })
      ...
    
    1..1
    # failed 1 test
not ok 2 - throw error # time=5.825ms

1..2
# failed 2 of 2 tests
# time=28.53ms
*/

[benjamingr]

Thanks @isaacs that helps.

When you have a lot of tests, and one of the promises gets rejected unexpectedly, it can be a huge pain to track down.

Why? Isn't there a stack trace and error pointing to the rejected promise?

---

I'm also surprised this worked with domains before (since the hooks didn't run on the promise's domain). I think a fix should be pretty easy? (similar to #36082 ).

[sajal50]

I believe this issue is very similar to #37244.

[benjamingr]

Fixed in #37281 (comment) , thanks @sajal50 !

[isaacs]

Thank you @sajal50 for fixing this! It's been a thorn in my shoe for so long. <3

[sajal50]

Glad I could help, @isaacs. 😄