692554 - consider last output time when determining test run hang/loop

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, defect)

Description

[Myk Melez [:myk] [@mykmelez]]

Attachment: patch v1: adds output timeout

The test runner should consider the last time a test wrote output when deciding whether or not to abort a test run because of an apparent hang or infinite loop.  Otherwise, it is prone to aborting test runs on slow machines running slow (debug) versions of Firefox, as in these recent runs on Linux and Windows:

https://tbpl.mozilla.org/php/getParsedLog.php?id=6691579&tree=Firefox&full=1
https://tbpl.mozilla.org/php/getParsedLog.php?id=6692941&tree=Firefox&full=1

Here's a patch that adds an output timer that is reset each time output is printed by the test run, which makes it possible to increase the overall test run timeout so that slow but succeeding test runs don't get aborted.

In order to do this, I had to route output through a logfile on all platforms rather than just Windows, since I needed the code to be able to observe output.  I originally tried to do so via StringIO, passing a StringIO instance to mozrunner for use as stdout and stderr handles, but mozrunner passes those handles to subprocess, which calls fileno() on them, and StringIO doesn't support that method.

In any case, routing output through a logfile seems to work just fine (tested on Windows, Mac, and Linux), even though it was originally a workaround for problems on Windows, and folks are conspiring to get rid of it over in bug 692164.

I also renamed `output` to `result` (which seems more descriptive anyway) to avoid confusion with the new `output_timeout` variable.

Comment 1

[Brian Warner [:warner :bwarner]]

Comment on attachment 565323 [details] [diff] [review]
patch v1: adds output timeout

Thoughts:
 * while you're cleaning up __init__.py, I'd drop the "run_timeout" and "output_timeout" variables and just pass e.g. run_timeout=TEST_RUN_TIMEOUT to the run() call. The "timeout=None" followed by "timeout=TEST_RUN_TIMEOUT" clauses were kinda superfluous, and makes me think that there used-to-be/was-planned code to let you override the values with argv parameters.
 * it'd be even simpler to remove all of that from __init__.py and define your TIMEOUT constants in runner.py, and not pass any arguments around.
 * renaming "output" to "result" looks great.

either way, looks good! I'll let you race with Alex to see who lands first: this will conflict with bug 693302, where he turns off the logfile for Fennec. I suspect the "redirect runner output to /dev/null" might resolve his problem, though.

Comment 2

[Myk Melez [:myk] [@mykmelez]]

Thanks Brian, fixed with your suggested changes and the conflict with Alex's patch resolved:

https://github.com/mozilla/addon-sdk/commit/eaa5e461b12bc0e4dc36eb6c054e4a2072d32eec

Comment 3

[Brian Warner [:warner :bwarner]]

oops, looks like I gave you bad advice: that timeout= argument was also preventing timeouts from being enforced on "cfx run". Bug 694613 is tracking the regression.