🐛 Bug: --timeout 0 with unref'd timers causes process exit

[rolfl]

Background context - SSCCE to follow. Bear with me, this behaviour is somewhat bizarre, so explaining it is complicated....

When using WebStorm as an IDE, it can run the mocha tests in "run" mode or "debug" mode. If the tests are constructed in a particular way (specifically - using promises) In "run" mode, everything works fine. In debug mode, all the tests are ignored.... in WebStorm, it looks like:

It took me a lot of trial-and-error to identify the "root cause", but it boils down to the --timeout 0 that webstorm adds when doing the node --inspect-brk part of debugging. The timeout 0 is added to allow breakpoints to pause the code without causing the tests to time out.

The problem can be explained with the following test case:

'use strict';


function slowThing() {
  return new Promise(resolve => setTimeout(resolve, 10).unref());
}

describe('This has lots of 10ms tests', function() {
  it('10ms', () => slowThing());
});

Note, all the test does, is wait 10ms, and then succeed.

There are 2 key features in the above....

1. it returns a promise in the it(...) test.
2. it does an unref() on the setTimeout()

If you run the above normally, it succeeds node ./node_modules/mocha/bin/_mocha --ui bdd tests/sscce.spec.js:

  This has lots of 10ms tests
    ✓ 10ms

  1 passing (34ms)

If you add --timeout 0 it completes successfully, but does not actually run the test: node ./node_modules/mocha/bin/_mocha --timeout 0 --ui bdd tests/sscce.spec.js && echo pass gives:

  This has lots of 10ms tests
pass

The same is true (it also fails) if you run in debug mode (--inspect).

BUT, if you add a second --timeout 0 it will then work correctly: node ./node_modules/mocha/bin/_mocha --timeout 0 --timeout 0 --ui bdd tests/sscce.spec.js && echo pass

  This has lots of 10ms tests
    ✓ 10ms

  1 passing (18ms)
pass

My guess is that the code that waits for Promise-based tests to complete is not actively waiting on the promise, so the node system discovers there are no events to prevent system exit, so it exits...

But, for the life of me, I don't understand why adding multiple --timeout 0 flags makes it work.....

Oh, and, if you use WebStorm, you end up having to add 2 --timeout 0 flags in your configuration, so that when you run the tests it has 2 timeouts, and when you debug, it has 3.

Edited to add versions:

rolf@rolf-vb:~/bmix/debugsscce$ node --version
v8.15.1
rolf@rolf-vb:~/bmix/debugsscce$ npm list mocha
[email protected] /home/rolf/bmix/debugsscce
└── [email protected]

[plroebuck]

@boneskull, look at this...

[juergba]

Try to remove all --timeout flags while debugging, incl. the one inserted by your IDE.

Update in v6.0.0: --no-timeout is implied when invoking Mocha using debug flags. It is equivalent to --timeout 0. --timeout 99999999 is no longer needed.

[rolfl]

@juergba - I should note that I can't remove the --timeout 0 that WebStorm injects.... I'll initiate communication with them about it. Having said that, that would still just be a workaround for the bug, not a fix. The bug is clearly in the --timeout 0 causing tests to be ignored.

Also, if I run with the flag --no-timeout , mocha skips the tests anyway.... so it's an issue with --no-timeout too.

rolf@rolf-vb:~/bmix/debugsscce$ node ./node_modules/.bin/mocha tests/sscce.spec.js


  This has lots of 10ms tests
    ✓ 10ms


  1 passing (35ms)

rolf@rolf-vb:~/bmix/debugsscce$ node ./node_modules/.bin/mocha --no-timeout tests/sscce.spec.js


  This has lots of 10ms tests
rolf@rolf-vb:~/bmix/debugsscce$

[boneskull]

--no-timeout and --timeout 0 are equivalent.

Do your tests get ignored outside of webstorm when using --inspect-brk?

cc @segrey

[boneskull]

Ah, looks like you answered that.

[boneskull]

The problem is with unref(). You said this doesn't happen in Mocha v5.x?

[boneskull]

Seems like it works in v5.2.0 when using --timeout 9999999, but not --timeout 0, so there's obviously some further problem in the timeout-handling code.

[boneskull]

(@segrey, nevermind, this doesn't have anything to do with webstorm)

[boneskull]

So it looks like because timeouts are disabled within Mocha, and unref() was used, at that point in the stack there's nothing left in the event loop to do, so it looks like node just wants to quit.

The Promise is a red herring; this can be reproduced trivially using --timeout 0 and the following test:

it('just kind of stops', function(done) {
  setTimeout(done, 10).unref();
});

[boneskull]

The bad news is, I'm not sure how to fix this other than suggest you use --timeout 99999999999 to put something in the event loop to prevent the process from exiting.

[rolfl]

@boneskull ... but why does setting --timeout 0 twice make it work again?

[boneskull]

that's a separate bug. it causes the timeout to become NaN which ... I'm not sure what happens then.

[boneskull]

(somebody please make a ticket for weirdness when the CLI parser thinks something like timeout is actually an array, which is what's happening...)

[boneskull]

another workaround, if you can get away with removing .unref() I'd suggest doing that. or just calling .ref() on the timer from your test code if the .unref() is in your code under test.

[rolfl]

We have a bunch of tests that make http calls but the socket is unrefd in a low level library... these calls die. I cannot easily change this... and i would have to modify 100s of tests to wrap them in something refd. The workaround with the doubled timeout will be my preference... until the Cli is fixed.

[rolfl]

@boneskull - I have played with the code a little to figure out what options are available. The underlying issue is that Mocha itself does not prevent exits when test cases are incomplete. It is reasonable for a test to call code that unref's timers, etc. so it is reasonable for mocha to hold the event loop active during tests.

I added a hold on to the event loop for the duration of a Mocha run using the code:

  var eventLoopHold = setInterval(utils.noop, 1000);

  function clearEventLoop() {
    if (!eventLoopHold) {
      return;
    }
    clearInterval(eventLoopHold);
    eventLoopHold.unref();
    eventLoopHold = null;
  }
  runner.once('end', clearEventLoop);

as seen in this change: rolfl@bd4a611#diff-aa849a970cef551664c12f04a4209f6fR833

it works "well", and I also added the "trivial" test case and added it to the test suites.

The issue is in the Mocha.#run() test suites here: https://github.com/mochajs/mocha/blob/master/test/unit/mocha.spec.js#L281 ... these tests use sinon to sandbox, and the sinon fake-timer code is asymmetrically implementing the Timeout. It appears to set the interval just fine, but the clearInterval(), and the timer.unref() are not apparently behaving as expected. As a consequence, the running of the suite does not exit (there's a ref'd interval still).

Before I try to go further, is the adding of the event-loop holding timeout a viable option, and if it is, is there a way to get the mocha unit tests to pass with the sinon fakery?

[juergba]

For this special unref() case, you could add a setTimeout(noop, 99999999) to the root before() hook and a clearTimeout() in the root after() hook. This should keep the event loop running.

[rolfl]

@juergba - that's true, I could. On the other hand, I would have to add it to all files/tests because it is common when in the IDE doing TDD to set up a test-case, and ru just that one test case. The before/after would have to be called when running any single test too. It's not a practical solution.

Again, the bug is that mocha is not waiting for a test to complete before the mocha exits. The fact that the code-under-test is not locking the event loop is good for that code.

[boneskull]

@rolfl There is no fix (that I'm aware of) other than using --timeout 999999. This behavior is not new in Mocha v6.

[boneskull]

Before I try to go further, is the adding of the event-loop holding timeout a viable option, and if it is, is there a way to get the mocha unit tests to pass with the sinon fakery?

Adding a dummy timeout seems like a bandaid on the "real" fix. I am not sure what the "real" fix is.

Mocha does not consume Sinon's fake timers; these are disabled by default by createSandbox(). Don't quite understand what you're talking about in these tests.

[boneskull]

@juergba - that's true, I could. On the other hand, I would have to add it to all files/tests because it is common when in the IDE doing TDD to set up a test-case, and ru just that one test case. The before/after would have to be called when running any single test too. It's not a practical solution.

This is incorrect; you can do this:

// hack.js
let t;

before(function() {
  t = setTimeout(() => {}, 1e9);
});

after(function() {
  clearTimeout(t);
});

run via

$ mocha --file hack.js path/to/tests

[boneskull]

I have an idea to address this. While I have a feeling this is actually "expected behavior" in Node.js, users shouldn't have to deal with it.

[boneskull]

Ref: #3825

[JoshuaKGoldberg]

Released in [email protected]. We did it! 🚀