🚀 Feature: Add support for outputting Error cause

[TazmanianDI]

We are using VError to gather up nested traces which is something proving to be very useful with promises and generators (we can actually get complete stack traces that way). However the default reporting with Mocha only outputs the first error in the stack.

For example, with this code:

const VError = require('verror');

describe('Test', () => {
  it('Test', () => {
    function1();
  });
});

function function1() {
  try {
    function2();
  } catch (e) {
    throw new VError(e);
  }
}

function function2() {
  throw new Error('Something Bad');
}

You get the output:

 VError: : Something Bad
  at function1 (test\sandbox.js:13:11)
  at Context.it (test\sandbox.js:5:5)
  at Test.Runnable.run (node_modules\co-mocha\lib\co-mocha.js:43:16)

This doesn't actually tell me where the root error came from (in function2)

If I add a try...catch and then console.error(e) the top level error, I got a lot more detail:

{ VError: : Something Bad
    at function1 (C:\Work\NPS\nps-dev\test\sandbox.js:17:11)
    at Context.it (C:\Work\NPS\nps-dev\test\sandbox.js:6:7)
    at callFn (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runnable.js:343:21)
    at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runnable.js:335:7)
    at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\co-mocha\lib\co-mocha.js:43:16)
    at Runner.runTest (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:444:10)
    at C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:550:12
    at next (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:361:14)
    at C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:371:7
    at next (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:295:14)
    at Immediate.<anonymous> (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:339:5)
    at runCallback (timers.js:649:20)
    at tryOnImmediate (timers.js:622:5)
    at processImmediate [as _immediateCallback] (timers.js:594:5)
  jse_shortmsg: '',
  jse_cause: 
   Error: Something Bad
       at function2 (C:\Work\NPS\nps-dev\test\sandbox.js:22:9)
       at function1 (C:\Work\NPS\nps-dev\test\sandbox.js:15:5)
       at Context.it (C:\Work\NPS\nps-dev\test\sandbox.js:6:7)
       at callFn (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runnable.js:343:21)
       at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runnable.js:335:7)
       at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\co-mocha\lib\co-mocha.js:43:16)
       at Runner.runTest (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:444:10)
       at C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:550:12
       at next (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:361:14)
       at C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:371:7
       at next (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:295:14)
       at Immediate.<anonymous> (C:\Work\NPS\nps-dev\node_modules\mocha\lib\runner.js:339:5)
       at runCallback (timers.js:649:20)
       at tryOnImmediate (timers.js:622:5)
       at processImmediate [as _immediateCallback] (timers.js:594:5),
  jse_info: {},
  message: ': Something Bad' }

Of course, this is incredibly verbose but I would prefer this over less. I suspect this is because of the features that have been implemented that clean up the stack traces. I don't see why those couldn't run recursively and clean up all the nested stacks and output something more like this:

{ VError: : Something Bad
    at function1 (C:\Work\NPS\nps-dev\test\sandbox.js:17:11)
    at Context.it (C:\Work\NPS\nps-dev\test\sandbox.js:6:7)
    at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\co-mocha\lib\co-mocha.js:43:16)
   Error: Something Bad
       at function2 (C:\Work\NPS\nps-dev\test\sandbox.js:22:9)
       at function1 (C:\Work\NPS\nps-dev\test\sandbox.js:15:5)
       at Context.it (C:\Work\NPS\nps-dev\test\sandbox.js:6:7)
       at Test.Runnable.run (C:\Work\NPS\nps-dev\node_modules\co-mocha\lib\co-mocha.js:43:16)

Now I can see the original exception in function2.

[andykais]

any news on this feature?

[andykais]

current workaround:

mocha -r setup.js

// setup.js
const VError = require('verror')

process.on('uncaughtException', error => {
  console.error(VError.fullStack(error))
})
process.on('unhandledRejection', error => {
  console.error(VError.fullStack(error))
})

This isn't ideal however, because we report the error twice. Once from console.error and once from mocha internally.

console.error output looks like this for those curious:

Error: wrapped message: original message
    at CatchSubscriber.e [as selector] (/Users/andrew/Code/scratchwork/scrape-pages/lib/webpack:/scrape-pages/src/util/error.ts:6:17)
    at CatchSubscriber.error (/Users/andrew/Code/scratchwork/scrape-pages/node_modules/rxjs/src/internal/operators/catchError.ts:119:23)
    at MergeMapSubscriber.OuterSubscriber.notifyError (/Users/andrew/Code/scratchwork/scrape-pages/node_modules/rxjs/src/internal/OuterSubscriber.ts:17:22)
    at InnerSubscriber._error (/Users/andrew/Code/scratchwork/scrape-pages/node_modules/rxjs/src/internal/InnerSubscriber.ts:21:17)
caused by: Error: original message
    at ScrapeStep._defineProperty (/Users/andrew/Code/scratchwork/scrape-pages/lib/webpack:/scrape-pages/src/scraper/scrape-step/index.ts:53:11)
    at /Users/andrew/Code/scratchwork/scrape-pages/lib/webpack:/scrape-pages/src/util/rxjs/observables/while-loop.ts:16:27
    ...

[voxpelli]

Here's an old PR implementing this: #2381

[gabegorelick]

This can work if you're willing to use a custom reporter. See https://github.com/unscrambl/mocha-custom-stack-trace-reporter/blob/8c23026d7bc5aef823a0011e3f575b61e039e2c8/src/mochaCustomStackTraceReporter.ts for example. The custom reporter can simply register a fail event handler that updates err.stack.

[JoshuaKGoldberg]

Per #4829, retargeting this to indicate support for Error: cause.