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 139242 6d5466692056a199ff00e1436b4608ae37586c3e
parent 139241 32ffcd6db605bb1b30da2885a1dcdca286192a21
child 139243 7fb8ea5cd2fc17f15a12178987d5af2f0fcfd227
push id1890
push userryanvm@gmail.com
push dateFri, 19 Jul 2013 17:44:21 +0000
treeherderfx-team@20848adc9980 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
bugs895376
milestone25.0a1
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);
+}