Error object stored on Runnable._trace leaks memory

[schuay]

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:

mocha/lib/runnable.js

Line 56 in 2303c66

this._trace = new Error('done() called multiple times');

.

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.

[boneskull]

@schuay Is this a bug in V8?

[boneskull]

Webpack's workaround

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.

[boneskull]

if it turns out that this is a "feature" and not a "bug" in V8, then we should modify Mocha, and this seems reasonable:

this._trace = new Error().stack;

then we can just console.error(this._trace) if it triggers.

[schuay]

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?

[boneskull]

@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):

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.

[boneskull]

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 😝

[schuay]

Hmm, I'm not familiar with Mocha at all. Could you elaborate what the problem is in your previous code example?

[boneskull]

@schuay So, you call done to tell Mocha your test is finished. This allows you to do async things (in lieu of Promises) 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:

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?

[schuay]

I see, thanks. If you don't necessarily need the full stack trace, another option would be V8's prepareStackTrace API.

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, although I suppose that won't be relevant for you.

[boneskull]

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)?

[schuay]

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.

[alexkozy]

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.

[sokra]

this._trace.stack = this._trace.stack;

This is a workaround without functional changes. It forces v8 to "calculate" the stack trace as string.

[schuay]

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.

[boneskull]

"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

[harrysarson]

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 :)

[boneskull]

@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.