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

random false positive "Unhandled rejection Error" after upgrading to 3.5.1 #1468

Closed
danielesegato opened this issue Oct 12, 2017 · 16 comments
Closed

Comments

@danielesegato
Copy link

danielesegato commented Oct 12, 2017

I've this weird issue with jasmine testing framework and bluebird: it sometimes (not consistently) produce errors in the console log like this one:

Unhandled rejection Error: dummy
    at UserContext.<anonymous> (/home/mastro/ws/my-project-path/spec/unit/logic.spec.js:246:89)
    at UserContext.arguments.(anonymous function) (/home/mastro/ws/my-project-path/node_modules/jasmine-promises/dist/jasmine-promises.js:35:30)
    at attempt (/home/mastro/ws/platform/nsp-gamification-loyalty-services/node_modules/jasmine-core/lib/jasmine-core/jasmine.js:4297:26)
    at QueueRunner.run (/home/mastro/ws/platform/nsp-gamification-loyalty-services/node_modules/jasmine-core/lib/jasmine-core/jasmine.js:4217:20)
    at Timeout.runNext [as _onTimeout] (/home/mastro/ws/platform/nsp-gamification-loyalty-services/node_modules/jasmine-core/lib/jasmine-core/jasmine.js:4257:20)
    at tryOnTimeout (timers.js:228:11)
    at Timer.listOnTimeout (timers.js:202:5)

Those are actually printed in the logs but do not make the test fail. In fact the test succeed, a test exhibiting the issue may look something like this:

        it('should throw if the check of `type` and `config` throws', () => {
            spyOn(actionHandler, 'validateActionConfig').and.returnValue(Promise.reject(new Error('dummy'))); 
            return sut.createAction(principal, action)
                .then(() => {
                    fail('Promise rejection expected, instead fulfilled');
                })
                .catch((err) => {
                    expect(actionHandler.validateActionConfig).toHaveBeenCalled();
                    expect(err.message).toBe('dummy');
                });
        });

The spyOn is jasmine way of testing mocked dependencies. sut is the subject under test. This test check our function createAction forward any rejectiong error from the call to actionHandler.validateActionConfig() by returning a rejection promise when the function is called.
That promise is then catched, as you can see, and we also check the error is exactly the one throw there. So the promise IS catched, but somehow it is detected as uncatched.

Furthermore this is not an on/off problem. Some test randomly exhibit this behavior, some never do.

This didn't happen with bluebird 3.5.0 and, according to your 3.5.1 release note (https://github.com/petkaantonov/bluebird/releases/tag/v3.5.1) you changed something in the Unhandled Promise rejection.
Can you shed some light on what's possibly going on?
Thanks!

related dependencies

├── bluebird@3.5.1
│
├─┬ jasmine@2.8.0
│ └── exit@0.1.2
├── jasmine-core@2.8.0
├─┬ jasmine-expect@3.7.1
│ └── add-matchers@0.5.0
├── jasmine-promises@0.4.1
├─┬ jasmine-spec-reporter@3.3.0
│ └── colors@1.1.2

and...

$ node -v
v6.11.2
$ npm -v
3.10.10

I initially posted this as a comment to an old issue here #493 and opened a bug to jasmine here: jasmine/jasmine-npm#124

But after some further testing with different versions of jasmine and bluebird I'm fairly certain this is introduced by a change in bluebird.

The problem DID NOT happen on bluebird version 3.5.0.
And I think this problem is related to #1404

@Celadora
Copy link

Celadora commented Oct 18, 2017

I'm having a similar problem. Here is some code to reproduce the potential bug:

var Promise = require('bluebird');


async function test() {
  await rejection().error(err=>{
    console.error(err);
  });
}

test()

function rejection() {
  return new Promise((resolve, reject)=>{
    reject(new Error('test'));
  }).error(err=>{
    console.error(err);
    return err;
  })
}

It produces the following error:

(node:16566) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: test
(node:16566) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

Without using async/await a similar error is produced:

var Promise = require('bluebird');


function test() {
  rejection().error(err=>{
    console.error(err);
  });
}

test()

function rejection() {
  return new Promise((resolve, reject)=>{
    reject(new Error('test'));
  }).error(err=>{
    console.error(err);
    return err;
  })
}

Error:


Unhandled rejection Error: test
    at Promise (/sandbox/promiserejectionbug/index2.js:14:12)
    at Promise._execute (/sandbox/promiserejectionbug/node_modules/bluebird/js/release/debuggability.js:303:9)
    at Promise._resolveFromExecutor (/sandbox/promiserejectionbug/node_modules/bluebird/js/release/promise.js:483:18)
    at new Promise (/sandbox/promiserejectionbug/node_modules/bluebird/js/release/promise.js:79:10)
    at rejection (/sandbox/promiserejectionbug/index2.js:13:10)
    at test (/sandbox/promiserejectionbug/index2.js:5:3)
    at Object.<anonymous> (/sandbox/promiserejectionbug/index2.js:10:1)
    at Module._compile (module.js:624:30)
    at Object.Module._extensions..js (module.js:635:10)
    at Module.load (module.js:545:32)
    at tryModuleLoad (module.js:508:12)
    at Function.Module._load (module.js:500:3)
    at Function.Module.runMain (module.js:665:10)
    at startup (bootstrap_node.js:187:16)
    at bootstrap_node.js:607:3

Thank you.

[edit]

By using .catch(err=>{}) instead of .error(err=>{}) the bug seems to go away.

Works as expected:

var Promise = require('bluebird');

test();
async function test() {
  await rejection().catch(err=>{
    console.error(err);
  });
}

function rejection() {
  return new Promise((resolve, reject)=>{
    reject(new Error('test'));
  }).catch(err=>{
    console.error(err);
    return err;
  })
}

kirrg001 added a commit to TryGhost/Ghost that referenced this issue Oct 31, 2017
no issue

- bson-objectid@1.2.1
- compression@1.7.1
- express@4.16.2
- moment-timezone@0.5.14
- mysql@2.15.0
- nconf@0.8.5
- sanitize-html@1.15.0
- simple-html-tokenizer@0.4.3
- superagent@3.8.0

IMPORTANT:
- we are unable to bump moment and bluebird at the moment, because in both releases there is a bug which breaks our tests
- i didn't investigate a lot, but there is petkaantonov/bluebird#1468
- and for moment, a couple of reports came in for .19 regarding a wrong date behaviour
@overlookmotel
Copy link
Contributor

@danielesegato Can you possibly simplify your example without all the jasmine-specific stuff? It's hard to reason through if you don't know jasmine.

I just fixed another similar bug with #1489 and I'm wondering if this issue might be related - maybe I can help, but at present I can't really work out what's going on in your example.

@erikerikson
Copy link

I've found rather similar behavior and had reported it at chaijs/chai#1134. Will try the new code on your PR.

@erikerikson
Copy link

those changes did not resolve my particular issue.

@overlookmotel
Copy link
Contributor

@Celadora The issue you raise is not a bug, it's intended behaviour.

.error() catches only operational errors, and the error you're rejecting with is not an operational error, so the .error() handler is not invoked. So it is indeed an unhandled rejection.

.catch() catches all errors, which is why it behaves as you expected.

See the docs for .error()

This is unrelated to original issue raised by @danielesegato.

@overlookmotel
Copy link
Contributor

@erikerikson's issue is also unrelated to @danielesegato's original issue. @erikerikson's issue is explored in #1501.

@danielesegato
Copy link
Author

danielesegato commented Feb 9, 2018

@overlookmotel sorry I forgot to answer you, I don't know how to reproduce the problem in a simpler way cause I do not understand exactly what is causing it.

I "solved" it by forcing the use of version 3.5.0. The warnings show up if I upgrade to 3.5.1.
I didn't try more recent versions.

Sorry I can't be more helpful.

@danielesegato
Copy link
Author

I can explain what my code does in respect to the Promise.

spyOn(actionHandler, 'validateActionConfig').and.returnValue(Promise.reject(new Error('dummy'))); 

this create a new rejection promise with an error: Promise.reject(new Error('dummy'))) and make it so a call to actionHandler.validateActionConfig() will return that promise.

Inside sut.createAction(principal, action) the code perform that call, which then return the rejection promise which is handled:

.catch((err) => {
                    expect(actionHandler.validateActionConfig).toHaveBeenCalled();
                    expect(err.message).toBe('dummy');
                });

this part of code receive the error I created above and check the function actionHandler.validateActionConfig() has been called and the error is the one I created above.

So, i know for sure, that function has been called and that promise has been returned.

In other words, I've handled the error and I don't expect to receive any warning like that.

@danielesegato
Copy link
Author

I should also add this is not an ON/OFF problem, the warning doesn't always show for the same tests, it seems random and could happen in any of those test using a Promise.reject(). And I'm 100% positive all those DO catch that exception.

If you think it is useful I can try to show you an example of the code inside that createAction but you can think of it as something like:

this.createAction = function() {
  return actionHandler.validateActionConfig();
}

In reality it's all inside a Promise.try() with some other methods and checks but it DO return that promise cause the test pass.

@overlookmotel
Copy link
Contributor

Hi @danielesegato.

Thanks for replies. Just so you understand, I'm not a maintainer of bluebird, just this has got me interested. I'd like to help, but it's not crucial to my work so I can't spend too much time on it.

I don't know Jasmine, and there's a lot of moving parts in this. Being an intermittent fault will also make it even harder to diagnose.

I think only way I can help is if you're able to create a standalone repo with all the elements in place (failing test, the code for actionHandler, and package.json with the required dependencies) - something I can clone to my computer and run to reproduce the problem. Then I may be able to figure out what's going on and fix it.

I understand if you don't have time for that, but in that case I'm afraid this is likely to remain a mystery!

@whawker
Copy link

whawker commented Jun 29, 2018

@danielesegato I came up against this same issue in my Jasmine test

I fixed it by using andCallFake instead of returnValue

spyOn(actionHandler, 'validateActionConfig').and.callFake(() => Promise.reject(new Error('dummy')));

My thought is that returnValue immediately evaluates the result, so Node thinks your test case is rejecting a promise.

@bowofolaf
Copy link

@danielesegato I came up against this same issue in my Jasmine test

I fixed it by using andCallFake instead of returnValue

spyOn(actionHandler, 'validateActionConfig').and.callFake(() => Promise.reject(new Error('dummy')));

My thought is that returnValue immediately evaluates the result, so Node thinks your test case is rejecting a promise.

This worked for me in an angular test using $q.reject. Still don't understand why, its never happened before. And the only thing I can see that's different is that the promise is being used by $timeout. I am calling .catch appropriately as well on the promise returned from $timeout and the one returned by the function passed into it.

@petkaantonov
Copy link
Owner

3.5.1 updated the unhandled rejection to use setTimeout to delay checking if there are unhandled rejections. The functionality of setTimeout has been hijacked by the test framework hence the callback runs earlier than expected.

@petkaantonov
Copy link
Owner

  • Fixing in node: just use require("timers") to get reference to the actual setTimeout
  • Fixing in browsers: create iframe, attach and remove it from DOM and get reference to actual setTimeout from iframe.contentWindow.setTimeout

@benjamingr
Copy link
Collaborator

@petkaantonov I don't think this is for us to fix to be honest - this is something the test framework should take care of.

@benjamingr
Copy link
Collaborator

Ideas for how welcome by the way (I help maintain lolex which is likely the fake timers library)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants