Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Do not filter out stack trace for unhandled rejections #10784

Closed
vkrol opened this issue Nov 5, 2020 · 32 comments
Closed

Do not filter out stack trace for unhandled rejections #10784

vkrol opened this issue Nov 5, 2020 · 32 comments

Comments

@vkrol
Copy link
Contributor

vkrol commented Nov 5, 2020

🐛 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
@arunpugahz
Copy link

arunpugahz commented Jan 18, 2021

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

@sclarson
Copy link

Also experienced this in 15 and the downgrade fixed it.

@justsml
Copy link

justsml commented Feb 16, 2021

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?

@Paradoxor
Copy link

+1

1 similar comment
@3runo3atista
Copy link

+1

@SimenB
Copy link
Member

SimenB commented Mar 31, 2021

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

@3runo3atista
Copy link

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
Copy link
Contributor Author

vkrol commented Apr 14, 2021

@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
Copy link

I'm using handling it with:

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

in jest.setup.js

@LvChengbin
Copy link

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

@nour-sidaoui
Copy link

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

@vicary
Copy link

vicary commented Jul 14, 2021

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

@Pomax
Copy link

Pomax commented Oct 23, 2021

@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
Copy link

vicary commented Oct 23, 2021

@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
Copy link

Pomax commented Oct 23, 2021

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
Copy link
Contributor

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
Copy link

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
Copy link
Contributor

@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
Copy link

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
Copy link
Contributor

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
Copy link

Pomax commented Dec 8, 2021

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
Copy link
Contributor

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.

dbjorge added a commit to microsoft/accessibility-insights-web that referenced this issue Jan 14, 2022
#5066)

#### Details

This PR adds a new setup step to each of our test suites which forces Jest to flush all `Promise`s in a globally applied `afterEach` fixture.

This forces Jest to flush any pending resolved Promises that a test might have forgotten to handle *before* Jest considers that test to be completed. That way, if a test leaks a Promise, the resulting error message gets logged as a failure in the responsible test and includes a nice, Jest-formatted stack, instead of test "passing" and the error as a Node UnhandledProjmiseRejectionWarning with no stack or test context.

This is intended to work in tandem with #5061, allowing it to go in as a last-resort while mitigating the poor logging that we get if it's actually triggered (by avoiding having it need to trigger in the common case)

##### Motivation

Avoids silent test failures (eg, the one that currently exists in `injector-controller.test.ts`)

##### Context

jestjs/jest#10784 (comment)

#### Pull request checklist
<!-- If a checklist item is not applicable to this change, write "n/a" in the checkbox -->
- [n/a] Addresses an existing issue: #0000
- [x] Ran `yarn fastpass`
- [x] Added/updated relevant unit test(s) (and ran `yarn test`)
- [x] Verified code coverage for the changes made. Check coverage report at: `<rootDir>/test-results/unit/coverage`
- [x] PR title *AND* final merge commit title both start with a semantic tag (`fix:`, `chore:`, `feat(feature-name):`, `refactor:`). See `CONTRIBUTING.md`.
- [n/a] (UI changes only) Added screenshots/GIFs to description above
- [n/a] (UI changes only) Verified usability with NVDA/JAWS
@ItamarGronich
Copy link

ItamarGronich commented Jan 24, 2022

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
Copy link
Contributor

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
Copy link

Pomax commented Jan 26, 2022

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
Copy link
Contributor

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
Copy link
Member

SimenB commented Jan 29, 2022

Happy to take a docs PR 🙂

@github-actions
Copy link

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.

@github-actions github-actions bot added the Stale label Jan 29, 2023
@cameron-martin
Copy link

Not stale

@github-actions github-actions bot removed the Stale label Feb 3, 2023
@benjamingr
Copy link
Contributor

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

@cameron-martin
Copy link

Oops, somebody close it then

Copy link

github-actions bot commented Feb 7, 2024

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Feb 7, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests