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

multiple async done() calls result in failure; closes #4151 #4152

Merged
merged 5 commits into from
May 20, 2020

Conversation

boneskull
Copy link
Contributor

@boneskull boneskull commented Jan 14, 2020

This fixes bug #4151.

  • added a method in errors module to create a "multiple done" err
  • modernize multiple-done.spec.js
  • refactor errors into constants in errors module
  • remove Runner#started prop; replace with Runner#state prop + constants
  • add a catchall createFatalError() function to errors module; this is called
    when a test fails twice by other means (unsure what those means are yet)

Please note that because of how the fixture for this is written (using setTimeout), the behavior of the associated test is non-deterministic. We could increase the delay, but we're just hacking around and will likely have to increase or decrease it again (and write another test!). One of two things will happen:

  • The fixture will fail before the Runner completes, or
  • The fixture will fail after the Runner completes

In the first case, it's handled by the Runner's uncaught exception listener, (assuming --allow-uncaught is not set) and will exit with code 1. In the second case, it's caught by the, uh, other uncaught exception listener, uncaughtEnd(), (@juergba will know more about this) and exits with code 7.

I've tried to give the user enough context to track down the problem. The test covers whichever of these two happens to occur via a dynamic call to skip().

Update: Can't rely on the exit codes for anything

@boneskull boneskull added type: bug a defect, confirmed by a maintainer semver-patch implementation requires increase of "patch" version number; "bug fixes" area: async related to asynchronous use of Mocha labels Jan 14, 2020
@boneskull boneskull force-pushed the boneskull/issue/4151 branch 2 times, most recently from f5c142b to 1a5269f Compare January 14, 2020 00:55
@coveralls
Copy link

coveralls commented Jan 14, 2020

Coverage Status

Coverage increased (+0.2%) to 93.435% when pulling 7b39f4c on boneskull/issue/4151 into 722ce01 on master.

@juergba
Copy link
Contributor

juergba commented Jan 14, 2020

This PR is a good one, it helps me out with a problem I have in #4150.
I will need some days for reviewing.

Following test case shows more reliable results, maybe you can fix the failing CI tests that way.

describe('uncaught test', function() {
  this.timeout(1500);
    it('throw delayed error', (done) => {      
      setTimeout(() => {done(/*new Error()*/);}, 1000);
      setTimeout(() => {done();}, 2000);
    });
});

When you remove the first setTimeout which results in a timeout error, then the second done is swallowed. Otherwise when the first done reports an error, the second done throws. That's weird, not consistent.

Btw, I have not understood yet why (most parts of) Runner#uncaught() is registered on process.on('uncaughtException', ...) instead of runner.on('error', ...).

lib/runner.js Outdated
@@ -834,7 +857,7 @@ Runner.prototype.uncaught = function(err) {
runnable = new Runnable('Uncaught error outside test suite');
runnable.parent = this.suite;

if (this.started) {
if (this.state === constants.STATE_RUNNING) {
this.fail(runnable, err);
} else {
// Can't recover from this failure
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This part is probably wrong as well. Why don't we just abort here, or throw? When the runner has stopped, we throw anyway. When it hasn't even started, then there is nothing to recover or fail or to report, so we should just throw.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure if it's wrong or not. If we know which Runnable is throwing the uncaught error, then I think it makes sense to report it as a failure instead of just bailing. But I could be convinced otherwise. Either way, I think we can address it in another PR?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree, separate PR.

@juergba
Copy link
Contributor

juergba commented Jan 14, 2020

When a reporter errors (except generateDiff now), Mocha aborts without any message and parts of the reporter's output / epilogue are missing.
I don't know wether that bug is related to this PR as well.

@boneskull
Copy link
Contributor Author

@juergba If a reporter errors, that's an internal error, and shouldn't we just bail? Don't think that's related to this, though.

  • I fixed the test and behavior to be "more consistent".
  • Looks like I need to add some unit tests, as I suspected.

@boneskull
Copy link
Contributor Author

When you remove the first setTimeout which results in a timeout error, then the second done is swallowed. Otherwise when the first done reports an error, the second done throws. That's weird, not consistent.

I'll add a case for this and see if I can get to the bottom of it and maybe make it more consistent, but no guarantees right now.

when an async test times out, Mocha calls done(err) for the test where err is a timeout error. So, when the done() is eventually called by the test--e.g., setTimeout(done, 5000)--it's already considered a "multiple call to done" and is ignored. at least, I think that's how it works. I think we want to keep ignoring stuff because otherwise anything timing out which also calls done(err) may be noisy, but, again, I could be convinced otherwise

@juergba
Copy link
Contributor

juergba commented Jan 15, 2020

I'll add a case for this and see if I can get to the bottom

I know that in Runner#uncaught errors are ignored when runnable's is already failed. Is there another place where errors get ignored intentionally?

We should leave it as is, not aiming for perfection in dealing with uncaught exceptions. Most important is that Mocha should never leave with exitCode=0 when there was an uncaght exception thrown.

@@ -928,7 +951,7 @@ Runner.prototype.run = function(fn) {
if (rootSuite.hasOnly()) {
rootSuite.filterOnly();
}
self.started = true;
self.state = constants.STATE_RUNNING;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is setting runner's state not too early, in case of delay?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not sure. will see.

Copy link
Contributor

@juergba juergba left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we have a Runner#state property now, we don't need to unregister Runner#uncaught and register Runner#uncaughtEnd when runner ends. We just need one uncaught handler, where we rethrow when runner.state === constants.STATE_STOPPED;

Btw, I have not understood yet why (most parts of) Runner#uncaught() is registered on process.on('uncaughtException', ...) instead of runner.on('error', ...).

Do you know why?

@boneskull
Copy link
Contributor Author

Since we have a Runner#state property now, we don't need to unregister Runner#uncaught and register Runner#uncaughtEnd when runner ends. We just need one uncaught handler, where we rethrow when runner.state === constants.STATE_STOPPED;

Ooh, that's good. Yes.

Btw, I have not understood yet why (most parts of) Runner#uncaught() is registered on process.on('uncaughtException', ...) instead of runner.on('error', ...).
Do you know why?

If we catch an error in Runner code, then we can emit it as an error event, but there's no guarantee we can always do that.

For example, a simple assertion error would be catchable, and could be emitted as error:

it('should fail', function() {
  throw new Error()
});

likewise

it('should fail', function(done) {
  setTimeout(() => {
    done(new Error())
  });
});

or

it('should fail', async function() {
  return Promise.reject()
});

as far as I recall, this very common pattern is handled by uncaughtException; the Runner cannot catch this otherwise:

it('should fail', function(done) {
  setTimeout(() => {
    throw new Error();
  });
});

last time I checked, Mocha doesn't even do anything with this:

it('should fail', function() {
  Promise.reject();
});

The only way to handle this--like the previous case--is a listener on process (unhandledRejection, in this case).

We should probably add an unhandledRejection handler 😜

@boneskull boneskull force-pushed the boneskull/issue/4151 branch 3 times, most recently from 9f0ecd5 to e69edbe Compare May 19, 2020 00:02
boneskull added 4 commits May 19, 2020 13:58
- added a method in `errors` module to create a "multiple done" err
- modernize `multiple-done.spec.js`
- refactor errors into constants in `errors` module
- remove `Runner#started` prop; replace with `Runner#state` prop + constants
- add a catchall `createFatalError()` function to `errors` module; this is called
  when a test fails twice by other means (unsure what those means are yet)
- force color in Travis CI b/c my eyes
move logic to `Runner#uncaught`, since we can now rely on the value of `Runner#state`.

Signed-off-by: Christopher Hiller <boneskull@boneskull.com>
Signed-off-by: Christopher Hiller <boneskull@boneskull.com>
Signed-off-by: Christopher Hiller <boneskull@boneskull.com>
@boneskull boneskull force-pushed the boneskull/issue/4151 branch from e69edbe to 55283e3 Compare May 19, 2020 21:11
Signed-off-by: Christopher Hiller <boneskull@boneskull.com>
@boneskull
Copy link
Contributor Author

boneskull commented May 19, 2020

@nicojs Some of this touches stuff you changed recently. I found an issue, but I think it has existed for a long time.

In particular, in Runner#run:

  var self = this;
  function uncaught(err) {
    self.uncaught(err);
  }

  self._removeEventListener(process, 'uncaughtException', uncaught);
  self._addEventListener(process, 'uncaughtException', uncaught);

Do you see the bug? 😄

We use this uncaught function because when a listener is invoked by an EventEmitter, the listener is called with the context of the EventEmitter. But we need it to use the context of the Runner instance, so this is a workaround.

EventEmitter#removeListener(eventName, listener) needs the exact same listener as was registered in the first place in order to remove it (and only it). But every time we call Runner#run, a new uncaught function is created. So, in essence, self._removeEventListener(process, 'uncaughtException', uncaught); does nothing, because our newly-created uncaught will not have been registered. Thus, if ten calls are made to Runner#run, ten different listeners will be registered.

This is unlikely to be a problem during the normal course of operation, I think, which is why it wouldn't have been noticed.

The fix isn't awesome. I renamed Runner#uncaught to Runner#_uncaught, and in the Runner constructor:

this.uncaught = this._uncaught.bind(this);

Now, we change the aforementioned code to:

  // "self" isn't strictly necessary here
  var self = this;
  self._removeEventListener(process, 'uncaughtException', self.uncaught);
  self._addEventListener(process, 'uncaughtException', self.uncaught);

Even having access to lambda functions, we'd still need the listener to call with the correct context. So even then, the Runner constructor would have to do this:

this.uncaught = err => this._uncaught(err);

This could also probably be solved with a Proxy, but that's even worse, IMO.

@boneskull boneskull merged commit cb5eb8e into master May 20, 2020
@boneskull boneskull deleted the boneskull/issue/4151 branch May 20, 2020 19:08
@craigtaub craigtaub added this to the next milestone May 21, 2020
craigtaub pushed a commit that referenced this pull request May 21, 2020
- added a method in `errors` module to create a "multiple done" err
- modernize `multiple-done.spec.js`
- refactor errors into constants in `errors` module
- remove `Runner#started` prop; replace with `Runner#state` prop + constants
- add a catchall `createFatalError()` function to `errors` module; this is called when a test fails twice by other means (unsure what those means are yet)
- force color in Travis CI b/c my eyes
- remove `Runner#uncaughtEnd`; move logic to `Runner#uncaught`, since we can now rely on the value of `Runner#state`.
- upgrade `unexpected-eventemitter`
- fix potential listener leak in `Runner#run`
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: async related to asynchronous use of Mocha semver-patch implementation requires increase of "patch" version number; "bug fixes" type: bug a defect, confirmed by a maintainer
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants