Bug 1263280 - Dump a list of addons currently installed when writing the sync error log r=markh

MozReview-Commit-ID: KudJLUYWv1N

--HG--
extra : transplant_source : %98%7F%C9%B6l%0C%84%B0%8B%ACH%23%CC%FF%E6%04A%02-%8C

services/common/logmanager.js

@@ -226,6 +226,10 @@ LogManager.prototype = {
     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",

services/sync/modules/policies.js

@@ -18,6 +18,8 @@ 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;
@@ -686,6 +688,27 @@ ErrorHandler.prototype = {
     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.
@@ -698,9 +721,19 @@ ErrorHandler.prototype = {
         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);
   },
 
   /**

services/sync/tests/unit/test_errorhandler_filelog.js

@@ -45,20 +45,22 @@ add_test(function test_noOutput() {
   // 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 onResetFileLogInner() {
+      Svc.Obs.remove("weave:service:reset-file-log", onResetFileLogInner);
 
-  Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
-    Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
+      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() {
@@ -265,6 +267,51 @@ add_test(function test_login_error_logOnError_true() {
   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.");