fc.assert displays failure log 2 times with mocha (even when changing the logger)

[BourgoisMickael]

🐛 Bug Report

When the assertion function throw, the output is displayed 2 times under mocha

To Reproduce

const fc = require('fast-check')

function throwSomething (smth) {
  throw new Error(smth)
}

describe.only('test fast-check', function () {
  it('displaying 2 times', function () {
    fc.assert(
      fc.property(
        fc.integer(), num => throwSomething(num)
      ),
      { logger: function () { console.info('logger called') } }
    )
  })

  it('displaying only 1 time', function () {
    throwSomething('hello world')
  })
})

Then run this file with mocha

The result will be

  test fast-check
    1) displaying 2 times
    2) displaying only 1 time

  0 passing (21ms)
  2 failing

  1) test fast-check
       displaying 2 times:
     Property failed after 1 tests
{ seed: 408091181, path: "0:0", endOnFailure: true }
Counterexample: [0]
Shrunk 1 time(s)
Got error: Error: 0

Stack trace: Error: 0
    at throwSomething (/home/tmp/test.js:4:9)
    at fc.assert.fc.property.num (/home/tmp/test.js:11:30)
    at Property.predicate (/home/tmp/node_modules/fast-check/lib/check/property/Property.generated.js:15:105)
    at Property.run (/home/tmp/node_modules/fast-check/lib/check/property/Property.generic.js:19:31)
    at runIt (/home/tmp/node_modules/fast-check/lib/check/runner/Runner.js:19:32)
    at check (/home/tmp/node_modules/fast-check/lib/check/runner/Runner.js:107:11)
    at Object.assert (/home/tmp/node_modules/fast-check/lib/check/runner/Runner.js:111:15)
    at Context.<anonymous> (/home/tmp/test.js:9:8)
    at callFn (/home/tmp/node_modules/mocha/lib/runnable.js:387:21)
    at Test.Runnable.run (/home/tmp/node_modules/mocha/lib/runnable.js:379:7)
    at Runner.runTest (/home/tmp/node_modules/mocha/lib/runner.js:525:10)
    at /home/tmp/node_modules/mocha/lib/runner.js:643:12
    at next (/home/tmp/node_modules/mocha/lib/runner.js:437:14)
    at /home/tmp/node_modules/mocha/lib/runner.js:447:7
    at next (/home/tmp/node_modules/mocha/lib/runner.js:362:14)
    at Immediate.<anonymous> (/home/tmp/node_modules/mocha/lib/runner.js:415:5)
    at runCallback (timers.js:810:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5)

Hint: Enable verbose mode in order to have the list of all failing values encountered during the run
  Error: Property failed after 1 tests
  { seed: 408091181, path: "0:0", endOnFailure: true }
  Counterexample: [0]
  Shrunk 1 time(s)
  Got error: Error: 0
  
  Stack trace: Error: 0
      at throwSomething (test.js:4:9)
      at fc.assert.fc.property.num (test.js:11:30)
      at Property.predicate (node_modules/fast-check/lib/check/property/Property.generated.js:15:105)
      at Property.run (node_modules/fast-check/lib/check/property/Property.generic.js:19:31)
      at runIt (node_modules/fast-check/lib/check/runner/Runner.js:19:32)
      at check (node_modules/fast-check/lib/check/runner/Runner.js:107:11)
      at Object.assert (node_modules/fast-check/lib/check/runner/Runner.js:111:15)
      at Context.<anonymous> (test.js:9:8)
  
  Hint: Enable verbose mode in order to have the list of all failing values encountered during the run
      at Object.throwIfFailed (node_modules/fast-check/lib/check/runner/utils/RunDetailsFormatter.js:99:11)
      at Object.assert (node_modules/fast-check/lib/check/runner/Runner.js:115:31)
      at Context.<anonymous> (test.js:9:8)

  2) test fast-check
       displaying only 1 time:
     Error: hello world
      at throwSomething (test.js:4:9)
      at Context.<anonymous> (test.js:18:5)

Expected behavior

There should be only 1 output, like for the 2nd. Also with Mocha, on the 2nd test, the Error line is printed in red and the stack trace is in grey, but with fc.assert one output is in red and the other is in grey.

I tried defining a logger but the function is not called.

A solution I tried is to put fc.assert in a try catch block and then output with console.log but it's not a good way to do it and the output doesn't get the mocha formatting, and same if I use fc.check to output the result I won't have the mocha formatting.

Your environment

Packages / Softwares	Version(s)
fast-check	1.16.0
node	v8.16.0

[dubzzz]

Thanks a lot for the report. The behaviour is indeed unexpected. I'll try to troubleshoot and fix it.

It does not seem that there is such problem with test runners: Jest or Jasmine - they might treat the error in a different way.

[dubzzz]

After some investigations it happens that the problem comes from the content of the error message produced by fast-check. Basically we can easily reproduce the problem by using throwSomething2 as defined below:

funtion throwSomething2() {
  const err = new Error("something wrong happened");
  throw new Error("Execution failed.\nGot error: " + err + "\n\nStack trace: " + err.stack);
}

describe("describe", () => {
  it("it report v2", () => {
    throwSomething2();
  });
});

The resulting error for the spec above is:

  2) describe
       it report v2:
     Execution failed.
Got error: Error: something wrong happened

Stack trace: Error: something wrong happened
    at throwSomething2 (C:\dev\try-mocha\test\test.js:9:15)
    at Context.<anonymous> (C:\dev\try-mocha\test\test.js:20:5)
    at callFn (C:\dev\try-mocha\node_modules\mocha\lib\runnable.js:387:21)
    at Test.Runnable.run (C:\dev\try-mocha\node_modules\mocha\lib\runnable.js:379:7)
    at Runner.runTest (C:\dev\try-mocha\node_modules\mocha\lib\runner.js:535:10)
    at C:\dev\try-mocha\node_modules\mocha\lib\runner.js:653:12
    at next (C:\dev\try-mocha\node_modules\mocha\lib\runner.js:447:14)
    at C:\dev\try-mocha\node_modules\mocha\lib\runner.js:457:7
    at next (C:\dev\try-mocha\node_modules\mocha\lib\runner.js:362:14)
    at Immediate._onImmediate (C:\dev\try-mocha\node_modules\mocha\lib\runner.js:425:5)
    at processImmediate (internal/timers.js:439:21)
  Error: Execution failed.
  Got error: Error: something wrong happened
  
  Stack trace: Error: something wrong happened
      at throwSomething2 (test\test.js:9:15)
      at Context.<anonymous> (test\test.js:20:5)
      at processImmediate (internal/timers.js:439:21)
      at throwSomething2 (test\test.js:10:9)
      at Context.<anonymous> (test\test.js:20:5)
      at processImmediate (internal/timers.js:439:21)

In the resulting log we can see that Execution failed appears twice.

[dubzzz]

Using Mocha, the following functions result in totally different reports:

function throwSomething2() {
  throw new Error(`Execution failed.`);
}
function throwSomething2() {
  throw new Error(`Execution failed. at throwSomething2 (C:\\dev\\try-mocha\\test\\test.js:9:15)`);
}

First function resulted in:

  1) describe
       it report v2:
     Error: Execution failed.
      at throwSomething2 (test\test.js:23:9)
      at Context.<anonymous> (test\test.js:34:5)
      at processImmediate (internal/timers.js:439:21)

While second function resulted in:

  1) describe
       it report v2:
     Execution failed. at throwSomething2 (C:\dev\try-mocha\test\test.js:9:15)
  Error: Execution failed. at throwSomething2 (test\test.js:9:15)
      at throwSomething2 (test\test.js:24:9)
      at Context.<anonymous> (test\test.js:34:5)
      at processImmediate (internal/timers.js:439:21)

It looks like there is an issue with the way Mocha reports Error objects containing stacks. I'm reporting a potential problem in Mocha. I let you know as soon as I have an answer.

[BourgoisMickael]

I've made a workaround

const fc = require('fast-check')

class FastCheckError extends Error {
  constructor (message, stack) {
    super(message)
    this.name = this.constructor.name
    this.stack += stack
  }
}

function utilCheck (stats) {
  if (!stats.failed) {
    return
  }

  const indent = '     '
  const errorMessage = stats.error.substring(0, stats.error.indexOf('\n'))
  const message = `Property failed after ${stats.numRuns} tests\n\n` +
  `${indent}Replay: {\n${indent} seed: ${stats.seed},\n${indent} path: ${stats.counterexamplePath}\n${indent}}\n` +
  `${indent}Counter example: [${stats.counterexample}]\n` +
  `${indent}Got error: ${errorMessage}\n` +
  `${indent}Encountered failures were: \n${indent} - [${stats.failures.join(`]\n${indent} - [`)}]\n`

  const toRemove = 'Stack trace: '
  const stack = '\n\n  Property-based testing (fast-check) stack trace:\n  ' +
  stats.error.substring(stats.error.indexOf(toRemove) + toRemove.length)

  throw new FastCheckError(message, stack)
}

describe('workaround', function () {
  it('throw an error', async function () {
    utilCheck(fc.check(
      fc.property(
        fc.integer(), num => { throw new Error(num) }
      ),
      { verbose: true }
    ))
  })
})

This will print the output below:

  1) workaround
       throw an error:
     FastCheckError: Property failed after 1 tests

     Replay: {
      seed: 1453092355,
      path: 0:0
     }
     Counter example: [0]
     Got error: Error: 0
     Encountered failures were: 
      - [-10]
      - [0]

      at utilCheck (workaround.js:28:9)
      at Context.<anonymous> (workaround.js:33:5)
  
    Property-based testing (fast-check) stack trace:
    Error: 0
      at fc.check.fc.property.num (workaround.js:35:39)
      at Property.predicate (node_modules/fast-check/lib/check/property/Property.generated.js:15:105)
      at Property.run (node_modules/fast-check/lib/check/property/Property.generic.js:19:31)
      at runIt (node_modules/fast-check/lib/check/runner/Runner.js:19:32)
      at Object.check (node_modules/fast-check/lib/check/runner/Runner.js:107:11)
      at Context.<anonymous> (workaround.js:33:18)

This way I can separate the stack trace and the error message.

I was thinking, it could be nice to have access to the error message and stack trace separately instead of having the field error containing everything, there could be a field errorMessage and a field errorStack containing the raw stack trace.

And also there could be some kind of formatter or reporter function in parameter for fc.assert to format the output so we don't have to call fc.check and then call a function on the result

[dubzzz]

I'm pretty OK for the idea of a custom reporter. Internally fc.assert somehow defines it's own custom reporter.

The main challenge will be to investigate how we should adapt the parameters of fc.assert. For instance, verbose option might make no sense for custom reporters. Such feature will really benefit from #402 and can drive how we should implement it.

Please fill a Feature request ticket for that. So that I can track it.

[dubzzz]

No update for the moment, I'm waiting an update on the associated Mocha issue https://github.com/mochajs/mocha/issues/3992

[dubzzz]

@BourgoisMickael Sorry for the delay I just got an update on mochajs/mocha#3992. It seems that there is still part of the bug that's remaining.

By the way, I am currently working on something related to this issue. But I am still thinking of it for the moment. I am looking for a easy to use and powerful way to do that when needed

[dubzzz]

It seems that a fix might land soon in mocha. A Pull Request has recently been opened - https://github.com/mochajs/mocha/pull/4399 - to fix the ticket concerning doubled stack traces in mocha - https://github.com/mochajs/mocha/issues/3992

[xamgore]

I encounter the same issue in jest while using fc.assert. Also, stack traces are cut, which is a bit inconvenient.

[dubzzz]

Depending when it will fully be supported by test runners, I'm investigating the idea to replace our composite error copying the original error into the final one by something native Error::cause (implementation #2965).

Ideally, depending how test runners and IDE plan to show them, fast-check could just build its own error agnostic of the original error and reference the original one as a cause 🤔 I'll need to dig a bit more but some browsers like Firefox already show the cause when rendering Error with cause in a console. Alternatively without using that recent feature I can try the same with AggregateError.

[dubzzz]

Closing this issue as the recent merge of https://github.com/dubzzz/fast-check/pull/2965 which makes 'Error with cause' something possible is probably the way to go. Not having to copy the original error within the message of the new one will probably drop many problems including this one. But so far, only one test framework really handle 'Error with cause' properly all others (including Mocha) only drop that part.

Feature will be part of 3.2.0.