Mocha failing when error message too big

[furstenheim]

Description

Mocha never ends with big error messages

Steps to Reproduce

const {expect} = require('chai')
 it('Test failing', function () {
      const longArray = _.times(10000, function (i) {
        return {a : i}
      })
      const shortArray = []
      expect(longArray).deep.equal(shortArray)
})

Then execute yarn mocha test --exit, the test will execute it will be marked as failure, but the summary will never appear and the process will not exit.

If on contrary one writes:

const {expect} = require('chai')
 it('Test failing', function () {
      const longArray = _.times(10000, function (i) {
        return {a : i}
      })
      const shortArray = []
      try {
        expect(longArray).deep.equal(shortArray)
     } catch (e) {
        console.error(e)
        throw new Error('Small error')
     }
})

The test fails and it displays an error in the summary. Error is logged without any problem.

Expected behavior: [What you expect to happen]
Mocha should be able to exit the process even if the error is overly long. Maybe the message could be reduced?

Actual behavior: [What actually happens]
The process hangs forever

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

Versions

Mocha 5.1.1

• The output of mocha --version and node node_modules/.bin/mocha --version:
• The output of node --version:
  v8.11.2
• The version and architecture of your operating system:
  Ubuntu
• Your shell (bash, zsh, PowerShell, cmd, etc.):
  bash
• Your browser and version (if running browser tests):
• Any other third party Mocha related modules (with versions):
• The code transpiler being used:

[boneskull]

Please retry this but use the built in assert module. same result? if so, the problem may be in our diff-generating code.

_{Sent with GitHawk}

[outsideris]

With current master(6b5a785),
it is hang pretty long rather than forever

$ time mocha rr.js


  1) Test failing

  0 passing (106ms)
  1 failing

  1) Test failing:

      AssertionError [ERR_ASSERTION]: Input A expected to strictly deep-equal input B:
+ expected - actual ... Lines skipped

real	1m58.016s
user	2m2.341s
sys	0m0.649s

With assert module, it is same result.

const assert = require('assert');
const _ = require('lodash');

 it('Test failing', function () {
      const longArray = _.times(10000, function (i) {
        return {a : i}
      })
      const shortArray = []
      assert.deepStrictEqual(longArray, shortArray);
});

real	1m56.692s
user	2m1.052s
sys	0m0.571s

[plroebuck]

If it just takes a long time, is that necessarily a "confirmed bug"?

[outsideris]

Because it doesn't take so long without mocha.
So, I thought there is a performance issue in mocha even if I didn't find why.

[boneskull]

This could very well be related to #3686

[cyjake]

@furstenheim Try running mocha again with --full-trace enabled, if it performs well then it sure is related to #3686

[furstenheim]

@cyjake Just tried mocha 5.2.0 (latest) with --full-trace option and the problem persists

[cyjake]

@boneskull I've reproduced this issue locally and done a superficial study of the reason. It is blocked at Base.epilogue() (generateDiff() specifically).

[juergba]

When run in Node without Mocha, the AssertionError output appears very fast and is even shortened, see "Lines skipped".

When run in Mocha there is an additional part, which is not shortened and takes very long. The information content is the same in both parts. I will investigate, maybe we can just skip it. Or do Browsers need that second part?

      AssertionError [ERR_ASSERTION]: Input A expected to strictly deep-equal input B:
+ expected - actual ... Lines skipped

- [
-   {
-     a: 1
-   },
              //  [...]
-   {
-     a: 6
-   },
-   {
...
+ []
...
      + expected - actual         // additional Mocha part

      -[
      -  {
      -    "a": 1
      -  }
      -  {

[juergba]

The first part is read from err.message, an AssertionError of the built in assert module. The output is perfectly formatted and shortened. Unfortunately we can not take this formatted diff for granted with all third party assertion libraries.

The second part is made by Mocha and has to be shortened somehow. Running Mocha with no-diff option, the performance is very fast, since no Mocha diff is created.

[juergba]

Mocha is using jsdiff for creating a diff-patch out off err.actual and err.expected. Since several years there have been open issues regarding heavy performance problems with large files. Maybe we should think about evaluating another package one day.

For now I propose to just shorten the two strings to be compared before creating the diff-patch.

var generateDiff = (exports.generateDiff = function(actual, expected) {
  var diffSize = 4096;
  if (actual.length > diffSize) {
    actual = actual.substring(0, diffSize) + ' ... Lines skipped';
  }
  if (expected.length > diffSize) {
    expected = expected.substring(0, diffSize) + ' ... Lines skipped';
  }
  return exports.inlineDiffs
    ? inlineDiff(actual, expected)
    : unifiedDiff(actual, expected);
});

@furstenheim Do you have time to patch base.js and give it a try with your chai example, please?

[furstenheim]

@juergba checked. That change does the trick

[plroebuck]

Does upgrading our 'jsdiff' dependency make any difference (before making changes to Mocha)?

[juergba]

No, doesn't make any difference.
A nice solution would be using an option like diff-timeout to limit the time spent in building the diff, like Google's diff-match-patch offers.
But there is no sense in making a PR which is ignored to death then.

[wnghdcjfe]

I think it is not JSdiff fault

because..

lib/reporters/base.js

  var msg = diff.createPatch('string', actual, expected); 
  var lines = msg.split('\n').splice(5);

this code spent a lot of time in test code and then result
real 2m40.205s
user 2m43.989s
sys 0m1.058s

so I think it is relevant to diff.createPatch performance in first

But..I think it is wrong. it is only late in mocha! not the jsdiff fault!

I tested same code in only jsdiff

const diff = require('diff')
const _ = require('lodash') 
let actual = _.times(10000, function (i) {
    return {a : i}
})
let expected = []  
actual = JSON.stringify(actual)
expected = JSON.stringify(expected)

var msg = diff.createPatch('string', actual, expected)
console.log(msg)
var lines = msg.split('\n').splice(5);
console.log(lines) 

the result is..
real 0m0.436s
user 0m0.140s
sys 0m0.047s

so fast..

but mocha in diff is 3.5 version and my tested diff version is 4.0 version I will check 4.0 version in mocha

Actually almost I found it!!
In diff structure is like that set diff variable like this

lib > patch > create.js > structuredPatch

var diff =
  /*istanbul ignore start*/
  (0,
  /*istanbul ignore end*/

  /*istanbul ignore start*/
  _line
  /*istanbul ignore end*/
  .
  /*istanbul ignore start*/
  diffLines)
  /*istanbul ignore end*/
  (oldStr, newStr, options);

console.log(diff, _line.diffLines, oldStr, newStr, options)

and then.. it said like this in mocha

 {\n    "a": 9789\n  }\n  {\n    "a": 9790\n  }\n  {\n    "a": 9791\n  }\n  {\n    "a": 9792\n  }\n  {\n    "a": 9793\n  }\n  {\n    "a": 9794\n  }\n  {\n    "a": 9795\n  }\n  {\n    "a": 9796\n  }\n  {\n    "a": 9797\n  }\n  {\n    "a": 9798\n  }\n  {\n    "a": 9799\n  }\n  {\n    "a": 9800\n  }\n  {\n    "a": 9801\n  }\n  {\n    "a": 9802\n  }\n  {\n    "a": 9803\n  }\n  {\n    "a": 9804\n  }\n  {\n    "a": 9805\n  }\n  {\n    "a": 9806\n  }\n  {\n    "a": 9807\n  }\n  {\n    "a": 9808\n  }\n  {\n    "a": 9809\n  }\n  {\n    "a": 9810\n  }\n  {\n    "a": 9811\n  }\n  {\n    "a": 9812\n  }\n  {\n    "a": 9813\n  }\n  {\n    "a": 9814\n  }\n  {\n    "a": 9815\n  }\n  {\n   

but..!!!
in only diff

"a":9949},{"a":9950},{"a":9951},{"a":9952},{"a":9953},{"a":9954},{"a":9955},{"a":9956},{"a":9957},{"a":9958},{"a":9959},{"a":9960},{"a":9961},{"a":9962},{"a":9963},{"a":9964},{"a":9965},{"a":9966},{"a":9967},{"a":9968},{"a":9969},{"a":9970},{"a":9971},{"a":9972},{"a":9973},{"a":9974},{"a":9975},{"a":9976},{"a":9977},{"a":9978},{"a":9979},{"a":9980},{"a":9981},{"a":9982},{"a":9983},{"a":9984},{"a":9985},{"a":9986},{"a":9987},{"a":9988},{"a":9989},{"a":9990},{"a":9991},{"a":9992},{"a":9993},{"a":9994},{"a":9995},{"a":9996},{"a":9997},{"a":9998},{"a":9999}]'

very clear

in mocha stringify logic is wrong! and now i will figure it out!

[wnghdcjfe]

@juergba
I was wrong.. sorry.the reason is all about the jsdiff

1. I logged to real err.actual and write file to message.txt

//in reporters/base.js
fs.writeFileSync('./message.txt', err.actual);
 msg += generateDiff(err.actual, err.expected);
        // indent stack trace
        stack = stack.replace(/^/gm, '  ');

        // indented test title
        var testTitle = '';
        test.titlePath().forEach(function(str, index) {
          if (index !== 0) {
...

2. and testing jsDiff

const diff = require('diff')
const _ = require('lodash') 
const fs = require('fs') 
const expected = '[]'
const actual = fs.readFileSync('./message.txt').toString(); 
console.log(actual)
var msg = diff.createPatch('string', actual, expected) 
console.log(msg) 

but jsdiff can't handle like.. "a": 9789\n }\n {\n "a": 9790\n }\n ....
I'm sorry to confuse you.

[kevinoid]

I just ran into this issue due to large and difficult to diff err.actual and err.expected objects:

const assert = require('assert');
const zlib = require('zlib');
it('produces a large/slow diff', () => { 
  assert.deepStrictEqual(new zlib.Gzip(), new zlib.Inflate());
});

I killed mocha after 10 minutes. Inspector showed the following stack trace:

at execEditLength (/tmp/example/node_modules/diff/lib/diff/base.js:53:7)
at Diff.diff (/tmp/example/node_modules/diff/lib/diff/base.js:116:19)
at diffLines (/tmp/example/node_modules/diff/lib/diff/line.js:44:19)
at structuredPatch (/tmp/example/node_modules/diff/lib/patch/create.js:20:83)
at createTwoFilesPatch (/tmp/example/node_modules/diff/lib/patch/create.js:126:14)
at Object.createPatch (/tmp/example/node_modules/diff/lib/patch/create.js:146:10)
at unifiedDiff (/tmp/example/node_modules/mocha/lib/reporters/base.js:449:18)
at exports.generateDiff (/tmp/example/node_modules/mocha/lib/reporters/base.js:188:9)
at /tmp/example/node_modules/mocha/lib/reporters/base.js:263:14
at Array.forEach (<anonymous>)
at Function.exports.list (/tmp/example/node_modules/mocha/lib/reporters/base.js:212:12)
at Spec.Base.epilogue (/tmp/example/node_modules/mocha/lib/reporters/base.js:364:10)
at Object.onceWrapper (events.js:286:20)
at Runner.emit (events.js:203:15)
at /tmp/example/node_modules/mocha/lib/runner.js:908:12
at /tmp/example/node_modules/mocha/lib/runner.js:779:7
at next (/tmp/example/node_modules/mocha/lib/runner.js:362:14)
at Immediate._onImmediate (/tmp/example/node_modules/mocha/lib/runner.js:428:5)
at runCallback (timers.js:705:18)
at tryOnImmediate (timers.js:676:5)
at processImmediate (timers.js:658:5)

with actual.length === 107108 and expected.length === 115195.

Mocha is using jsdiff for creating a diff-patch out off err.actual and err.expected. Since several years there have been open issues regarding heavy performance problems with large files. Maybe we should think about evaluating another package one day.

Apparently Google's diff-match-patch compares favorably. (See kpdecker/jsdiff#239).

You may also want to consider limiting the size of the input to diff. Finding a minimal diff of 2 highly-dissimilar multi-MB strings is probably not a good use of time/compute/output screen space, even with a fast algorithm. It could also be an easy interim fix until diff alternatives are evaluated.

[boneskull]

I would like to see this move forward, as we are still getting issues relating to it.

[boneskull]

it has issues from top to bottom -- from the stringification code to the diffing of those canonical results... yuk.