🐛 Bug: Reports the Error twice when its message contains something similar to a stack

[dubzzz]

Prerequisites

• Checked that your issue hasn't already been filed by cross-referencing issues with the faq label
• Checked next-gen ES issues and syntax problems by using the same environment and/or transpiler configuration without Mocha to ensure it isn't just a feature that actually isn't supported in the environment in question or a bug in your code.
• 'Smoke tested' the code to be tested by running it outside the real test suite to get a better sense of whether the problem is in the code under test, your usage of Mocha, or Mocha itself
• Ensured that there is no discrepancy between the locally and globally installed versions of Mocha. You can find them with: node node_modules/.bin/mocha --version(Local) and mocha --version(Global). We recommend that you not install Mocha globally.

Description

Mocha reports twice the Error instance when it contains something that looks similar to a stacktrace.

As a consequence throw new Error("Oups."); and throw new Error("Oups. at plouf (C:\\dev\\try-mocha\\test.js:9:15)"); will not be treated the same way in the report of Mocha.

Steps to Reproduce

Here is a small spec file to reproduce:

function oups() {
  throw new Error(`Oups.`);
}
function oupsStack() {
  throw new Error(`Oups. at plouf (C:\\dev\\try-mocha\\test.js:9:15)`);
}
describe("describe", () => {
  it("it oups", () => {
    oups();
  });
  it("it oupsStack", () => {
    oupsStack();
  });
});

Error related to dubzzz/fast-check#399

Expected behavior: [What you expect to happen]

The reports of oups and oupsStack should be similar (even if oupsStack contains something similar to a stack trace).
I would have expected the following error report from mocha:

  1) describe
       it oups:
     Error: Oups.
      at oups (test\test2.js:2:9)
      at Context.<anonymous> (test\test2.js:11:5)
      at processImmediate (internal/timers.js:439:21)

  2) describe
       it oupsStack:
     Error: Oups. at plouf (C:\dev\try-mocha\test.js:9:15)
      at oupsStack (test\test2.js:6:9)
      at Context.<anonymous> (test\test2.js:14:5)
      at processImmediate (internal/timers.js:439:21)

Actual behavior: [What actually happens]

Here is the actual report I got from Mocha:

  1) describe
       it oups:
     Error: Oups.
      at oups (test\test2.js:2:9)
      at Context.<anonymous> (test\test2.js:11:5)
      at processImmediate (internal/timers.js:439:21)

  2) describe
       it oupsStack:
     Oups. at plouf (C:\dev\try-mocha\test.js:9:15)
  Error: Oups. at plouf (test.js:9:15)
      at oupsStack (test\test2.js:6:9)
      at Context.<anonymous> (test\test2.js:14:5)
      at processImmediate (internal/timers.js:439:21)

We can see that Oups. at plouf is visible twice in the log while Oups. is only visible once.

Reproduces how often: [What percentage of the time does it reproduce?]

Versions

• The output of mocha --version and node node_modules/.bin/mocha --version:
  • mocha --version: none
  • node_modules/.bin/mocha --version: 6.2.0
• The output of node --version: 12.6.0
• Your operating system
  • name and version: Windows 10
  • architecture (32 or 64-bit): 64bits
• Your shell (e.g., bash, zsh, PowerShell, cmd): git bash
• Any code transpiler (e.g., TypeScript, CoffeeScript, Babel) being used (and its version): pure js without any transpilers

[craigtaub]

Sorry nobody replied sooner. Just tried this on mocha v7 on a mac and got the expected

  1) describe
       it oups:
     Error: Oups.
      at oups (test/test.spec.js:19:9)
      at Context.<anonymous> (test/test.spec.js:26:5)
      ...
      at processImmediate (internal/timers.js:445:21)

  2) describe
       it oupsStack:
     Error: Oups. at plouf (C:\dev\try-mocha\test.js:9:15)
      at oupsStack (test/test.spec.js:22:9)
      at Context.<anonymous> (test/test.spec.js:29:5)
      ...
      at processImmediate (internal/timers.js:445:21)

I believe this is now resolved in latest.

[dubzzz]

Indeed, thanks a lot 👍
It seems that the issue is now fixed with the latest version of mocha

[dubzzz]

@craigtaub While it works for the two examples above, I still have an issue when the message contained into the error looks like a stacktrace, here is an example of the issue:

function oupsStackStack() {
  const err = new Error();
  throw new Error(`An error occured with following trace:\n\n${err.stack}`);
}
describe("describe", () => {
  it("it oupsStackStack", () => {
    oupsStackStack();
  });
});

If you run this snippet with Mocha 7.2.0, you should see the error message An error occured with following trace twice in the report.

When I ran it, the reported error was the following (with mocha 7.2.0):
*bold corresponds to the red part in the report

describe
1) it oupsStackStack

0 passing (5ms)
1 failing

1) describe
it oupsStackStack:
An error occured with following trace:

Error
at oupsStackStack (C:\Users\mocha-fs\spec.js:2:15)
at Context. (C:\Users\mocha-fs\spec.js:7:5)
at callFn (C:\Users\mocha-fs\node_modules\mocha\lib\runnable.js:374:21)
at Test.Runnable.run (C:\Users\mocha-fs\node_modules\mocha\lib\runnable.js:361:7)
at Runner.runTest (C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:619:10)
at C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:745:12
at next (C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:536:14)
at C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:546:7
at next (C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:448:14)
at Immediate._onImmediate (C:\Users\mocha-fs\node_modules\mocha\lib\runner.js:514:5)
at processImmediate (internal/timers.js:439:21)
Error: An error occured with following trace:

Error
at oupsStackStack (spec.js:2:15)
at Context. (spec.js:7:5)
at processImmediate (internal/timers.js:439:21)
at oupsStackStack (spec.js:3:9)
at Context. (spec.js:7:5)
at processImmediate (internal/timers.js:439:21)

While I would have expected something like:

describe
1) it oupsStackStack

0 passing (5ms)
1 failing

1) describe
it oupsStackStack:
An error occured with following trace:

Error
at oupsStackStack (C:\mocha-fs\spec.js:2:15)
at Context. (C:\mocha-fs\spec.js:7:5)
at callFn (C:\mocha-fs\node_modules\mocha\lib\runnable.js:374:21)
at Test.Runnable.run (C:\mocha-fs\node_modules\mocha\lib\runnable.js:361:7)
at Runner.runTest (C:\mocha-fs\node_modules\mocha\lib\runner.js:619:10)
at C:\mocha-fs\node_modules\mocha\lib\runner.js:745:12
at next (C:\mocha-fs\node_modules\mocha\lib\runner.js:536:14)
at C:\mocha-fs\node_modules\mocha\lib\runner.js:546:7
at next (C:\mocha-fs\node_modules\mocha\lib\runner.js:448:14)
at Immediate._onImmediate (C:\mocha-fs\node_modules\mocha\lib\runner.js:514:5)
at processImmediate (internal/timers.js:439:21)
at oupsStackStack (spec.js:3:9)
at Context. (spec.js:7:5)
at processImmediate (internal/timers.js:439:21)

[craigtaub]

Ah I see, so the message is

Error
at oupsStackStack (C:\mocha-fs\spec.js:2:15)
at Context. (C:\mocha-fs\spec.js:7:5)
at callFn (C:\mocha-fs\node_modules\mocha\lib\runnable.js:374:21)
at Test.Runnable.run (C:\mocha-fs\node_modules\mocha\lib\runnable.js:361:7)
at Runner.runTest (C:\mocha-fs\node_modules\mocha\lib\runner.js:619:10)
at C:\mocha-fs\node_modules\mocha\lib\runner.js:745:12
at next (C:\mocha-fs\node_modules\mocha\lib\runner.js:536:14)
at C:\mocha-fs\node_modules\mocha\lib\runner.js:546:7
at next (C:\mocha-fs\node_modules\mocha\lib\runner.js:448:14)
at Immediate._onImmediate (C:\mocha-fs\node_modules\mocha\lib\runner.js:514:5)
at processImmediate (internal/timers.js:439:21)

So should print that then the call stack. Odd. Not sure its a big issue but certainly seems odd.

Ran this as a normal node script and printed what submitter has suggested it should. Assuming a bug or at least needs further investigation.

[JoshuaKGoldberg]

Confirmed that the snippet in #3992 (comment) gives the duplicate error stack still.

[dubzzz]

Given mocha properly handles errors with cause, I believe the recommended approach would be to use it instead of copying the stack in the message. I updated my library (fast-check) to switch to error with cause (will be the default starting at v4).