From 29442c3607f897a4cee2d54e7800b14fef51a31f Mon Sep 17 00:00:00 2001 From: Marco Bonardo Date: Fri, 19 Jul 2013 15:51:34 +0200 Subject: [PATCH] Bug 895376 - Make mochitest browser harness distinguish real timeouts from long-running tests. r=gavin --- testing/mochitest/browser-harness.xul | 3 ++ testing/mochitest/browser-test.js | 32 +++++++++++++-- testing/mochitest/tests/browser/Makefile.in | 39 ++++++++++--------- .../tests/browser/browser_fail_timeout.js | 2 +- .../browser/browser_fail_unexpectedTimeout.js | 12 ++++++ 5 files changed, 65 insertions(+), 23 deletions(-) create mode 100644 testing/mochitest/tests/browser/browser_fail_unexpectedTimeout.js diff --git a/testing/mochitest/browser-harness.xul b/testing/mochitest/browser-harness.xul index 7ad1a3f7bd4..1e61665f3c5 100644 --- a/testing/mochitest/browser-harness.xul +++ b/testing/mochitest/browser-harness.xul @@ -117,6 +117,8 @@ this.results = []; this.scope = null; this.duration = 0; + this.unexpectedTimeouts = 0; + this.lastOutputTime = 0; } browserTest.prototype = { get passCount() { @@ -130,6 +132,7 @@ }, addResult: function addResult(result) { + this.lastOutputTime = Date.now(); this.results.push(result); this.dumper.dump(result.result + " | " + this.path + " | " + result.msg + "\n"); diff --git a/testing/mochitest/browser-test.js b/testing/mochitest/browser-test.js index 59600a159fe..4495ddc56c2 100644 --- a/testing/mochitest/browser-test.js +++ b/testing/mochitest/browser-test.js @@ -40,7 +40,7 @@ function testOnLoad() { "chrome,centerscreen,dialog=no,resizable,titlebar,toolbar=no,width=800,height=600", sstring); } else { // This code allows us to redirect without requiring specialpowers for chrome and a11y tests. - function messageHandler(m) { + let messageHandler = function(m) { messageManager.removeMessageListener("chromeEvent", messageHandler); var url = m.json.data; @@ -49,7 +49,7 @@ function testOnLoad() { var webNav = content.window.QueryInterface(Components.interfaces.nsIInterfaceRequestor) .getInterface(Components.interfaces.nsIWebNavigation); webNav.loadURI(url, null, null, null, null); - } + }; var listener = 'data:,function doLoad(e) { var data=e.getData("data");removeEventListener("contentEvent", function (e) { doLoad(e); }, false, true);sendAsyncMessage("chromeEvent", {"data":data}); };addEventListener("contentEvent", function (e) { doLoad(e); }, false, true);'; messageManager.loadFrameScript(listener, true); @@ -303,6 +303,14 @@ Tester.prototype = { // behavior of returning the last opened popup. document.popupNode = null; + // Notify a long running test problem if it didn't end up in a timeout. + if (this.currentTest.unexpectedTimeouts && !this.currentTest.timedOut) { + let msg = "This test exceeded the timeout threshold. It should be " + + "rewritten or split up. If that's not possible, use " + + "requestLongerTimeout(N), but only as a last resort."; + this.currentTest.addResult(new testResult(false, msg, "", false)); + } + // Note the test run time let time = Date.now() - this.lastStartTime; this.dumper.dump("INFO TEST-END | " + this.currentTest.path + " | finished in " + time + "ms\n"); @@ -453,16 +461,32 @@ Tester.prototype = { } else { var self = this; - this.currentTest.scope.__waitTimer = setTimeout(function() { + this.currentTest.scope.__waitTimer = setTimeout(function timeoutFn() { if (--self.currentTest.scope.__timeoutFactor > 0) { // We were asked to wait a bit longer. self.currentTest.scope.info( "Longer timeout required, waiting longer... Remaining timeouts: " + self.currentTest.scope.__timeoutFactor); self.currentTest.scope.__waitTimer = - setTimeout(arguments.callee, gTimeoutSeconds * 1000); + setTimeout(timeoutFn, gTimeoutSeconds * 1000); return; } + + // If the test is taking longer than expected, but it's not hanging, + // mark the fact, but let the test continue. At the end of the test, + // if it didn't timeout, we will notify the problem through an error. + // To figure whether it's an actual hang, compare the time of the last + // result or message to half of the timeout time. + // Though, to protect against infinite loops, limit the number of times + // we allow the test to proceed. + const MAX_UNEXPECTED_TIMEOUTS = 10; + if (Date.now() - self.currentTest.lastOutputTime < (gTimeoutSeconds / 2) * 1000 && + ++self.currentTest.unexpectedTimeouts <= MAX_UNEXPECTED_TIMEOUTS) { + self.currentTest.scope.__waitTimer = + setTimeout(timeoutFn, gTimeoutSeconds * 1000); + return; + } + self.currentTest.addResult(new testResult(false, "Test timed out", "", false)); self.currentTest.timedOut = true; self.currentTest.scope.__waitTimer = null; diff --git a/testing/mochitest/tests/browser/Makefile.in b/testing/mochitest/tests/browser/Makefile.in index 1376948e72f..9749d49623d 100644 --- a/testing/mochitest/tests/browser/Makefile.in +++ b/testing/mochitest/tests/browser/Makefile.in @@ -11,25 +11,28 @@ relativesrcdir = @relativesrcdir@ include $(DEPTH)/config/autoconf.mk MOCHITEST_BROWSER_FILES = \ - head.js \ - browser_head.js \ - browser_pass.js \ - browser_async.js \ - browser_privileges.js \ - browser_popupNode.js \ - browser_popupNode_check.js \ - browser_sanityException.js \ - browser_sanityException2.js \ - $(NULL) + head.js \ + browser_head.js \ + browser_pass.js \ + browser_async.js \ + browser_privileges.js \ + browser_popupNode.js \ + browser_popupNode_check.js \ + browser_sanityException.js \ + browser_sanityException2.js \ + $(NULL) + # Disabled, these are only good for testing the harness' failure reporting -# browser_zz_fail_openwindow.js \ -# browser_fail.js \ -# browser_fail_async_throw.js \ -# browser_fail_fp.js \ -# browser_fail_pf.js \ -# browser_fail_throw.js \ -# browser_fail_timeout.js \ +# browser_zz_fail_openwindow.js \ +# browser_fail.js \ +# browser_fail_async_throw.js \ +# browser_fail_fp.js \ +# browser_fail_pf.js \ +# browser_fail_throw.js \ +# browser_fail_timeout.js \ +# browser_fail_unexpectedTimeout.js \ +# # Disabled because it would take too long, useful to check functionality though. -# browser_requestLongerTimeout.js \ +# browser_requestLongerTimeout.js \ include $(topsrcdir)/config/rules.mk diff --git a/testing/mochitest/tests/browser/browser_fail_timeout.js b/testing/mochitest/tests/browser/browser_fail_timeout.js index 4ba6a519e5a..6b99693d972 100644 --- a/testing/mochitest/tests/browser/browser_fail_timeout.js +++ b/testing/mochitest/tests/browser/browser_fail_timeout.js @@ -1,6 +1,6 @@ function test() { function end() { - ok(true, "didn't time out?"); + ok(false, "should have timed out"); finish(); } waitForExplicitFinish(); diff --git a/testing/mochitest/tests/browser/browser_fail_unexpectedTimeout.js b/testing/mochitest/tests/browser/browser_fail_unexpectedTimeout.js new file mode 100644 index 00000000000..2175eea2733 --- /dev/null +++ b/testing/mochitest/tests/browser/browser_fail_unexpectedTimeout.js @@ -0,0 +1,12 @@ +function test() { + function message() { + info("This should delay timeout"); + } + function end() { + ok(true, "Should have not timed out, but notified long running test"); + finish(); + } + waitForExplicitFinish(); + setTimeout(message, 20000); + setTimeout(end, 40000); +}