mocha icon indicating copy to clipboard operation
mocha copied to clipboard

fix: do not exit when only unref'd timer is present in test code

Open boneskull opened this issue 6 years ago • 21 comments

In the timeout-handling code in Runnable#resetTimeout, if _enableTimeouts was false, Mocha would completely avoid setting a timer, even if the timeout was set to 0.

This PR changes the behavior so that a timer is always set, regardless of _enableTimeouts. If the test timeout value is 0, we set it to the maximum delay value (docs). ~~Even if you happen to leave Mocha running in your debugger for longer than 24.8 days, the timer will just reset itself instead of throw a timeout error. Talk about corner cases...~~

UPDATE: Resetting the timeout is problematic if timeouts are disabled after the timeout is reset. We don't really need this behavior anyway.

Fixes #3817.

boneskull avatar Mar 11 '19 18:03 boneskull

@rolfl, can you give this code a try?

boneskull avatar Mar 11 '19 18:03 boneskull

I note that _enableTimeouts is essentially a useless, internal flag that could be removed (across several different files) if we assume a timeout value of 0 is false and anything else is true.

boneskull avatar Mar 11 '19 18:03 boneskull

@boneskull - I pulled your branch in to my local copy of mocha, I then npm link'd it in to my own project's npm repo, and ran the tests that initially caused my failues, in both normal, and debug mode, using webstorm to do it. (i.e. the worst case scenario). I also ran individual tests as selected from the WebStorm UI that uses the --grep functionality to run individual tests only.

I can (happily) report a success. It ran all tests and skipped none (and these things were failing before).

rolfl avatar Mar 11 '19 18:03 rolfl

How/when is the timeout cleared?

juergba avatar Mar 11 '19 19:03 juergba

@juergba - when the task completes: https://github.com/mochajs/mocha/blob/603da4464f34b58fb7bc96707680976b0f76cbe3/lib/runnable.js#L330

rolfl avatar Mar 11 '19 19:03 rolfl

Unfortunately there's more to be done here. My guess is there's a problem with --no-exit / --exit behavior, as the builds seem to hang.

boneskull avatar Mar 11 '19 19:03 boneskull

@boneskull - I ran in to the unit tests here hanging with --timeout 0 - as I mentioned in #3817. It may help you narrow down the issue... maybe. https://github.com/mochajs/mocha/blob/master/test/unit/mocha.spec.js#L281

rolfl avatar Mar 11 '19 19:03 rolfl

what I'm seeing is a hang in the Runnable unit tests around some edge-case stuff

boneskull avatar Mar 11 '19 19:03 boneskull

alright, think I fixed that problem.

boneskull avatar Mar 11 '19 19:03 boneskull

Coverage Status

coverage: 94.33% (-0.03%) from 94.359% when pulling 1dbfcf7e3a442792b7eef007d429296e55351f53 on boneskull/issue/3817 into 2f3fedcc41cbb9d3e503d84098fcc07d7c3c49f1 on master.

coveralls avatar Mar 11 '19 20:03 coveralls

I'm going to sit on this until I get at least one review

boneskull avatar Mar 11 '19 21:03 boneskull

out of topic: when debugging with VSCode, the CL input looks like this: node.exe --inspect-brk=19942 bin\_mocha D:/mocha3291/unref.js

This way the --inspect-brk is consumed directly by node and is not piped through Mocha first. Therefore timeout=0 has to be set manually while debugging in order to avoid a timeout error.

Nevertheless docu states:

Implies --no-timeout.

juergba avatar Mar 12 '19 09:03 juergba

When I run

'use strict';

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

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

the output is:

√ just kind of stops
√ just kind of stops

2 passing (31ms)

while debugging the same code, the output contains additional duration information:

√ just kind of stops (9410ms)
√ just kind of stops (5798ms)
2 passing (15s)

juergba avatar Mar 12 '19 09:03 juergba

This solution sets a timer for each individual test. Just as if user would call --timeout 999999 by himself or Mocha translates --timeout 0 into --timeout 999999 for convenience.

I would prefer a root timer, similar to the one proposed by @rolfl.

In "Mocha.prototype.run":

var runner = new exports.Runner(suite, options.delay);
  var setTimeout = global.setTimeout;
  if (suite._timeout === 0) {
    runner.rootTimer = setTimeout(function() {}, 999999);
  }

rootTimer has to be cleared on the EVENT_RUN_END event. This works and "npm test" terminates successfully. Yes, there is this issue with the global timers.

juergba avatar Mar 12 '19 13:03 juergba

I would prefer a root timer, similar to the one proposed by @rolfl.

I'd have to see this working to be convinced it's the right choice.

UPDATE:

Let me clarify.

  1. This of course adds an extra timer, regardless of the value of timeout.
  2. Most runs of Mocha will have a nonzero timeout value.
  3. I don't fully understand the impact and if there are any unintended consequences to doing this (FUD). Does this impact watch mode, signals, --exit/--no-exit, browsers? While our test coverage is pretty OK in Node.js, there's always edge cases and interplay between various usages that we're missing.

This PR sticks to the "status quo", so I'm more comfortable with this strategy.

boneskull avatar Mar 12 '19 18:03 boneskull

√ just kind of stops (9410ms) √ just kind of stops (5798ms) 2 passing (15s)

This is "slow" output. People using --timeout 0 or --timeout 99999999 don't usually bother setting --slow 0 or --slow 99999999999 anyway; this is how you'd suppress it.

I wouldn't be opposed to updating the default value of slow to be a function of the value of timeout (I've mentioned this before) but it doesn't belong in this PR.

boneskull avatar Mar 12 '19 18:03 boneskull

This way the --inspect-brk is consumed directly by node and is not piped through Mocha first. Therefore timeout=0 has to be set manually while debugging in order to avoid a timeout error.

This is why the debuggers which, when creating a "Mocha" debug profile, use node bin/_mocha --inspect-brk --timeout <value>.

The documentation is technically correct, but it might be worth mentioning that this only applies when executing bin/mocha. Please create an issue?

boneskull avatar Mar 12 '19 18:03 boneskull

@boneskull - re:

I would prefer a root timer, similar to the one proposed by @rolfl.

I'd have to see this working to be convinced it's the right choice.

In all my testing with the solution I proposed (using an interval instead of a timeout to avoid the 24-day limit) it works really well except for in the base mocha.#run() test case, where it appears sinon is interfering with either the setInterval or the clearInterval. I can investigate further, but the basic logic is similar to the logic you propose, except I put it out her for the overall run, wheras your change above puts it there for the individual suites. I put a ref() interval on the event loop that prevents node exit... and clear it when the mocha.run completes (on end event or done(...) call.

rolfl avatar Mar 12 '19 18:03 rolfl

@rolfl I can't see what you did, but you can't just use setTimeout or setInterval without dereferencing it, e.g. var setInterval = global.setInterval, because Sinon (or Unexpected, or any other test helper) could monkey with it. you may have gotten an ESLint error if this was the case.

boneskull avatar Mar 13 '19 22:03 boneskull

@juergba Would like to know if you are insistent on a "global" timer?

boneskull avatar Mar 13 '19 22:03 boneskull

BTW just noted, there is a very old branch about that issue: https://github.com/mochajs/mocha/commit/ead35769eea3e4576b53e8fe7cfdfa441c505b1c

juergba avatar Mar 14 '19 10:03 juergba

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

s/o @boneskull for setting up this change over five years ago.

JoshuaKGoldberg avatar Jul 20 '24 17:07 JoshuaKGoldberg