bug 1419594 - test only - make update tests less likely to fail during async writes of the update xml files. r=mhowell
authorRobert Strong <robert.bugzilla@gmail.com>
Wed, 22 Nov 2017 11:34:10 -0800
changeset 702177 4a65f0921a8545c8ec5f0f0de2b9557dbec66a89
parent 702176 b693fb4f900d51d3fda7300de6405a40b99ede4f
child 702178 f4851b138288a01cda19df0d3649a70d6322bc8b
child 705716 63d36dbc9eb06484c81b6c3b5f51e2e45b481f6a
push id90414
push usermozilla@noorenberghe.ca
push dateWed, 22 Nov 2017 21:44:13 +0000
reviewersmhowell
bugs1419594
milestone59.0a1
bug 1419594 - test only - make update tests less likely to fail during async writes of the update xml files. r=mhowell
toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
toolkit/mozapps/update/tests/unit_aus_update/downloadCompleteAfterPartialFailure.js
toolkit/mozapps/update/tests/unit_aus_update/downloadInterruptedRecoveryChannel.js
toolkit/mozapps/update/tests/unit_aus_update/downloadInvalidSizeMar.js
toolkit/mozapps/update/tests/unit_aus_update/updateManagerXML.js
--- a/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
+++ b/toolkit/mozapps/update/tests/data/xpcshellUtilsAUS.js
@@ -183,16 +183,29 @@ var gEnvDyldLibraryPath;
 var gEnvLdLibraryPath;
 var gASanOptions;
 
 // Set to true to log additional information for debugging. To log additional
 // information for an individual test set DEBUG_AUS_TEST to true in the test's
 // run_test function.
 var DEBUG_AUS_TEST = true;
 
+// Setting gDebugTestLog to true will create log files for the tests in
+// <objdir>/_tests/xpcshell/toolkit/mozapps/update/tests/<testdir>/ except for
+// the service tests since they run sequentially. This can help when debugging
+// failures for the tests that intermittently fail when they run in parallel.
+// Never set gDebugTestLog to true except when running tests locally.
+var gDebugTestLog = false;
+// An empty array for gTestsToLog will log most of the output of all of the
+// update tests except for the service tests. To only log specific tests add the
+// test file name without the file extension to the array below.
+var gTestsToLog = [];
+var gRealDump;
+var gFOS;
+
 const DATA_URI_SPEC = Services.io.newFileURI(do_get_file("../data", false)).spec;
 /* import-globals-from ../data/shared.js */
 Services.scriptloader.loadSubScript(DATA_URI_SPEC + "shared.js", this);
 
 XPCOMUtils.defineLazyModuleGetter(this, "ctypes",
                                   "resource://gre/modules/ctypes.jsm");
 XPCOMUtils.defineLazyModuleGetter(this, "MockRegistrar",
                                   "resource://testing-common/MockRegistrar.jsm");
@@ -760,16 +773,31 @@ function setupTestCommon() {
 
   Assert.strictEqual(gTestID, undefined,
                      "gTestID should be 'undefined' (setupTestCommon should " +
                      "only be called once)");
 
   let caller = Components.stack.caller;
   gTestID = caller.filename.toString().split("/").pop().split(".")[0];
 
+  if (gDebugTestLog && !IS_SERVICE_TEST) {
+    if (gTestsToLog.length == 0 || gTestsToLog.includes(gTestID)) {
+      let logFile = do_get_file(gTestID + ".log", true);
+      if (!logFile.exists()) {
+        logFile.create(Ci.nsIFile.NORMAL_FILE_TYPE, PERMS_FILE);
+      }
+      gFOS = Cc["@mozilla.org/network/file-output-stream;1"].
+             createInstance(Ci.nsIFileOutputStream);
+      gFOS.init(logFile, MODE_WRONLY | MODE_APPEND, PERMS_FILE, 0);
+
+      gRealDump = dump;
+      dump = dumpOverride;
+    }
+  }
+
   createAppInfo("xpcshell@tests.mozilla.org", APP_INFO_NAME, "1.0", "2.0");
 
   if (IS_SERVICE_TEST && !shouldRunServiceTest()) {
     return false;
   }
 
   do_test_pending();
 
@@ -951,83 +979,137 @@ function cleanupTestCommon() {
       logTestInfo("non-fatal error removing directory. Path: " +
                   applyDir.path + ", Exception: " + e);
     }
   }
 
   resetEnvironment();
 
   debugDump("finish - general test cleanup");
+
+  if (gRealDump) {
+    dump = gRealDump;
+    gRealDump = null;
+  }
+
+  if (gFOS) {
+    gFOS.close();
+  }
+}
+
+/**
+ * Helper function to store the log output of calls to dump in a variable so the
+ * values can be written to a file for a parallel run of a test and printed to
+ * the log file when the test runs synchronously.
+ */
+function dumpOverride(aText) {
+  gFOS.write(aText, aText.length);
+  gRealDump(aText);
 }
 
 /**
  * Helper function that calls do_test_finished that tracks whether a parallel
  * run of a test passed when it runs synchronously so the log output can be
  * inspected.
  */
 function doTestFinish() {
-  // Create empty update xml files and force the update manager to reload the
-  // update data. This will prevent the update manager from writing the test
-  // update data to the files when the test ends.
-  writeUpdatesToXMLFile(getLocalUpdatesXMLString(""), true);
-  writeUpdatesToXMLFile(getLocalUpdatesXMLString(""), false);
-  reloadUpdateManagerData();
-  gUpdateManager.saveUpdates();
-
   if (DEBUG_AUS_TEST) {
     // This prevents do_print errors from being printed by the xpcshell test
     // harness due to nsUpdateService.js logging to the console when the
     // app.update.log preference is true.
     Services.prefs.setBoolPref(PREF_APP_UPDATE_LOG, false);
     gAUS.observe(null, "nsPref:changed", PREF_APP_UPDATE_LOG);
   }
   do_execute_soon(testFinishWaitForUpdateXMLFiles);
 }
 
 /**
- * Waits until the active-update.xml and updates.xml files don't exist and then
- * calls do_test_finished to end the test. This is necessary due to these files
- * being written asynchronously by nsIUpdateManager.
+ * Waits until the update files don't exist and then calls do_test_finished to
+ * end the test. This is necessary due to the update xml files being written
+ * asynchronously by nsIUpdateManager. Uses do_timeout instead of
+ * do_execute_soon to lessen log spew.
  */
 function testFinishWaitForUpdateXMLFiles() {
-  let tmpActiveUpdateXML = getUpdatesRootDir();
-  tmpActiveUpdateXML.append(FILE_ACTIVE_UPDATE_XML + ".tmp");
-  if (tmpActiveUpdateXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, testFinishWaitForUpdateXMLFiles);
-    return;
-  }
-
-  let tmpUpdatesXML = getUpdatesRootDir();
-  tmpUpdatesXML.append(FILE_UPDATES_XML + ".tmp");
-  if (tmpUpdatesXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, testFinishWaitForUpdateXMLFiles);
-    return;
+  /**
+   * Waits until the update tmp files don't exist and then calls
+   * testFinishReloadUpdateXMLFiles.
+   */
+  function testFinishWaitForUpdateTmpXMLFiles() {
+    let tmpActiveUpdateXML = getUpdatesRootDir();
+    tmpActiveUpdateXML.append(FILE_ACTIVE_UPDATE_XML + ".tmp");
+    if (tmpActiveUpdateXML.exists()) {
+      // The xml files are written asynchronously so wait until it has been
+      // removed.
+      do_timeout(10, testFinishWaitForUpdateTmpXMLFiles);
+      return;
+    }
+
+    let tmpUpdatesXML = getUpdatesRootDir();
+    tmpUpdatesXML.append(FILE_UPDATES_XML + ".tmp");
+    if (tmpUpdatesXML.exists()) {
+      // The xml files are written asynchronously so wait until it has been
+      // removed.
+      do_timeout(10, testFinishWaitForUpdateTmpXMLFiles);
+      return;
+    }
+
+    do_timeout(10, testFinishReloadUpdateXMLFiles);
   }
 
-  let activeUpdateXML = getUpdatesXMLFile(true);
-  if (activeUpdateXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, testFinishWaitForUpdateXMLFiles);
-    return;
+  /**
+   * Creates empty update xml files, reloads / saves the update data, and then
+   * calls testFinishWaitForUpdateXMLFiles.
+   */
+  function testFinishReloadUpdateXMLFiles() {
+    try {
+      // Wrapped in a try catch since the file can be in the middle of a write.
+      writeUpdatesToXMLFile(getLocalUpdatesXMLString(""), true);
+    } catch (e) {
+      do_timeout(10, testFinishReloadUpdateXMLFiles);
+      return;
+    }
+    try {
+      // Wrapped in a try catch since the file can be in the middle of a write.
+      writeUpdatesToXMLFile(getLocalUpdatesXMLString(""), false);
+    } catch (e) {
+      do_timeout(10, testFinishReloadUpdateXMLFiles);
+      return;
+    }
+
+    reloadUpdateManagerData();
+    gUpdateManager.saveUpdates();
+    do_timeout(10, testFinishWaitForUpdateXMLFilesDelete);
   }
 
-  let updatesXML = getUpdatesXMLFile(false);
-  if (updatesXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, testFinishWaitForUpdateXMLFiles);
-    return;
+  /**
+   * Waits until the active-update.xml and updates.xml files don't exist and
+   * then calls do_test_finished to end the test. This is necessary due to the
+   * update xml files being written asynchronously by nsIUpdateManager.
+   */
+  function testFinishWaitForUpdateXMLFilesDelete() {
+    let activeUpdateXML = getUpdatesXMLFile(true);
+    if (activeUpdateXML.exists()) {
+      // Since the file is removed asynchronously wait until it has been
+      // removed. Uses do_timeout instead of do_execute_soon to lessen log spew.
+      do_timeout(10, testFinishWaitForUpdateXMLFilesDelete);
+      return;
+    }
+
+    let updatesXML = getUpdatesXMLFile(false);
+    if (updatesXML.exists()) {
+      // Since the file is removed asynchronously wait until it has been
+      // removed. Uses do_timeout instead of do_execute_soon to lessen log spew.
+      do_timeout(10, testFinishWaitForUpdateXMLFilesDelete);
+      return;
+    }
+
+    do_timeout(10, do_test_finished);
   }
 
-  do_execute_soon(do_test_finished);
+  do_timeout(10, testFinishWaitForUpdateTmpXMLFiles);
 }
 
 /**
  * Sets the most commonly used preferences used by tests
  */
 function setDefaultPrefs() {
   Services.prefs.setBoolPref(PREF_APP_UPDATE_ENABLED, true);
   if (DEBUG_AUS_TEST) {
@@ -1145,63 +1227,90 @@ function checkUpdateManager(aStatusFileS
     }
     if (i != msgTags.length - 1) {
       reloadUpdateManagerData();
     }
   }
 }
 
 /**
- * Waits until the active-update.xml and updates.xml files exists or not based
- * on the parameters specified when calling this function or the default values
- * if the parameters are not specified. After these conditions are met the
- * waitForUpdateXMLFilesFinished function is called. This is necessary due to
- * these files being written asynchronously by nsIUpdateManager.
+ * Waits until the update files exist or not based on the parameters specified
+ * when calling this function or the default values if the parameters are not
+ * specified. After these conditions are met the waitForUpdateXMLFilesFinished
+ * function is called.  This is necessary due to the update xml files being
+ * written asynchronously by nsIUpdateManager. Uses do_timeout instead of
+ * do_execute_soon to lessen log spew.
  *
  * @param   aActiveUpdateExists (optional)
  *          Whether the active-update.xml file should exist (default is false).
  * @param   aUpdatesExists (optional)
  *          Whether the updates.xml file should exist (default is true).
  */
 function waitForUpdateXMLFiles(aActiveUpdateExists = false, aUpdatesExists = true) {
-  let tmpActiveUpdateXML = getUpdatesRootDir();
-  tmpActiveUpdateXML.append(FILE_ACTIVE_UPDATE_XML + ".tmp");
-  if (tmpActiveUpdateXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, () => waitForUpdateXMLFiles(aActiveUpdateExists, aUpdatesExists));
-    return;
-  }
-
-  let tmpUpdatesXML = getUpdatesRootDir();
-  tmpUpdatesXML.append(FILE_UPDATES_XML + ".tmp");
-  if (tmpUpdatesXML.exists()) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, () => waitForUpdateXMLFiles(aActiveUpdateExists, aUpdatesExists));
-    return;
+  /**
+   * Waits until the update tmp files don't exist and then calls
+   * testFinishReloadUpdateXMLFiles.
+   *
+   * @param   aActiveUpdateExists (optional)
+   *          Whether the active-update.xml file should exist (default is false).
+   * @param   aUpdatesExists (optional)
+   *          Whether the updates.xml file should exist (default is true).
+   */
+  function waitForUpdateTmpXMLFiles(aActiveUpdateExists = false, aUpdatesExists = true) {
+    let tmpActiveUpdateXML = getUpdatesRootDir();
+    tmpActiveUpdateXML.append(FILE_ACTIVE_UPDATE_XML + ".tmp");
+    if (tmpActiveUpdateXML.exists()) {
+      // The xml files are written asynchronously so wait until it has been
+      // removed.
+      do_timeout(10, () => waitForUpdateTmpXMLFiles(aActiveUpdateExists, aUpdatesExists));
+      return;
+    }
+
+    let tmpUpdatesXML = getUpdatesRootDir();
+    tmpUpdatesXML.append(FILE_UPDATES_XML + ".tmp");
+    if (tmpUpdatesXML.exists()) {
+      // The xml files are written asynchronously so wait until it has been
+      // removed.
+      do_timeout(10, () => waitForUpdateTmpXMLFiles(aActiveUpdateExists, aUpdatesExists));
+      return;
+    }
+
+    do_timeout(10, () => waitForUpdateXMLFilesExist(aActiveUpdateExists, aUpdatesExists));
   }
 
-  let activeUpdateXML = getUpdatesXMLFile(true);
-  if (activeUpdateXML.exists() != aActiveUpdateExists) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, () => waitForUpdateXMLFiles(aActiveUpdateExists, aUpdatesExists));
-    return;
+  /**
+   * Waits until the update files exist or not based on the parameters specified
+   * when calling this function or the default values if the parameters are not
+   * specified. After these conditions are met the waitForUpdateXMLFilesFinished
+   * function is called.
+   *
+   * @param   aActiveUpdateExists (optional)
+   *          Whether the active-update.xml file should exist (default is false).
+   * @param   aUpdatesExists (optional)
+   *          Whether the updates.xml file should exist (default is true).
+   */
+  function waitForUpdateXMLFilesExist(aActiveUpdateExists = false, aUpdatesExists = true) {
+    let activeUpdateXML = getUpdatesXMLFile(true);
+    if (activeUpdateXML.exists() != aActiveUpdateExists) {
+      // Since the file is removed asynchronously wait until it has been removed.
+      do_timeout(10, () => waitForUpdateXMLFilesExist(aActiveUpdateExists, aUpdatesExists));
+      return;
+    }
+
+    let updatesXML = getUpdatesXMLFile(false);
+    if (updatesXML.exists() != aUpdatesExists) {
+      // Since the file is removed asynchronously wait until it has been removed.
+      do_timeout(10, () => waitForUpdateXMLFilesExist(aActiveUpdateExists, aUpdatesExists));
+      return;
+    }
+
+    do_timeout(10, waitForUpdateXMLFilesFinished);
   }
 
-  let updatesXML = getUpdatesXMLFile(false);
-  if (updatesXML.exists() != aUpdatesExists) {
-    // Since the file is removed asynchronously wait until it has been removed.
-    // Uses do_timeout instead of do_execute_soon to lessen log spew.
-    do_timeout(10, () => waitForUpdateXMLFiles(aActiveUpdateExists, aUpdatesExists));
-    return;
-  }
-
-  do_execute_soon(waitForUpdateXMLFilesFinished);
+  do_timeout(10, () => waitForUpdateTmpXMLFiles(aActiveUpdateExists, aUpdatesExists));
 }
 
 /**
  * On Mac OS X and Windows this checks if the post update '.running' file exists
  * to determine if the post update binary was launched.
  *
  * @param   aShouldExist
  *          Whether the post update '.running' file should exist.
--- a/toolkit/mozapps/update/tests/unit_aus_update/downloadCompleteAfterPartialFailure.js
+++ b/toolkit/mozapps/update/tests/unit_aus_update/downloadCompleteAfterPartialFailure.js
@@ -12,17 +12,21 @@ const WindowWatcher = {
         Assert.equal(aTitle, title,
                      "the ui string for title" + MSG_SHOULD_EQUAL);
         let text = gUpdateBundle.formatStringFromName("updaterIOErrorMsg",
                                                       [Services.appinfo.name,
                                                        Services.appinfo.name], 2);
         Assert.equal(aText, text,
                      "the ui string for message" + MSG_SHOULD_EQUAL);
 
-        doTestFinish();
+        // Cleaning up the active update along with reloading the update manager
+        // in doTestFinish will prevent writing the update xml files during
+        // shutdown.
+        gUpdateManager.cleanupActiveUpdate();
+        do_execute_soon(waitForUpdateXMLFiles);
       }
     };
   },
 
   QueryInterface: XPCOMUtils.generateQI([Ci.nsIWindowWatcher])
 };
 
 function run_test() {
@@ -55,8 +59,15 @@ function run_test() {
   reloadUpdateManagerData();
 
   let update = gUpdateManager.activeUpdate;
   update.errorCode = WRITE_ERROR;
   let prompter = Cc["@mozilla.org/updates/update-prompt;1"].
                  createInstance(Ci.nsIUpdatePrompt);
   prompter.showUpdateError(update);
 }
+
+/**
+ * Called after the call to waitForUpdateXMLFiles finishes.
+ */
+function waitForUpdateXMLFilesFinished() {
+  do_execute_soon(doTestFinish);
+}
--- a/toolkit/mozapps/update/tests/unit_aus_update/downloadInterruptedRecoveryChannel.js
+++ b/toolkit/mozapps/update/tests/unit_aus_update/downloadInterruptedRecoveryChannel.js
@@ -58,17 +58,22 @@ class TestDownloadListener {
                    "the download status" + MSG_SHOULD_EQUAL);
       do_execute_soon(resumeDownload);
     } else {
       // The second time we stop, it should be because the download is done.
       Assert.equal(gBestUpdate.state, STATE_PENDING,
                    "the update state" + MSG_SHOULD_EQUAL);
       Assert.equal(aStatus, Cr.NS_OK,
                    "the download status" + MSG_SHOULD_EQUAL);
-      do_execute_soon(finish_test);
+
+      // Cleaning up the active update along with reloading the update manager
+      // in doTestFinish will prevent writing the update xml files during
+      // shutdown.
+      gUpdateManager.cleanupActiveUpdate();
+      do_execute_soon(waitForUpdateXMLFiles);
     }
   }
 
   QueryInterface(iid) {
     if (iid.equals(Ci.nsIRequestObserver) ||
         iid.equals(Ci.nsIProgressEventSink)) {
       return this;
     }
@@ -95,8 +100,15 @@ function resumeDownload() {
   let state = gAUS.downloadUpdate(gBestUpdate, false);
   if (state == STATE_NONE || state == STATE_FAILED) {
     do_throw("nsIApplicationUpdateService:downloadUpdate returned " + state);
   }
 
   // Resuming creates a new Downloader, and thus drops registered listeners.
   gAUS.addDownloadListener(gListener);
 }
+
+/**
+ * Called after the call to waitForUpdateXMLFiles finishes.
+ */
+function waitForUpdateXMLFilesFinished() {
+  stop_httpserver(doTestFinish);
+}
--- a/toolkit/mozapps/update/tests/unit_aus_update/downloadInvalidSizeMar.js
+++ b/toolkit/mozapps/update/tests/unit_aus_update/downloadInvalidSizeMar.js
@@ -44,16 +44,20 @@ function check_test_helper_pt1_1() {
 
 /**
  * Called after the download listener onStopRequest is called.
  */
 function downloadListenerStop() {
   Assert.equal(gStatusResult, Cr.NS_ERROR_UNEXPECTED,
                "the download status result" + MSG_SHOULD_EQUAL);
   gAUS.removeDownloadListener(downloadListener);
+
+  // Cleaning up the active update along with reloading the update manager
+  // in doTestFinish will prevent writing the update xml files during shutdown.
+  gUpdateManager.cleanupActiveUpdate();
   do_execute_soon(waitForUpdateXMLFiles);
 }
 
 /**
  * Called after the call to waitForUpdateXMLFiles finishes.
  */
 function waitForUpdateXMLFilesFinished() {
   // The HttpServer must be stopped before calling do_test_finished
--- a/toolkit/mozapps/update/tests/unit_aus_update/updateManagerXML.js
+++ b/toolkit/mozapps/update/tests/unit_aus_update/updateManagerXML.js
@@ -160,10 +160,21 @@ function run_test() {
                "the update patch URL attribute" + MSG_SHOULD_EQUAL);
   Assert.equal(patch.size, "75",
                "the update patch size attribute" + MSG_SHOULD_EQUAL);
   Assert.ok(!!patch.selected,
             "the update patch selected attribute" + MSG_SHOULD_EQUAL);
   Assert.equal(patch.state, STATE_FAILED,
                "the update patch state attribute" + MSG_SHOULD_EQUAL);
 
-  doTestFinish();
+  // Cleaning up the active update along with reloading the update manager
+  // in doTestFinish will prevent writing the update xml files during
+  // shutdown.
+  gUpdateManager.cleanupActiveUpdate();
+  do_execute_soon(waitForUpdateXMLFiles);
 }
+
+/**
+ * Called after the call to waitForUpdateXMLFiles finishes.
+ */
+function waitForUpdateXMLFilesFinished() {
+  do_execute_soon(doTestFinish);
+}