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

Unhandled Promise Rejection Logging #3251

Closed
thomashuston opened this issue Apr 4, 2017 · 24 comments
Closed

Unhandled Promise Rejection Logging #3251

thomashuston opened this issue Apr 4, 2017 · 24 comments

Comments

@thomashuston
Copy link
Contributor

thomashuston commented Apr 4, 2017

Do you want to request a feature or report a bug?
feature

What is the current behavior?
When writing unit tests that involve promises, if a developer does not return the promise (or use async/await), uncaught rejections bubble up to Node's default unhandledRejection handler. For example:

image

That's fine, except that when running tests locally, because of the way Jest aggressively clears the console as concurrent test suites finish running, Node's default unhandledRejection logging sometimes gets cleared off the terminal. I've found this to be especially problematic on machines with more CPUs where many tests may be running concurrently.

That can make spotting these errors trickier in development. The default node error handler always prints the message in CI, when Jest isn't clearing the console at all, but in dev it's inconsistent.

If the current behavior is a bug, please provide the steps to reproduce and either a repl.it demo through https://repl.it/languages/jest or a minimal repository on GitHub that we can yarn install and yarn test.

What is the expected behavior?
It would be great if Jest had a default unhandledRejection handler baked in that provided the same error message and stack trace formatting we get for other errors. And, more importantly, if the default handler could ensure the error would not get wiped away by any console clearing Jest does in dev.

As a quick fix, I added an unhandledRejection handler in my Jest setup that logs the error to the console.

image

But if you guys think this could be useful to other people, I'd be happy to take a stab at implementing a more robust solution in Jest itself!

Please provide your exact Jest configuration and mention your Jest, node, yarn/npm version and operating system.
Jest v19.0.2
Node v6.9.4
yarn v0.21.3
Mac OS X 10.12.3

@thymikee
Copy link
Collaborator

thymikee commented Apr 4, 2017

Hm, something like this might be handy.
cc: @DmitriiAbramov @rogeliog

@rogeliog
Copy link
Contributor

rogeliog commented Apr 4, 2017

Yeah, this is a really good point... Even if Jest was not clearing the console, I think that the default UnhandledPromiseRejectionWarning is not super intuitive and makes it a bit hard to figure out the error

@aaronabramov
Copy link
Contributor

yea! I remember we already thought about it in the past, but couldn't implement it because of Jasmine dependency. Now that we started migrating away from jasmine i think it'd be pretty easy to implement!

@thomashuston
Copy link
Contributor Author

@DmitriiAbramov when you guys thought about this before, did you have anything specific in mind?

@aaronabramov
Copy link
Contributor

i think the easiest way to implement something like this is to have a global handler and save all unhandled errors to a test state.
then when all tests are done, check the state, if there's any errors, fail the test and log them

@paul42
Copy link

paul42 commented Apr 8, 2017

@DmitriiAbramov would it be possible to save the stack trace for the errors as well? if you're messy like I am and coming back into some code after time away and you're not certain where your tests are timing out at, it just takes longer. Thanks in advance!

@thomashuston
Copy link
Contributor Author

I'm on vacation for the next few weeks, but I'd be happy to have a go at this when I'm back!

@danielkcz
Copy link

danielkcz commented May 3, 2017

A small workaround I've figured out. Use setupFiles configuration option and create a simple file like this. If you need it for a browser, just check out this..

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

Then suddenly all warnings are replaced by nice stack trace :)

Edit: One caveat is this warning instead. I am not sure what happens with a really large project. (node:8452) Warning: Possible EventEmitter memory leak detected. 11 unhandledRejection listeners added. Use emitter.setMaxListeners() to increase limit

@stipsan
Copy link
Contributor

stipsan commented May 4, 2017

@FredyC here's how I avoid the memory leak:

// In Node v7 unhandled promise rejections will terminate the process
if (!process.env.LISTENING_TO_UNHANDLED_REJECTION) {
  process.on('unhandledRejection', reason => {
    throw reason
  })
  // Avoid memory leak by adding too many listeners
  process.env.LISTENING_TO_UNHANDLED_REJECTION = true
}

In this snippet I don't just log the error but I throw it to make sure jest test will return a non-zero exit code. This is very useful in a ci context.

@danielkcz
Copy link

@stipsan That's kinda surprising that setting env variable here actually makes it shared between other jest child processes. Not sure how that works really, but good to know :)

@outdooricon
Copy link

This seems to have just gotten a lot more important with Jest 20. I'm seeing expectations that are after a.resolves like .resolves.isInstanceOf() just print this UnhandledPromiseRejectionWarning and don't even register with the jest final output that there was a test failure.

@stipsan
Copy link
Contributor

stipsan commented Jun 10, 2017

@outdooricon yeah, it's very easy to miss. And in some cases I've seen that the child process the test is running in is killed before Node have the chance to log it so it's not in any output at all.

@AndrewSouthpaw
Copy link
Contributor

I'm not sure if it's related, but I'll share my own experience here... I've found the warning appears inconsistently between Jest test runs. Sometimes it occurs in --watch mode, sometimes it happens on a full test run once and then not again the second time. I'm completely befuddled by the inconsistency. Anyone else ever encountering similar issues?

@nloomans
Copy link

@thomashuston Any update on this?

@albertdb
Copy link

albertdb commented Sep 7, 2017

This seems to have been implemented in Jest 21, and it is extremely annoying. Any asynchronously handled promises that is rejected before having a handler attached makes tests fail. And I don't find any way to deactive this behaviour.

Any idea of how to overcome this? Thanks.

@MikeyBurkman
Copy link

Yeah this is kind of a blocker for me. Here's a small test to demonstrate the issue:

test('this should work', (done) => {
    const n = Promise.reject('nope');

    setTimeout(() => {
        n.catch((err) => console.log('Caught: ', err));
    });

    setTimeout(() => {
        // Never makes it to this point
        console.log('here');
        done();
    }, 10);
});

This test fails in Jest 21.x, but runs fine in Jest 20.x. If I were to catch the exception synchronously (NOT inside a setTimeout), the test passes in Jest 21.x as expected.

This looks like a contrived exception, but in my actual code, I'm having a Promise reject inside of an Express router that I'm testing. I'm testing the router using Supertest, so I have to use done() after running assertions on the http response.

@ramusus
Copy link

ramusus commented Jan 10, 2018

@MikeyBurkman I have just faced with the same issue, did you figure out how to deal with it?

@MikeyBurkman
Copy link

@ramusus Unfortunately, the best I could do was just downgrade to 20.x. I haven't looked into updating back to 21.x since Oct though, so maybe things have changed.

@SimenB
Copy link
Member

SimenB commented Jan 15, 2018

As noted, the original issue has been handled (in #4016), so closing. But as mentioned above, it means that you cannot attach catch asynchronously. @MikeyBurkman could you open up a separate issue for it?

(Also see #5311)

@benjamingr
Copy link
Contributor

Hey, for posterity we've made the errors much nicer in Node 10

@SimenB
Copy link
Member

SimenB commented Aug 31, 2018

@benjamingr that's awesome! Mind linking to the pr (yes, I know I'm being lazy...)

@benjamingr
Copy link
Contributor

nodejs/node@13db29b

@stuart-clark-45
Copy link

stuart-clark-45 commented Dec 5, 2018

I found just logging the errors from my setup file wasn't working, this did tho::

import * as fs from 'fs';
let errCounter = 0;
process.on('unhandledRejection', (reason) => {
  fs.writeFileSync(`error${errCounter++}.txt`, reason.stack);
});

wiese added a commit to wmde/wikibase-termbox that referenced this issue Dec 20, 2018
As opposed to just showing a warning that might get eaten in cli when
multple jest child processes work in parallel.
See jestjs/jest#3251
This is a bit unsatifactory as it makes the parent jest process hang in
case there are such occurances.

Bug: T212409
wiese added a commit to wmde/wikibase-termbox that referenced this issue Dec 20, 2018
As opposed to just showing a warning that might get eaten in cli when
multple jest child processes work in parallel.
See jestjs/jest#3251
This is a bit unsatifactory as it makes the parent jest process hang in
case there are such occurances.

Bug: T212409
jakobw pushed a commit to wmde/wikibase-termbox that referenced this issue Dec 20, 2018
As opposed to just showing a warning that might get eaten in cli when
multple jest child processes work in parallel.
See jestjs/jest#3251
This is a bit unsatifactory as it makes the parent jest process hang in
case there are such occurances.

Bug: T212409
wmfgerrit pushed a commit to wikimedia/mediawiki-extensions-Wikibase that referenced this issue Aug 15, 2019
As opposed to just showing a warning that might get eaten in cli when
multiple jest child processes work in parallel.
See jestjs/jest#3251
This is a bit unsatifactory as it makes the parent jest process hang
in case there are such occurrences.

Change-Id: I4c3e72dee856e65783e0b60a00a2be42eafa0fcb
wmfgerrit pushed a commit to wikimedia/mediawiki-extensions that referenced this issue Aug 15, 2019
* Update Wikibase from branch 'master'
  to da868c37ebe5f9471d02710a5f0fd532c8b6573c
  - Merge "bridge: throw in case we encounter unhandled rejection in tests"
  - bridge: throw in case we encounter unhandled rejection in tests
    
    As opposed to just showing a warning that might get eaten in cli when
    multiple jest child processes work in parallel.
    See jestjs/jest#3251
    This is a bit unsatifactory as it makes the parent jest process hang
    in case there are such occurrences.
    
    Change-Id: I4c3e72dee856e65783e0b60a00a2be42eafa0fcb
wmfgerrit pushed a commit to wikimedia/wikibase-termbox that referenced this issue Mar 5, 2021
Updates were fully automated by following the docs:
https://cli.vuejs.org/guide/installation.html#project-dependencies

postcss.config.js and jest.config.js required small manual changes.

jestjs/jest#3251 also got fixed in the
version that is now used, so that block was removed from the jest setup.

Bug: T274632
Change-Id: Ic1465140b14aa519fc29658d3da0f22ba38579f5
@github-actions
Copy link

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 May 12, 2021
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