Repository: mochajs/mocha

Problem statement:
Error object stored on Runnable._trace leaks memory
FYI: In V8, Error objects keep closures alive until the `err.stack` property is accessed, which prevents collection of the closure (and associated objects) until the Error objects die.

Mocha creates a long-living Error for each Runnable: https://github.com/mochajs/mocha/blob/2303c669ef1b47fef7cf86f5ef486d537033d443/lib/runnable.js#L56.

Would it make sense to either 1. store a string message instead of an Error, or 2. clear Error.stack, or 3. format Error.stack eagerly instead?

See also: https://crbug.com/v8/7142 and https://twitter.com/wSokra/status/935790750188625920.


Hints:
@schuay Is this a bug in V8?
[Webpack's workaround](https://github.com/webpack/webpack/commit/be2477bac7324af5ee0ad9abe899df9639fed263)

I don't really think Mocha should be changing any code unless there are widespread problems with this.  If it's a handful of projects having the problem, they should be able to work around it.
if it turns out that this is a "feature" and not a "bug" in V8, then we should modify Mocha, and this seems reasonable:

```js
this._trace = new Error().stack;
```

then we can just `console.error(this._trace)` if it triggers.
I wouldn't necessarily call it a bug on the V8 side. Our expectation is that in general Error objects are not long-lived, that not a huge number of them are live at once, and that for most Error objects the `stack` property will not be accessed.

Lazy stack formatting exploits that to skip expensive work. But that leads to the 'leak' in this case since we need to keep a few objects around in order to be able to format the stack later.

Your proposed solution above will basically format `stack` eagerly, and depending on how often it's called, may lead to significant slowdown.

So I'm not sure there's currently a perfect solution that will be ideal in all use-cases. In V8, we may be able to avoid keeping the closure alive, which might already improve things significantly.

Would it be an option to avoid exposing stack traces entirely?
@schuay Yes, you're right about the slowdown.

The point of storing the `Error` is the stack itself.  It's used if someone does this (and yes, code like this gets written; we just get fewer bug reports about it now that we provide a stack):

```js
describe('test suite', function () {
  it('is an async test which is bad', function (done) {
    setTimeout(() => {
      done(); // this test passes
      setTimeout(done); // but this is a problem.
    });
  });

  it('is an async test just minding its own business', function (done) {
    setTimeout(() => {
      // the previous test's error appears somewhere around here,
      // even though this test also passes!  
      done();
    }); 
  });
});
```

IMO, the "real" solution is one of:

1. native language support for "zones" or "async hooks" or whatever, because it's painful to connect the dots otherwise, OR
2. tail call support so that we can run tests in a recursive manner w/o having to break the stack via calls to `setImmediate()` due to "Maximum call stack exceeded" problems

Mocha could address this by basically implementing @sokra's hack behind a flag, I guess.
ugh, and the `Error` never goes out of scope because we have to call `setImmediate()` to avoid maximum call stack problems, right?

maybe someone can spend an afternoon and rewrite the test runner as a `for` loop 😝 
Hmm, I'm not familiar with Mocha at all. Could you elaborate what the problem is in your previous code example?
@schuay So, you call `done` to tell Mocha your test is finished.  This allows you to do async things (in lieu of `Promise`s) within your test, e.g. `setTimeout()` or HTTP requests or whathaveyou.

When that async execution is complete, the user executes the `done` callback, and the test is complete.

But this doesn't necessarily halt execution of the test.  Users can do weird stuff (and they do) like trying to call that `done` callback multiple times.  This is indicative of a Problem in the user's code.

Given the example as similar to the above:

```js
describe('test suite', function () {
  it('is a good async test', function (done) {
    setTimeout(done);
  });

  it('is a good synchronous test', function () {
    // omitting the parameter means the test is not expected to be asynchronous
    // unless a Promise is returned
  });

  it('is an async test which is bad', function (done) {
    setTimeout(() => {
      done(); // this test passes
      setTimeout(done); // but this is a problem.
    });
  });

  it('is an async test just minding its own business', function (done) {
    setTimeout(() => {
      // the previous test's error appears somewhere around here,
      // even though this test also passes!  
      done();
    }); 
  });
});
```

We will see output from Mocha like this (roughly):

```
- test suite
  - is a good async test - **OK**
  - is a good synchronous test - **OK**
  - is an async test which is bad - **OK**
  - is an async test just minding its own business 
**ERROR**: done() callback called twice <insert stack trace here> - **OK**
```

Now, where did we call `done()` twice?  This is confusing for the user.  We won't know without that stack as saved via `this._trace`; each test is run in its own `setImmediate()` callback.

Does that help?
I see, thanks. If you don't necessarily need the full stack trace, another option would be V8's `prepareStackTrace` [API](https://github.com/v8/v8/wiki/Stack-Trace-API#customizing-stack-traces). 

Using that, you could fetch e.g. the line/column numbers and the file name of the top frame and skip full stack trace formatting. Once the stack is formatted that way, all internal information (e.g. the closure and receiver of each frame) is freed.

Of course, ensuring that Error objects go out of scope at some point would be the best fix :)

And just FYI, there's also support for async stacks in DevTools / the [inspector protocol](https://chromedevtools.github.io/devtools-protocol/tot/Debugger/#event-paused), although I suppose that won't be relevant for you.
> I see, thanks. If you don't necessarily need the full stack trace, another option would be V8's prepareStackTrace API.

Mocha doesn't *just* run in V8, so we can't use runtime-specific APIs.

> And just FYI, there's also support for async stacks in DevTools / the inspector protocol, although I suppose that won't be relevant for you.

It is relevant, actually.  While it means the user will need to open a separate tool to track down what's going on, at least such a tool now exists.  

That means it may be OK to simply drop the stack and tell the user to open an inspector to figure it out.  😛 

@schuay In what version of V8 was this behavior introduced (specifically, which Node.js version does it correspond to)?
> Mocha doesn't just run in V8, so we can't use runtime-specific APIs.

In theory you could check for the existence of `Error.prepareStackTrace`, but I agree it's not a nice solution.

> @schuay In what version of V8 was this behavior introduced (specifically, which Node.js version does it correspond to)?

Hmm, not sure, but it's been roughly one year from looking at `git blame`. cc @ak239 and @hashseed who will know exactly when async stack traces were released.
Latest Node.js supports inspector bindings, so in theory you can enable async stacks using Debugger domain and then somehow fetch this stack trace.
But I believe that we should provide capabilities in JavaScript runtime which will allow to enable / disable async stacks. Something like Error.captureAsyncStacks(true) and then Error.stack will contain async stacks as well.
``` js
this._trace.stack = this._trace.stack;
```

This is a workaround without functional changes. It forces v8 to "calculate" the stack trace as string.
> This is a workaround without functional changes. It forces v8 to "calculate" the stack trace as string.

Accessing `stack` is enough to force eager formatting and clear internal data, no need to write to it.

But as discussed above, eager formatting is probably to slow to be a viable fix. I think `this._trace` should just be removed and debugging async stacks delegated to proper tools.
"Fixing" this bug will cause loss of functionality, but it's only "exceptional" functionality which should not be directly relied on, so I'm calling it `semver-patch`
Could the stack trace be stored only when a command line flag (something like `--debug-multiple-done-calls`) is set. Then if `done()` is called twice mocha could instruct the user to run the test again, this time with the flag set.

The slowdown of eager formatting would be acceptable because it would only occur when a user was trying to find where done was called twice.

Just my two cents :) 
@HarrySarson Not a bad idea, but it's also kind of an obscure thing to add a command-line flag for.  AFAIK this also affects browser (Chrome) users.

I think I'd like to just rip it out for now and see how it goes.  

Patch:
diff --git a/lib/runnable.js b/lib/runnable.js
--- a/lib/runnable.js
+++ b/lib/runnable.js
@@ -53,7 +53,6 @@ function Runnable (title, fn) {
   this._slow = 75;
   this._enableTimeouts = true;
   this.timedOut = false;
-  this._trace = new Error('done() called multiple times');
   this._retries = -1;
   this._currentRetry = 0;
   this.pending = false;
@@ -278,7 +277,13 @@ Runnable.prototype.run = function (fn) {
       return;
     }
     emitted = true;
-    self.emit('error', err || new Error('done() called multiple times; stacktrace may be inaccurate'));
+    var msg = 'done() called multiple times';
+    if (err && err.message) {
+      err.message += " (and Mocha's " + msg + ')';
+      self.emit('error', err);
+    } else {
+      self.emit('error', new Error(msg));
+    }
   }
 
   // finished
@@ -287,8 +292,9 @@ Runnable.prototype.run = function (fn) {
     if (self.timedOut) {
       return;
     }
+
     if (finished) {
-      return multiple(err || self._trace);
+      return multiple(err);
     }
 
     self.clearTimeout();


Test patch:
diff --git a/test/integration/fixtures/multiple-done-with-error.fixture.js b/test/integration/fixtures/multiple-done-with-error.fixture.js
new file mode 100644
--- /dev/null
+++ b/test/integration/fixtures/multiple-done-with-error.fixture.js
@@ -0,0 +1,8 @@
+'use strict';
+
+it('should fail in a test-case', function (done) {
+  process.nextTick(function () {
+    done();
+    done(new Error('second error'));
+  });
+});
diff --git a/test/integration/multiple-done.spec.js b/test/integration/multiple-done.spec.js
--- a/test/integration/multiple-done.spec.js
+++ b/test/integration/multiple-done.spec.js
@@ -15,15 +15,35 @@ describe('multiple calls to done()', function () {
     });
 
     it('results in failures', function () {
-      assert.equal(res.stats.pending, 0);
-      assert.equal(res.stats.passes, 1);
-      assert.equal(res.stats.failures, 1);
-      assert.equal(res.code, 1);
+      assert.equal(res.stats.pending, 0, 'wrong "pending" count');
+      assert.equal(res.stats.passes, 1, 'wrong "passes" count');
+      assert.equal(res.stats.failures, 1, 'wrong "failures" count');
     });
 
     it('throws a descriptive error', function () {
-      assert.equal(res.failures[0].err.message,
-        'done() called multiple times');
+      assert.equal(res.failures[0].err.message, 'done() called multiple times');
+    });
+  });
+
+  describe('with error passed on second call', function () {
+    before(function (done) {
+      run('multiple-done-with-error.fixture.js', args, function (err, result) {
+        res = result;
+        done(err);
+      });
+    });
+
+    it('results in failures', function () {
+      assert.equal(res.stats.pending, 0, 'wrong "pending" count');
+      assert.equal(res.stats.passes, 1, 'wrong "passes" count');
+      assert.equal(res.stats.failures, 1, 'wrong "failures" count');
+    });
+
+    it('should throw a descriptive error', function () {
+      assert.equal(
+        res.failures[0].err.message,
+        "second error (and Mocha's done() called multiple times)"
+      );
     });
   });
 
@@ -44,8 +64,7 @@ describe('multiple calls to done()', function () {
 
     it('correctly attributes the error', function () {
       assert.equal(res.failures[0].fullTitle, 'suite test1');
-      assert.equal(res.failures[0].err.message,
-        'done() called multiple times');
+      assert.equal(res.failures[0].err.message, 'done() called multiple times');
     });
   });
 
@@ -66,8 +85,7 @@ describe('multiple calls to done()', function () {
 
     it('correctly attributes the error', function () {
       assert.equal(res.failures[0].fullTitle, 'suite "before all" hook');
-      assert.equal(res.failures[0].err.message,
-        'done() called multiple times');
+      assert.equal(res.failures[0].err.message, 'done() called multiple times');
     });
   });
 
@@ -90,8 +108,7 @@ describe('multiple calls to done()', function () {
       assert.equal(res.failures.length, 2);
       res.failures.forEach(function (failure) {
         assert.equal(failure.fullTitle, 'suite "before each" hook');
-        assert.equal(failure.err.message,
-          'done() called multiple times');
+        assert.equal(failure.err.message, 'done() called multiple times');
       });
     });
   });
diff --git a/test/unit/runnable.spec.js b/test/unit/runnable.spec.js
--- a/test/unit/runnable.spec.js
+++ b/test/unit/runnable.spec.js
@@ -270,7 +270,8 @@ describe('Runnable(title, fn)', function () {
 
             test.on('error', function (err) {
               ++errCalls;
-              expect(err.message).to.equal('fail');
+              expect(err.message).to.equal(
+                "fail (and Mocha's done() called multiple times)");
               expect(calls).to.equal(1);
               expect(errCalls).to.equal(1);
               done();