jest: Do not filter out stack trace for unhandled rejections

šŸ› 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);
});
  1. 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

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Reactions: 52
  • Comments: 32 (10 by maintainers)

Commits related to this issue

Most upvoted comments

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

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.

image

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?

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

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

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;
});

@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

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

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.

Hey, saw this in the Node repo

Pull request based on @ItamarGronich 's issue in Node: https://github.com/nodejs/node/pull/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;
});

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);
    }
});

Oops, somebody close it then

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, https://github.com/facebook/jest/pull/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.

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.

@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));
});

Iā€™m using handling it with:

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

in jest.setup.js

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