Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh draft
authorThom Chiovoloni <tchiovoloni@mozilla.com>
Fri, 06 May 2016 14:35:40 -0400
changeset 364488 987fc9b66c0c84b08bac4823ccffe60441022d8c
parent 362635 4e237f92c4a2f0ec545371af4759ddbdf6ff12df
child 520296 dd9047d0350025a2822d5ed6172628f15e68d41a
push id17468
push userbmo:tchiovoloni@mozilla.com
push dateFri, 06 May 2016 18:34:59 +0000
reviewersmarkh
bugs1263280
milestone49.0a1
Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r?markh MozReview-Commit-ID: KudJLUYWv1N
services/common/logmanager.js
services/sync/modules/policies.js
services/sync/tests/unit/test_errorhandler_filelog.js
--- a/services/common/logmanager.js
+++ b/services/common/logmanager.js
@@ -221,16 +221,20 @@ LogManager.prototype = {
   get _logFileSubDirectoryEntries() {
     // At this point we don't allow a custom directory for the logs, nor allow
     // it to be outside the profile directory.
     // This returns an array of the the relative directory entries below the
     // profile dir, and is the directory about:sync-log uses.
     return ["weave", "logs"];
   },
 
+  get sawError() {
+    return this._fileAppender.sawError;
+  },
+
   // Result values for resetFileLog.
   SUCCESS_LOG_WRITTEN: "success-log-written",
   ERROR_LOG_WRITTEN: "error-log-written",
 
   /**
    * Possibly generate a log file for all accumulated log messages and refresh
    * the input & output streams.
    * Whether a "success" or "error" log is written is determined based on
--- a/services/sync/modules/policies.js
+++ b/services/sync/modules/policies.js
@@ -13,16 +13,18 @@ Cu.import("resource://gre/modules/Log.js
 Cu.import("resource://services-sync/constants.js");
 Cu.import("resource://services-sync/engines.js");
 Cu.import("resource://services-sync/util.js");
 Cu.import("resource://services-common/logmanager.js");
 Cu.import("resource://services-common/async.js");
 
 XPCOMUtils.defineLazyModuleGetter(this, "Status",
                                   "resource://services-sync/status.js");
+XPCOMUtils.defineLazyModuleGetter(this, "AddonManager",
+                                  "resource://gre/modules/AddonManager.jsm");
 
 this.SyncScheduler = function SyncScheduler(service) {
   this.service = service;
   this.init();
 }
 SyncScheduler.prototype = {
   _log: Log.repository.getLogger("Sync.SyncScheduler"),
 
@@ -681,31 +683,62 @@ ErrorHandler.prototype = {
    */
   syncAndReportErrors: function syncAndReportErrors() {
     this._log.debug("Beginning user-triggered sync.");
 
     this.dontIgnoreErrors = true;
     Utils.nextTick(this.service.sync, this.service);
   },
 
+  _dumpAddons: function _dumpAddons() {
+    // Just dump the items that sync may be concerned with. Specifically,
+    // active extensions that are not hidden.
+    let addonPromise = new Promise(resolve => {
+      try {
+        AddonManager.getAddonsByTypes(["extension"], resolve);
+      } catch (e) {
+        this._log.warn("Failed to dump addons", e)
+        resolve([])
+      }
+    });
+
+    return addonPromise.then(addons => {
+      let relevantAddons = addons.filter(x => x.isActive && !x.hidden);
+      this._log.debug("Addons installed", relevantAddons.length);
+      for (let addon of relevantAddons) {
+        this._log.debug(" - ${name}, version ${version}, id ${id}", addon);
+      }
+    });
+  },
+
   /**
    * Generate a log file for the sync that just completed
    * and refresh the input & output streams.
    */
   resetFileLog: function resetFileLog() {
     let onComplete = logType => {
       Svc.Obs.notify("weave:service:reset-file-log");
       this._log.trace("Notified: " + Date.now());
       if (logType == this._logManager.ERROR_LOG_WRITTEN) {
         Cu.reportError("Sync encountered an error - see about:sync-log for the log file.");
       }
     };
+
+    // If we're writing an error log, dump extensions that may be causing problems.
+    let beforeResetLog;
+    if (this._logManager.sawError) {
+      beforeResetLog = this._dumpAddons();
+    } else {
+      beforeResetLog = Promise.resolve();
+    }
     // Note we do not return the promise here - the caller doesn't need to wait
     // for this to complete.
-    this._logManager.resetFileLog().then(onComplete, onComplete);
+    beforeResetLog
+      .then(() => this._logManager.resetFileLog())
+      .then(onComplete, onComplete);
   },
 
   /**
    * Translates server error codes to meaningful strings.
    *
    * @param code
    *        server error code as an integer
    */
--- a/services/sync/tests/unit/test_errorhandler_filelog.js
+++ b/services/sync/tests/unit/test_errorhandler_filelog.js
@@ -40,30 +40,32 @@ function run_test() {
 
 add_test(function test_noOutput() {
   // Ensure that the log appender won't print anything.
   errorHandler._logManager._fileAppender.level = Log.Level.Fatal + 1;
 
   // Clear log output from startup.
   Svc.Prefs.set("log.appender.file.logOnSuccess", false);
   Svc.Obs.notify("weave:service:sync:finish");
+  Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogOuter() {
+    Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogOuter);
+    // Clear again without having issued any output.
+    Svc.Prefs.set("log.appender.file.logOnSuccess", true);
 
-  // Clear again without having issued any output.
-  Svc.Prefs.set("log.appender.file.logOnSuccess", true);
-
-  Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
-    Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
+    Svc.Obs.add("weave:service:reset-file-log", function onResetFileLogInner() {
+      Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogInner);
 
-    errorHandler._logManager._fileAppender.level = Log.Level.Trace;
-    Svc.Prefs.resetBranch("");
-    run_next_test();
+      errorHandler._logManager._fileAppender.level = Log.Level.Trace;
+      Svc.Prefs.resetBranch("");
+      run_next_test();
+    });
+
+    // Fake a successful sync.
+    Svc.Obs.notify("weave:service:sync:finish");
   });
-
-  // Fake a successful sync.
-  Svc.Obs.notify("weave:service:sync:finish");
 });
 
 add_test(function test_logOnSuccess_false() {
   Svc.Prefs.set("log.appender.file.logOnSuccess", false);
 
   let log = Log.repository.getLogger("Sync.Test.FileLog");
   log.info("this won't show up");
 
@@ -260,16 +262,61 @@ add_test(function test_login_error_logOn
     });
   });
 
   // Fake an unsuccessful login due to prolonged failure.
   setLastSync(PROLONGED_ERROR_DURATION);
   Svc.Obs.notify("weave:service:login:error");
 });
 
+
+add_test(function test_errorLog_dumpAddons() {
+  Svc.Prefs.set("log.appender.file.logOnError", true);
+
+  let log = Log.repository.getLogger("Sync.Test.FileLog");
+
+  // We need to wait until the log cleanup started by this test is complete
+  // or the next test will fail as it is ongoing.
+  Svc.Obs.add("services-tests:common:log-manager:cleanup-logs", function onCleanupLogs() {
+    Svc.Obs.remove("services-tests:common:log-manager:cleanup-logs", onCleanupLogs);
+    run_next_test();
+  });
+
+  Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
+    Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
+
+    let entries = logsdir.directoryEntries;
+    do_check_true(entries.hasMoreElements());
+    let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
+    do_check_eq(logfile.leafName.slice(-4), ".txt");
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
+    do_check_false(entries.hasMoreElements());
+
+    // Ensure we logged some addon list (which is probably empty)
+    readFile(logfile, function (error, data) {
+      do_check_true(Components.isSuccessCode(error));
+      do_check_neq(data.indexOf("Addons installed"), -1);
+
+      // Clean up.
+      try {
+        logfile.remove(false);
+      } catch(ex) {
+        dump("Couldn't delete file: " + ex + "\n");
+        // Stupid Windows box.
+      }
+
+      Svc.Prefs.resetBranch("");
+    });
+  });
+
+  // Fake an unsuccessful sync due to prolonged failure.
+  setLastSync(PROLONGED_ERROR_DURATION);
+  Svc.Obs.notify("weave:service:sync:error");
+});
+
 // Check that error log files are deleted above an age threshold.
 add_test(function test_logErrorCleanup_age() {
   _("Beginning test_logErrorCleanup_age.");
   let maxAge = CLEANUP_DELAY / 1000;
   let oldLogs = [];
   let numLogs = 10;
   let errString = "some error log\n";