Strange behaviour with error reporting using mocha and bluebird

[lo1tuma]

We created some tests today that were using promisified code. We observed strange behaviour when some assertions were failing. The error messages were not displayed but the stack trace was complete.

Error messages in then blocks are being truncated. This is the output for a minimal example we attached below:

bash-3.2$ node foo.js

/Users/mat/workspace/foo/node_modules/bluebird/js/main/async.js:93
                throw res.e;
                         ^
    at /Users/mat/workspace/foo/foo.js:5:15
    at Function.Module.runMain (module.js:499:11)
    at startup (node.js:119:16)
From previous event:
    at Object.<anonymous> (/Users/mat/workspace/foo/foo.js:3:9)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
    at startup (node.js:119:16)
    at node.js:906:3

As you can see, the error message is missing from the output. After some debugging we found out, that it is actually present but is not written to the output (I attached the expected output containing the error message at the bottom of this issue).

This is the minimalistic example mentioned above:

var Promise = require('bluebird');

Promise.resolve()
    .then(function () {
        throw new Error('a$_b');
    }).done();

The result is especially interesting as bluebird uses the following function name: PromiseResolver$_callback. We found this string in our assertion error message.

---

The following cases work (replaced only the throw line, modifying the error message):

• throw new Error('a$_');
• throw new Error('$_b');
• throw new Error('a$b');

These result in the correct output. E.g.:

node foo.js
node foo.js

/Users/mat/workspace/foo/node_modules/bluebird/js/main/async.js:93
                throw res.e;
                         ^
Error: a$b
    at /Users/mat/workspace/foo/foo.js:5:15
    at Function.Module.runMain (module.js:499:11)
    at startup (node.js:119:16)
From previous event:
    at Object.<anonymous> (/Users/mat/workspace/foo/foo.js:3:9)
    at Module._compile (module.js:456:26)
    at Object.Module._extensions..js (module.js:474:10)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:312:12)
    at Function.Module.runMain (module.js:497:10)
    at startup (node.js:119:16)
    at node.js:906:3

System spec:

• bluebird version: 2.2.2 and current master build
• node version: 0.10.29
• zsh version: 5.0.2
• bash version: 3.2.51(1)-release
• Mac OS X version: 10.9.3

[petkaantonov]

a$_b matches the regexp that is used to check if a function is internal

[lo1tuma]

This is a problem if you make assertions with sinon on promisified stubs. Sinon shows all calls and its parameters within the message of the assertion.

Here is an example mocha test:

var expect = require('chai').expect,
    sinon = require('sinon'),
    Promise = require('bluebird'),
    chai = require('chai'),
    sinonChai = require('sinon-chai');

chai.use(sinonChai);

var anyThirdPartyModule = {};

function foo() {
    var fooAsync = Promise.promisify(anyThirdPartyModule.foo);

    return fooAsync();
}

describe('foo', function () {
    before(function () {
        anyThirdPartyModule.foo = sinon.stub().yields();
    });

    it('should do something', function () {
        return foo()
            .then(function () {
                // anyThirdPartyModule.foo was only called once, so the next line will throw an AssertionError
                expect(anyThirdPartyModule.foo).to.have.been.calledTwice;
            });
    });
});

The output of this AssertionError is missing the error message:

1) foo should do something:
     From previous event:
    at promisified (eval at makeNodePromisifiedEval (/Users/mat/workspace/foo/node_modules/bluebird
  js/main/promisify.js:199:12), <anonymous>:7:21)
      at foo (/Users/mat/workspace/foo/test/foo.js:14:12)
      at Context.<anonymous> (/Users/mat/workspace/foo/test/foo.js:24:16)
      at callFn (/Users/mat/workspace/foo/node_modules/mocha/lib/runnable.js:247:21)
      at Test.Runnable.run (/Users/mat/workspace/foo/node_modules/mocha/lib/runnable.js:240:7)
      at Runner.runTest (/Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:373:10)
      at /Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:451:12
      at next (/Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:298:14)
      at /Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:308:7
      at next (/Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:246:23)
      at Object._onImmediate (/Users/mat/workspace/foo/node_modules/mocha/lib/runner.js:275:5)

If I manually catch the AssertionError and log the error message to the console, I get the following output:

expected stub to have been called exactly twice, but it was called once
    stub(function PromiseResolver$_callback() {})

Why does bluebird remove this error message from the stack-trace? Why does it remove only the message and not the call stack?

[petkaantonov]

Because the regexp is pretty naive right now. It's supposed to cut out lines from stack traces that are internal calls but matching that pattern in the error message was not foreseen.

[lxanders]

So one possibility would be to not apply the regex on the error message? Would you accept a pull request for this issue that improves the regex matching or removes it for the error message?