Duplicated failing test summary

[skeggse]

Running Mocha 3.4.2 on Node 8.1.3 (also reproducible on Node 7.6.0).

describe('mocha', function() {
  it('should report the first of multiple exceptions', function(done) {
    process.nextTick(() => {
      console.log('first');
      throw new Error('first');
    });
    process.nextTick(() => {
      console.log('second');
      done(new Error('second'));
    });
  });
});

Output:

$ mocha 


  multiple errors
first
    1) should report on multiple uncaught exceptions
second
    2) should report on multiple uncaught exceptions


  0 passing (12ms)
  2 failing

  1) multiple errors should report on multiple uncaught exceptions:
     Error: second
      at process.nextTick (test/index.js:9:12)
      at _combinedTickCallback (internal/process/next_tick.js:95:7)
      at Immediate._tickCallback (internal/process/next_tick.js:161:9)

  2) multiple errors should report on multiple uncaught exceptions:
     Error: second
      at process.nextTick (test/index.js:9:12)
      at _combinedTickCallback (internal/process/next_tick.js:95:7)
      at Immediate._tickCallback (internal/process/next_tick.js:161:9)




  0 passing (14ms)
  2 failing

  1) multiple errors should report on multiple uncaught exceptions:
     Error: second
      at process.nextTick (test/index.js:9:12)
      at _combinedTickCallback (internal/process/next_tick.js:95:7)
      at Immediate._tickCallback (internal/process/next_tick.js:161:9)

  2) multiple errors should report on multiple uncaught exceptions:
     Error: second
      at process.nextTick (test/index.js:9:12)
      at _combinedTickCallback (internal/process/next_tick.js:95:7)
      at Immediate._tickCallback (internal/process/next_tick.js:161:9)

Not only does mocha output four (!) copies of the second error, it fails to output any copies of the first error. This makes it difficult to debug tests if the second error is merely a symptom of the first.

[ScottFreeCode]

It's actually not a simple case of four copies of the second error, but rather, in addition to getting two copies of the second error rather than one of the first and one of the second, it's also running the whole end summary (which is where the stacktraces get printed, but also the pass/fail/pending-if-any counts) twice.

There's probably multiple bugs in play here, which is impressive considering both of them are quite surprising.

Thanks for spotting this and providing a perfect test case! We'll look into what's happening under the hood; but if anyone wants to jump on it and propose a fix, feel free!

[ScottFreeCode]

Quick followup observation:

• If I change both to use done instead of throwing, I still get two copies of the second error, but the summary is only printed once.
• If I change the second error to be thrown, regardless of whether the first error is thrown or is passed to done, I get a print of the first error and no print of the second error. (See also Mocha's hanging CI browser tests #2890 (comment) )

[robininfo-edsx]

I fall on this issue too with this code

const fs = require('fs');
it('Bug', () => {
  console.log('!!!!');
  return new Promise(function(resolve, reject) {
    fs.readFile('/', (err, data) => {
      if (err) {
        reject(err);
      }
      data.toString();
      resolve();
    });
  });
});

As after rejecting the promise an uncaught error is throw by data.toString(); as data is undefined

[ScottFreeCode]

Hi @robininfo-edsx,

When I run that code, I get a single print of a test failure and an unhandled promise rejection warning from Node. That seems like a different issue (assuming it is an issue; I'm not sure off the top of my head what the right behavior is if you give Mocha a promise that eventually becomes rejected but -- due to the effects of reject in the constructor callback occurring asynchronously after the constructor callback finishes -- not till after an uncaught exception, which typically fails a test, is thrown).

[ScottFreeCode]

Ok, based on #2995 I think I've boiled @robininfo-edsx's example down to another, even more interesting case of this issue after all. Here's four different test files, each of which I've run individually:

// no async, no describe
it('Bug', () => {
  return new Promise(function(resolve, reject) {
      reject(new Error('one'));
      throw new Error('two');
    });
});

// no async, describe
describe('suite', () => {
  it('Bug', () => {
    return new Promise(function(resolve, reject) {
        reject(new Error('one'));
        throw new Error('two');
      });
  });
});

// async, no describe
it('Bug', () => {
  return new Promise(function(resolve, reject) {
    process.nextTick(() => {
      reject(new Error('one'));
      throw new Error('two');
    });
  });
});

// async, describe
describe('suite', () => {
  it('Bug', () => {
    return new Promise(function(resolve, reject) {
      process.nextTick(() => {
        reject(new Error('one'));
        throw new Error('two');
      });
    });
  });
});

The two non-async examples work as expected. The async no-describe example gets a failed test printed correctly and an unhandled rejection warning. Adding describe to the async example turns it into another variation of the duplicated test run end/summary printing issue. Strange that being in a suite makes a difference -- that's a very specific combination of behaviors.

---

Something we should start looking at is whether this problem is triggered by:

• only a single test
• a test like this anywhere in the testsuite
• multiple tests all like this
• a test like this as the first of multiple tests
• a test like this as the last of multiple tests

We've only covered the first of those possibilities so far.

[robininfo-edsx]

So effectively my last comment was not the same issue however it may play on this issue as mocka can have multiple result for a test.
Which is pretty bad and can cause the uncaught promise that I had in #2995 by just removing describe

[ScottFreeCode]

Just a heads-up -- since there are other issues about exceptions being clobbered when reporting multiple failures arising out of the same test (e.g. #2971) and I've been directing other reports of duplicated test summaries here, I've attempted to make the title more about what happens rather than how (although in the process it's not bringing up the angle of "second" being reported twice rather than "first" then "second", which I believe is distinct from the duplicated summary).

[sebascabot]

This bug in combination with an afterEach have even more negative impact.

The afterEach() is the one receiving this 2nd exception.
Mocha is not expecting this, and fail with a crash.
No more test are executed.

Here the code to reproduce it,
In the output in DEBUG we can see the 'afterEach()' fail with the 'uncaught exception'/

describe('Batch #1', function() {
    afterEach (function () {});

    it('should be OK :: A.1', function(done) {
        process.nextTick(() => {
            console.log('==>  Code Inside A.1 / 1st Failule');
            console.log('==>  Test Title:', this.test.title);
            throw Error('==>  First failure <');
        });
        process.nextTick(() => {
            console.log('-->  Code Inside A.1 / 2nd Failure');
            console.log('-->  Test Title:', this.test.title);
            done( Error('-->  Second failure <'));

        });
    });

    it('should be OK :: A.2', function() {});
});

describe('Batch #2', function() {
    it('should be OK :: B.1', function() {});
});

And here part of the output where run with DEBUG=*

  mocha:runner run suite Batch #1 +2ms
  Batch #1
==>  Code Inside A.1 / 1st Failule
==>  Test Title: should be OK :: A.1
  mocha:runner uncaught exception ==>  First failure < +3ms
    1) should be OK :: A.1
-->  Code Inside A.1 / 2nd Failure
-->  Test Title: "after each" hook
    2) should be OK :: A.1

  mocha:runner run suite Batch #2 +2ms
  Batch #2
  mocha:runner uncaught exception Cannot read property 'isPending' of undefined +0ms
    3) "after each" hook

  mocha:runner finished running +1ms

  0 passing (9ms)
  3 failing

  1) Batch #1
       should be OK :: A.1:
     Error: -->  Second failure <
      at process.nextTick (bug-after-each-1.js:16:19)
      at _combinedTickCallback (internal/process/next_tick.js:131:7)
      at Immediate._tickCallback (internal/process/next_tick.js:180:9)

  2) Batch #1
       should be OK :: A.1:
     Error: -->  Second failure <
      at process.nextTick (bug-after-each-1.js:16:19)
      at _combinedTickCallback (internal/process/next_tick.js:131:7)
      at Immediate._tickCallback (internal/process/next_tick.js:180:9)

  3) Batch #1
       "after each" hook:
     Uncaught TypeError: Cannot read property 'isPending' of undefined

Here our observation:

1. Our Test A.1 is reported twice as a failure. (already know)
2. afterEach() hook, fail dramatically (and there is no code in our example! for this hook)
3. The test runner stop at Test A.1, since Mocha exit abruptly. All the others test are ignored

Note, this is the most problematic configuration, a describe() with a afterEach() and two it() inside, where the first it() throw 2 exceptions. With more or less it() Mocha do not exit abruptly.

The cause of the failure seams to be the afterEach() hook catching the exception thrown from the it().

My config:

> mocha -V
4.0.1
> node -v
v8.9.1

[ScottFreeCode]

The afterEach() is the one receiving this 2nd exeception.

See also #967

Mocha is not expecting this, and fail with a crash.
No more test are executed.

Unless I've missed something, I don't think it's crashing exactly: there's an expected behavior that failures in Each hooks abort whichever suite those hooks belong to.

[ScottFreeCode]

Per #3105's example, another way this can happen is with an afterEach hook that returns a promise and a test that completes and but has left asynchronous code running that later throws (during the afterEach run).

[ScottFreeCode]

I suspect all these cases come down to double-completions of some test or hook causing Mocha to redundantly run some of its logic that includes the final end summary. There's some code to suppress some reporting of double-completions, but it's obviously not a general solution. The general solution would be to refactor the flow of Mocha's suite/hooks/test running actions, such that after a hook or test is completed any subsequent completion of that hook or test:

• will be reported as an error, but
• cannot rerun any of the next steps.

For instance, this is easy to do with promise flows since promises only resolve once; if Mocha reaches (or has reached? I'll have to review for version 4) a point where only environments that have native promises are supported, or if it's possible for Mocha to use a promise library internally without polluting the environment of the tests or the code being tested, then one way to resolve the issue completely and permanently would be simply to rewrite the logic in terms of promises (on the inside anyway, converting to the existing callback-based interactions at the API boundaries).

[skeggse]

then one way to resolve the issue completely and permanently would be simply to rewrite the logic in terms of promises

If I understand correctly, this might mask the true outcome of a test that succeeds and then fails, no? We might want to report all failures, and ignore subsequent "successes" (or report them as failures) and simply have additional info for the console.

[ScottFreeCode]

Those would need to be reported, but should not re-run any of Mocha's test run logic (that says "ok, that test is done, do the hooks, now do the next one; ok, that suite is done, do its after hooks, are we at the end? do the end..."). It should be entirely possible to get the logic un-repeatable with promises while leaving the immediate handlers for various test/hook results in a state where they'll emit a failure to the reporter -- not that it would be easy, but the hard part isn't leaving those handlers still correctly reporting redundant test/hook completions; the hard part is changing Mocha's overcomplex internals and using promises under the hood of a callback-based API.

[juergba]

fixed by #4150

Batch #1
==>  Code Inside A.1 / 1st Failule
    1) should be OK :: A.1
-->  Code Inside A.1 / 2nd Failure
    2) should be OK :: A.1
    √ should be OK :: A.2

  Batch #2
    √ should be OK :: B.1

  2 passing (38ms)
  2 failing

  1) Batch #1
       should be OK :: A.1:
      Uncaught Error: ==>  First failure <
      [...]

  2) Batch #1
       should be OK :: A.1:
      Error: -->  Second failure < (and Mocha's done() called multiple times)
      [...]

[Mereep]

I am not sure if I am right here: I come Ticket #3105 to here when receiving the very same message while doing truffle test.
In my case it was a simple argument order mistake which triggered that:

it("should only be possible for admins to pause an account", async function() {
    let instance = await Accounts.deployed();

    await truffleAssert.fails(
      instance.pause({from: accounts[1]}),
      truffleAssert.ErrorType.REVERT,
    );
  })

when switching the arguments by mistake to

...
await truffleAssert.fails(
      truffleAssert.ErrorType.REVERT,
      instance.pause({from: accounts[1]})
);
...

you'll be presented with what is written in #3105.