Do not filter out stack trace for unhandled rejections

[vkrol]

🐛 Bug Report

In strict unhandled rejections mode (https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode), the stack trace of unhandled rejection is not displayed in the console. This mode is default in Node.js 15.

To Reproduce

Steps to reproduce the behavior:

1. Run a test with an unhandled rejection, for example:

test("foo", () => {
  Promise.reject(new Error());
  expect(1).toBe(1);
});

2. The output is:

 RUNS  ./index.test.js
node:internal/process/promises:218
          triggerUncaughtException(err, true /* fromPromise */);
          ^

[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "Error".] {
  code: 'ERR_UNHANDLED_REJECTION'
}

Expected behavior

The stack trace is displayed in the console.

Link to repl or repo (highly encouraged)

https://github.com/vkrol/jest-unhandled-rejection-stack-trace

envinfo

  System:
    OS: Windows 10 10.0.19042
    CPU: (8) x64 Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz
  Binaries:
    Node: 15.1.0 - ~\scoop\apps\nodejs\current\node.EXE
    Yarn: 1.22.5 - ~\scoop\apps\yarn\current\Yarn\bin\yarn.CMD
    npm: 7.0.8 - ~\scoop\apps\nodejs\current\npm.CMD
  npmPackages:
    jest: 26.6.3 => 26.6.3

[arunpugahz]

+1
Happened to me with the node version 15
I downgraded the node to 14.15.4, the issue is resolved

[sclarson]

Also experienced this in 15 and the downgrade fixed it.

[justsml]

This is such a frustrating default behavior.
Usually I can quickly figure out the location of the error, but today I've been working on the wrong area of my app.

Turns out the bug wasn't caused by my code changes, but an upgraded dependency in unrelated code...

I had to use VS Code debugger to trap the error. It was pretty frustrating to find all the line number details I'd expect were there. They were simply dropped by node+jest's output.

Is there a way to let users know the risk of using NODE_OPTIONS="--unhandled-rejections=strict" ?

Or is there a node.js option to make the crash behavior less user-hostile?

[Paradoxor]

+1

[3runo3atista]

+1

[SimenB]

Does --expand not show the full trace? If not, that's a bug

[3runo3atista]

Does --expand not show the full trace? If not, that's a bug

Thanks your hint + (https://jestjs.io/docs/troubleshooting#debugging-in-vs-code) helped me solve my issue.
I am running "jest": "26.6.3" with node v15.12.0

I was using jest.fn().mockRejectedValue() that returns a Promise for a "sync" function.

[vkrol]

@SimenB

Does --expand not show the full trace? If not, that's a bug

No, this flag doesn't help. What kind of flag is that? I can't find any mention of it anywhere?

[TheHalcyonSavant]

I'm using handling it with:

process.on('unhandledRejection', (reason, promise) => {
    console.log('unhandledRejection', reason, promise);
});

in jest.setup.js

[LvChengbin]

Currently, you can just use NODE_OPTIONS=--unhandled-rejections=warn yarn test to resolve this problem.

[nour-sidaoui]

@LvChengbin NODE_OPTIONS=--unhandled-rejections=warn npm test saved me!

[vicary]

--unhandled-rejections=warn simply ignores the rejection, how does this resolves the problem of a missing stack trace?

[Pomax]

@vicary it should warn about them, but still keep running. If you want it to warn, and then fail your test suite with a clear error that you can more easily track down, use the warn-with-error-code mode (see the https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode link from the original comment).

For those using jest through npm scripts, that means using something like this:

"cross-env NODE_OPTIONS=\"--experimental-vm-modules --unhandled-rejections=warn-with-error-code\" jest --verbose=false"

Without the unhandled rejection flag, you'd see this:

 RUNS  some/test/file.js
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "Error: some error message here".] {
  code: 'ERR_UNHANDLED_REJECTION'

But using warn-with-error-code gets us this, which is far more useful:

 FAIL  some/error/file.js
  ● Your test title here

    line(where.things[went]).wrong

    Expected something or other

    Received the wrong thing

      123 |
    > 124 |     expect(...)
          |             ^
      125 |       `some failure reason from the actual error thrown`
      126 |

      at Object.<anonymous> (some/test/file.js:124:12)

Test Suites: 1 failed, 1 total
Tests:       1 failed, 0 passed, 1 total
Snapshots:   0 total
Time:        0.123 s, estimated 1 s

[vicary]

@Pomax Thanks for the advise.

Give that I want the test to fail AND have a precise stack trace so I can fix it, instead of letting the it slide and call it a day.

According to the docs, the description of --unhandled-rejections=strict looks more promising then other modes because jest has unhandledRejection set and it's not doing a good job, but it has a working uncaughtException handler in place.

Does it makes sense?

[Pomax]

if strict gets you more information, then I'd recommend creating a parallel "detailed" test script, where npm run test does the regular jest'ing with warn-with-error-code set, and then a secondary npm run test:strict or the like that instead uses the strict mode for rejection handling. That way 99% of the time the regular test runner will do the job you need just fine, but when it doesn't, you have a secondary test command to fall back to.

[nwalters512]

This behavior looks consistent with the default value for Node's --unhandled-rejection option, documented here:

throw: Emit unhandledRejection. If this hook is not set, raise the unhandled rejection as an uncaught exception. This is the default.

This makes it seem like Jest has not attached an unhandledRejection event listener. It looks like Jest should be attaching such a handler here, but maybe I'm incorrectly assuming $j.process is analogous to the process global.

[timritzer]

We found a solution, although I am sure it has a performance impact.

This behavior looks consistent with the default value for Node's --unhandled-rejection option, documented here:

throw: Emit unhandledRejection. If this hook is not set, raise the unhandled rejection as an uncaught exception. This is the default.

This makes it seem like Jest has not attached an unhandledRejection event listener. It looks like Jest should be attaching such a handler here, but maybe I'm incorrectly assuming $j.process is analogous to the process global.

They do attach it. But if you look carefully they restore it after the tests are complete. So what is happening is the tests are completing, they are restoring the (non-existant) event handlers, and then node is blowing up. Since the promise is rejecting after the test suite finishes.

We found a workaround, by flushing the promises after each test, the error is forced to happen exactly where the test fails, and it even marks the test as failed. I am sure it will have a performance impact, so I am testing that a bit.

https://www.npmjs.com/package/flush-promises

const flushPromises = require('flush-promises');

afterEach(async ()=>
{
    try {
        await flushPromises();
    } catch(e) {
        console.log(e);
    }
});

[nwalters512]

@timritzer ah, nice find! That matches up with the fact that the following code will produce an error handled by Jest when await new Promise(...) is there, but will produce an unhandled promise rejection when it's missing:

it('example test', async () => {
    Promise.reject(new Error('error'));
    // Comment out the following line to see an unhandled rejection error
    await new Promise(resolve => setTimeout(resolve, 0));
});

[timritzer]

Yep! Also just did some before/after testing on our admittedly small test base of ~600 tests and 5 snapshot tests. Performance difference was pretty minimal. Ultimately it's just an empty promise that resolves so I can't imagine it will have too much overhead.

[nwalters512]

I did a little more digging - per the Node source code, it looks like Node should be printing a proper stack trace for uncaught exceptions, as long as the rejection reason is an instance of Error:

https://github.com/nodejs/node/blob/09c9e5dea42fd11606f0d8988462e291cbfafd32/lib/internal/process/promises.js#L244

However, for some reason, it seems like errors that are thrown in Jest code aren't actually errors. You can reproduce this easily with the node interpreter. Compare the output of the following scripts:

$ node -e "Promise.reject(new Error('this is an error'));"
[eval]:1
Promise.reject(new Error('this is an error'));
               ^

Error: this is an error
    at [eval]:1:16
    at Script.runInThisContext (node:vm:129:12)
    at Object.runInThisContext (node:vm:305:38)
    at node:internal/process/execution:75:19
    at [eval]-wrapper:6:22
    at evalScript (node:internal/process/execution:74:60)
    at node:internal/main/eval_string:27:3

$ node -e "Promise.reject('this is not an error');"
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "this is not an error".] {
  code: 'ERR_UNHANDLED_REJECTION'
}

The former (which is an actual error) includes a very nice and easy to understand stack trace; the latter (which is not an error) shows the reference to Node internals that the original report in this thread shows. I'm not sure why an error isn't seen as instanceof Error by Node - it could be the fault of Jest, or some unknown polyfill, or something else. But this seems to be the root of why we don't get nice stack traces in Jest.

Interestingly, if you add the following to a script referenced from setupFiles, Node does show a nice stack trace - presumably the default uncaughtException handler is behaving better than the default unhandledRejection code.

process.on('unhandledRejection', (reason) => {
  throw reason;
});

[Pomax]

To explain the "why" at least: Promises do not throw errors on rejection (and never have). Instead, all they do is generate a new, completed promise with the rejected flag set and the rejection data bound so you can get that data out. Rejections themselves are in fact the opposite of an error: they're one of the two well-defined ways in which a promise is expected to complete. However, if something doesn't handle a promise rejection, that's an error and you get an UnhandledRejection error.

[nwalters512]

I think I've narrowed this down to an issue with Jest's jest-environment-node (possibly other environments as well). I added the following log below this line in the Node environment implementation:

const require('console');
console.log('Error prototypes equal? ' + String(Error === global.Error));

When I run Jest, I see the output Prototypes equal? false - which explains why Node doesn't think the promise rejection reason isn't actually an Error and thus doesn't print the error with its stack trace.

As for a fix... let's consider the following simple test case:

describe('index', () => {
    it('has unhandled rejection', () => {
        Promise.reject(new Error('error in test'));
    });
});

If we run that with the latest published version of Jest, we'll see the [UnhandledPromiseRejection ... error without a stack trace.

Now, let's add the following line below this line in the Node environment implementation:

global.Error = Error

Now when we run the above test, we see the actual stack trace:

$ jest --runInBand

 RUNS  src/index.test.js
/path/jest-unhandled-rejection-repro/src/index.test.js:3
    Promise.reject(new Error('error in test'));
                   ^

Error: error in test
    at Object.<anonymous> (/path/jest-unhandled-rejection-repro/src/index.test.js:3:24)
    at Object.asyncJestTest (/path/jest-unhandled-rejection-repro/node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:106:37)
    at /path/jest-unhandled-rejection-repro/node_modules/jest-jasmine2/build/queueRunner.js:45:12
    at new Promise (<anonymous>)
    at mapper (/path/jest-unhandled-rejection-repro/node_modules/jest-jasmine2/build/queueRunner.js:28:19)
    at /path/jest-unhandled-rejection-repro/node_modules/jest-jasmine2/build/queueRunner.js:75:41
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

This isn't perfect - for instance, it doesn't handle someone rejecting a promise with a TypeError or any other class that inherits from Error. If we change the above simple test case to Promise.reject(new TypeError('type error in test')), we're back to the same uninformative error as before:

$ jest --runInBand

 RUNS  src/index.test.js
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

[UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "TypeError: type error in test".] {
  code: 'ERR_UNHANDLED_REJECTION'
}

Copying over the TypeError prototype to the new global object fixes this too, but this feels like playing whack-a-mole. I don't understand Jest environments to know if this is the right fix, or if there's something else that would work better instead.

FWIW, it looks like there's precedence for this kind of change. For instance, #7626 copied over the ArrayBuffer prototype to the environment so that Buffer.from([0x62, 0x75, 0x66, 0x66, 0x65, 0x72]) instanceof ArrayBuffer would be truthy.

@SimenB does this seem like the right fix? I'd be happy to make a PR if so.

[ItamarGronich]

I've opened a bug for nodejs: nodejs/node#41676
Seems like it's a much deeper problem - node doesn't handle "unhandled rejections" when the value is not an error as @nwalters512 has already described.
So the fix i think should come from node and not jest

[benjamingr]

Hey, saw this in the Node repo

Pull request based on @ItamarGronich 's issue in Node: nodejs/node#41682

We likely won't fix the issue of primitives throwing (also raised there, at least I'm personally -1 but other members may feel differently) but I've altered the check for unhandled rejection error logging to check if the error has a .stack property rather than instanceof Error to deal with cross realm errors.

As mentioned previously you can use the 'unhandledRejection' event (on process) to work around it in the meantime. When I designed the hook it was meant to be versatile and enable this sort of use case, you would set it up in globalSetup for example you may choose to:

process.on('unhandledRejection', (reason) => {
  console.log(reason); // log the reason including the stack trace
  throw e;
});

[Pomax]

Even if that PR might land soon, it might be worth updating the docs for now to explain this use, in an easily discoverable location with links to it from other obvious places people will be looking. Worst case, the docs can be reverted a few days from now, but some Node PRs end up taking months of back and forth, and then having those docs updated will make a huge difference to a lot of people =)

[benjamingr]

The PR landed yesterday and will go out with the next v12/v14/v16/v17 versions.

Probably a good idea to update the docs regardless.

[SimenB]

Happy to take a docs PR 🙂

[github-actions]

This issue is stale because it has been open for 1 year with no activity. Remove stale label or comment or this will be closed in 30 days.

[cameron-martin]

Not stale

[benjamingr]

Stale, stale, this was fixed for every non end-of-life version of Node.js :) @cameron-martin

[cameron-martin]

Oops, somebody close it then

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.