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

[danielesegato]

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]

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

[overlookmotel]

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

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

[erikerikson]

those changes did not resolve my particular issue.

[overlookmotel]

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

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

[danielesegato]

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

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]

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]

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]

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

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

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]

• 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]

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

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