bug 1281586 - clean up logging in the hope it helps figure out this intermittent. r=mhowell
authorRobert Strong <robert.bugzilla@gmail.com>
Tue, 06 Sep 2016 12:28:56 -0700
changeset 312906 76fc567fe00ea3571bc56df4a10e41f9a87bb4f4
parent 312905 de9d3e0f0b20e94cb0eaa13b955ba8a639e27917
child 312907 8082a95eccd36bca0e0f59f53d514a7fe8baf5ea
push id30665
push usercbook@mozilla.com
push dateWed, 07 Sep 2016 15:20:43 +0000
treeherdermozilla-central@95acb9299faf [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmhowell
bugs1281586
milestone51.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 1281586 - clean up logging in the hope it helps figure out this intermittent. r=mhowell
toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
--- a/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
+++ b/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
@@ -117,16 +117,19 @@ const MAX_TIMEOUT_RUNS = 20000;
 // Time in seconds the helper application should sleep before exiting. The
 // helper can also be made to exit by writing |finish| to its input file.
 const HELPER_SLEEP_TIMEOUT = 180;
 
 // Maximum number of milliseconds the process that is launched can run before
 // the test will try to kill it.
 const APP_TIMER_TIMEOUT = 120000;
 
+// How many of do_timeout calls using FILE_IN_USE_TIMEOUT_MS to wait before the
+// test is aborted.
+const FILE_IN_USE_MAX_TIMEOUT_RUNS = 60;
 const FILE_IN_USE_TIMEOUT_MS = 1000;
 
 const PIPE_TO_NULL = IS_WIN ? ">nul" : "> /dev/null 2>&1";
 
 const LOG_FUNCTION = do_print;
 
 const gHTTPHandlerPath = "updates.xml";
 
@@ -169,16 +172,17 @@ var gCallbackArgs = ["./", "callback.log
 var gPostUpdateBinFile = "postup_app" + BIN_SUFFIX;
 var gUseTestAppDir = true;
 // Some update staging failures can remove the update. This allows tests to
 // specify that the status file and the active update should not be checked
 // after an update is staged.
 var gStagingRemovedUpdate = false;
 
 var gTimeoutRuns = 0;
+var gFileInUseTimeoutRuns = 0;
 
 // Environment related globals
 var gShouldResetEnv = undefined;
 var gAddedEnvXRENoWindowsCrashDialog = false;
 var gEnvXPCOMDebugBreak;
 var gEnvXPCOMMemLeakLog;
 var gEnvDyldLibraryPath;
 var gEnvLdLibraryPath;
@@ -3330,16 +3334,20 @@ function checkFilesAfterUpdateCommon(aGe
   }
 }
 
 /**
  * Calls the appropriate callback log check for service and non-service tests.
  */
 function checkCallbackLog() {
   if (IS_SERVICE_TEST) {
+    // Prevent this check from being repeatedly logged in the xpcshell log by
+    // checking it here instead of in checkCallbackServiceLog.
+    Assert.ok(!!gServiceLaunchedCallbackLog,
+              "gServiceLaunchedCallbackLog should be defined");
     checkCallbackServiceLog();
   } else {
     checkCallbackAppLog();
   }
 }
 
 /**
  * Helper function for updater binary tests for verifying the contents of the
@@ -3447,52 +3455,47 @@ function checkPostUpdateAppLog() {
 }
 
 /**
  * Helper function for updater service tests for verifying the contents of the
  * updater callback application log which should contain the arguments passed to
  * the callback application.
  */
 function checkCallbackServiceLog() {
-  Assert.ok(!!gServiceLaunchedCallbackLog,
-            "gServiceLaunchedCallbackLog should be defined");
-
   let expectedLogContents = gServiceLaunchedCallbackArgs.join("\n") + "\n";
   let logFile = Cc["@mozilla.org/file/local;1"].createInstance(Ci.nsILocalFile);
   logFile.initWithPath(gServiceLaunchedCallbackLog);
   let logContents = readFile(logFile);
   // It is possible for the log file contents check to occur before the log file
   // contents are completely written so wait until the contents are the expected
   // value. If the contents are never the expected value then the test will
   // fail by timing out after gTimeoutRuns is greater than MAX_TIMEOUT_RUNS or
   // the test harness times out the test.
   if (logContents != expectedLogContents) {
-    gTimeoutRuns++;
-    if (gTimeoutRuns > MAX_TIMEOUT_RUNS) {
-      logTestInfo("callback service log contents are not correct");
-      let aryLog = logContents.split("\n");
-      let aryCompare = expectedLogContents.split("\n");
-      // Pushing an empty string to both arrays makes it so either array's length
-      // can be used in the for loop below without going out of bounds.
-      aryLog.push("");
-      aryCompare.push("");
-      // xpcshell tests won't display the entire contents so log the incorrect
-      // line.
-      for (let i = 0; i < aryLog.length; ++i) {
-        if (aryLog[i] != aryCompare[i]) {
-          logTestInfo("the first incorrect line in the service callback log " +
-                      "is: " + aryLog[i]);
-          Assert.equal(aryLog[i], aryCompare[i],
-                       "the service callback log contents" + MSG_SHOULD_EQUAL);
+    gFileInUseTimeoutRuns++;
+    if (gFileInUseTimeoutRuns > FILE_IN_USE_MAX_TIMEOUT_RUNS) {
+      if (logContents == null) {
+        if (logFile.exists()) {
+          logTestInfo("callback service log exists but readFile returned null");
+        } else {
+          logTestInfo("callback service log does not exist");
+        }
+      } else {
+        logTestInfo("callback service log contents are not correct");
+        let aryLog = logContents.split("\n");
+        // xpcshell tests won't display the entire contents so log each line.
+        logTestInfo("contents of " + logFile.path + ":");
+        for (let i = 0; i < aryLog.length; ++i) {
+          logTestInfo(aryLog[i]);
         }
       }
       // This should never happen!
       do_throw("Unable to find incorrect service callback log contents!");
     }
-    do_execute_soon(checkCallbackServiceLog);
+    do_timeout(FILE_IN_USE_TIMEOUT_MS, checkCallbackServiceLog);
     return;
   }
   Assert.ok(true, "the callback service log contents" + MSG_SHOULD_EQUAL);
 
   waitForFilesInUse();
 }
 
 /**