Bug 895376 - Make mochitest browser harness distinguish real timeouts from long-running tests.
authorMarco Bonardo <mbonardo@mozilla.com>
Fri, 19 Jul 2013 15:51:34 +0200
changeset 151506 6d5466692056a199ff00e1436b4608ae37586c3e
parent 151505 32ffcd6db605bb1b30da2885a1dcdca286192a21
child 151507 7fb8ea5cd2fc17f15a12178987d5af2f0fcfd227
push id2859
push userakeybl@mozilla.com
push dateMon, 16 Sep 2013 19:14:59 +0000
treeherdermozilla-beta@87d3c51cd2bf [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
bugs895376
milestone25.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 895376 - Make mochitest browser harness distinguish real timeouts from long-running tests. r=gavin
testing/mochitest/browser-harness.xul
testing/mochitest/browser-test.js
testing/mochitest/tests/browser/Makefile.in
testing/mochitest/tests/browser/browser_fail_timeout.js
testing/mochitest/tests/browser/browser_fail_unexpectedTimeout.js
--- a/testing/mochitest/browser-harness.xul
+++ b/testing/mochitest/browser-harness.xul
@@ -112,29 +112,32 @@
     var gErrorCount = 0;
 
     function browserTest(aTestFile) {
       this.path = aTestFile;
       this.dumper = gDumper;
       this.results = [];
       this.scope = null;
       this.duration = 0;
+      this.unexpectedTimeouts = 0;
+      this.lastOutputTime = 0;
     }
     browserTest.prototype = {
       get passCount() {
         return this.results.filter(function (t) !t.info && !t.todo && t.pass).length;
       },
       get todoCount() {
         return this.results.filter(function (t) !t.info && t.todo && t.pass).length;
       },
       get failCount() {
         return this.results.filter(function (t) !t.info && !t.pass).length;
       },
 
       addResult: function addResult(result) {
+        this.lastOutputTime = Date.now();
         this.results.push(result);
 
         this.dumper.dump(result.result + " | " + this.path + " | " + result.msg + "\n");
       },
 
       setDuration: function setDuration(duration) {
         this.duration = duration;
       },
--- a/testing/mochitest/browser-test.js
+++ b/testing/mochitest/browser-test.js
@@ -35,26 +35,26 @@ function testOnLoad() {
     var sstring = Cc["@mozilla.org/supports-string;1"].
                   createInstance(Ci.nsISupportsString);
     sstring.data = location.search;
 
     Services.ww.openWindow(window, "chrome://mochikit/content/browser-harness.xul", "browserTest",
                            "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;
 
       // Window is the [ChromeWindow] for messageManager, so we need content.window 
       // Currently chrome tests are run in a content window instead of a ChromeWindow
       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);
     messageManager.addMessageListener("chromeEvent", messageHandler);
   }
 }
 
 function Tester(aTests, aDumper, aCallback) {
@@ -298,16 +298,24 @@ Tester.prototype = {
         }
       }, this);
 
       // Clear document.popupNode.  The test could have set it to a custom value
       // for its own purposes, nulling it out it will go back to the default
       // 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");
       this.currentTest.setDuration(time);
 
       testScope.destroy();
       this.currentTest.scope = null;
     }
@@ -448,26 +456,42 @@ Tester.prototype = {
 
     // If the test ran synchronously, move to the next test, otherwise the test
     // will trigger the next test when it is done.
     if (this.currentTest.scope.__done) {
       this.nextTest();
     }
     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;
         self.nextTest();
       }, gTimeoutSeconds * 1000);
     }
   },
 
--- a/testing/mochitest/tests/browser/Makefile.in
+++ b/testing/mochitest/tests/browser/Makefile.in
@@ -6,30 +6,33 @@ DEPTH		= @DEPTH@
 topsrcdir	= @top_srcdir@
 srcdir		= @srcdir@
 VPATH		= @srcdir@
 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
--- a/testing/mochitest/tests/browser/browser_fail_timeout.js
+++ b/testing/mochitest/tests/browser/browser_fail_timeout.js
@@ -1,8 +1,8 @@
 function test() {
   function end() {
-    ok(true, "didn't time out?");
+    ok(false, "should have timed out");
     finish();
   }
   waitForExplicitFinish();
   setTimeout(end, 40000);
 }
new file mode 100644
--- /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);
+}