Bug 1131410 followup - addressing review comments I missed in part1, r=adw/rnewman

services/common/logmanager.js

@@ -1,24 +1,24 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+"use strict;"
 
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'Services',
+XPCOMUtils.defineLazyModuleGetter(this, "Services",
-  'resource://gre/modules/Services.jsm');
+  "resource://gre/modules/Services.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'Preferences',
+XPCOMUtils.defineLazyModuleGetter(this, "FileUtils",
-  'resource://gre/modules/Preferences.jsm');
+  "resource://gre/modules/FileUtils.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'FileUtils',
+XPCOMUtils.defineLazyModuleGetter(this, "Log",
-  'resource://gre/modules/FileUtils.jsm');
+  "resource://gre/modules/Log.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'Log',
+XPCOMUtils.defineLazyModuleGetter(this, "OS",
-  'resource://gre/modules/Log.jsm');
+  "resource://gre/modules/osfile.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'Task',
+XPCOMUtils.defineLazyModuleGetter(this, "CommonUtils",
-  'resource://gre/modules/Task.jsm');
+  "resource://services-common/utils.js");
-XPCOMUtils.defineLazyModuleGetter(this, 'OS',
+
-  'resource://gre/modules/osfile.jsm');
+Cu.import("resource://gre/modules/Preferences.jsm");
-XPCOMUtils.defineLazyModuleGetter(this, 'CommonUtils',
+Cu.import("resource://gre/modules/Task.jsm");
-  'resource://services-common/utils.js');
 
 this.EXPORTED_SYMBOLS = [
   "LogManager",
@@ -28,7 +28,7 @@ const DEFAULT_MAX_ERROR_AGE = 20 * 24 * 60 * 60; // 20 days
 
 // "shared" logs (ie, where the same log name is used by multiple LogManager
 // instances) are a fact of life here - eg, FirefoxAccounts logs are used by
-// both Sync and Reading-list.
+// both Sync and Reading List.
 // However, different instances have different pref branches, so we need to
 // handle when one pref branch says "Debug" and the other says "Error"
 // So we (a) keep singleton console and dump appenders and (b) keep track
@@ -103,7 +103,7 @@ LogManager.prototype = {
 
     // The file appender doesn't get the special singleton behaviour.
     let fapp = this._fileAppender = new Log.StorageStreamAppender(formatter);
-    // the stream gets a default of Debug as the user must go out of there way
+    // the stream gets a default of Debug as the user must go out of their way
     // to see the stuff spewed to it.
     this._observeStreamPref = setupAppender(fapp, "log.appender.file.level", Log.Level.Debug);
 
@@ -151,7 +151,7 @@ LogManager.prototype = {
     const BUFFER_SIZE = 8192;
 
     // get a binary stream
-    let binaryStream = Cc['@mozilla.org/binaryinputstream;1'].createInstance(Ci.nsIBinaryInputStream);
+    let binaryStream = Cc["@mozilla.org/binaryinputstream;1"].createInstance(Ci.nsIBinaryInputStream);
     binaryStream.setInputStream(inputStream);
     yield OS.File.makeDir(outputFile.parent.path, { ignoreExisting: true });
     let output = yield OS.File.open(outputFile.path, { write: true} );
@@ -165,12 +165,14 @@ LogManager.prototype = {
         yield output.write(new Uint8Array(chunk));
       }
     } finally {
-      inputStream.close();
+      try {
-      binaryStream.close();
+        binaryStream.close(); // inputStream is closed by the binaryStream
-      yield output.close();
+        yield output.close();
+      } catch (ex) {
+        this._log.error("Failed to close the input stream", ex);
+      }
     }
     this._log.trace("finished copy to", outputFile.path);
-    return (yield OS.File.stat(outputFile.path)).lastModificationDate;
   }),
 
   /**
@@ -179,70 +181,65 @@ LogManager.prototype = {
    * Returns a promise that resolves on completion or rejects if the file could
    * not be written.
    */
-  resetFileLog(reason) {
+  resetFileLog: Task.async(function* (reason) {
-    return new Promise((resolve, reject) => {
+    try {
-      try {
+      let flushToFile;
-        let flushToFile;
+      let reasonPrefix;
-        let reasonPrefix;
+      switch (reason) {
-        switch (reason) {
+        case this.REASON_SUCCESS:
-          case this.REASON_SUCCESS:
+          flushToFile = this._prefs.get("log.appender.file.logOnSuccess", false);
-            flushToFile = this._prefs.get("log.appender.file.logOnSuccess");
+          reasonPrefix = "success";
-            reasonPrefix = "success";
+          break;
-            break;
+        case this.REASON_ERROR:
-          case this.REASON_ERROR:
+          flushToFile = this._prefs.get("log.appender.file.logOnError", true);
-            flushToFile = this._prefs.get("log.appender.file.logOnError");
+          reasonPrefix = "error";
-            reasonPrefix = "error";
+          break;
-            break;
+        default:
-          default:
+          throw new Error("Invalid reason");
-            return reject(new Error("Invalid reason"));
-        }
-
-        let inStream = this._fileAppender.getInputStream();
-        this._fileAppender.reset();
-        if (flushToFile && inStream) {
-          this._log.debug("Flushing file log");
-          let filename = this.logFilePrefix + "-" + reasonPrefix + "-" + Date.now() + ".txt";
-          let file = this._logFileDirectory;
-          file.append(filename);
-          this._log.trace("Beginning stream copy to " + file.leafName + ": " +
-                          Date.now());
-          this._copyStreamToFile(inStream, file).then(
-            modDate => {
-              this._log.trace("onCopyComplete: " + Date.now());
-              this._log.trace("Output file timestamp: " + modDate + " (" + modDate.getTime() + ")");
-            },
-            err => {
-              this._log.error("Failed to copy log stream to file", err)
-              reject(err)
-            }
-          ).then(
-            () => {
-              // It's not completely clear to markh why we only do log cleanups
-              // for errors, but for now the Sync semantics have been copied...
-              // (one theory is that only cleaning up on error makes it less
-              // likely old error logs would be removed, but that's not true if
-              // there are occasional errors - let's address this later!)
-              if (reason == this.REASON_ERROR &&
-                  !this._cleaningUpFileLogs) {
-                this._log.trace("Scheduling cleanup.");
-                // Note we don't return or wait on this promise - it continues
-                // in the background
-                this.cleanupLogs().then(null, err => {
-                  this._log.error("Failed to cleanup logs", err);
-                });
-              }
-              resolve();
-            }
-          );
-        } else {
-          resolve();
-        }
-      } catch (ex) {
-        this._log.error("Failed to resetFileLog", ex)
-        reject(ex);
       }
-    })
+
-  },
+      // might as well avoid creating an input stream if we aren't going to use it.
+      if (!flushToFile) {
+        this._fileAppender.reset();
+        return;
+      }
+
+      let inStream = this._fileAppender.getInputStream();
+      this._fileAppender.reset();
+      if (inStream) {
+        this._log.debug("Flushing file log");
+        // We have reasonPrefix at the start of the filename so all "error"
+        // logs are grouped in about:sync-log.
+        let filename = reasonPrefix + "-" + this.logFilePrefix + "-" + Date.now() + ".txt";
+        let file = this._logFileDirectory;
+        file.append(filename);
+        this._log.trace("Beginning stream copy to " + file.leafName + ": " +
+                        Date.now());
+        try {
+          yield this._copyStreamToFile(inStream, file);
+          this._log.trace("onCopyComplete", Date.now());
+        } catch (ex) {
+          this._log.error("Failed to copy log stream to file", ex);
+          return;
+        }
+        // It's not completely clear to markh why we only do log cleanups
+        // for errors, but for now the Sync semantics have been copied...
+        // (one theory is that only cleaning up on error makes it less
+        // likely old error logs would be removed, but that's not true if
+        // there are occasional errors - let's address this later!)
+        if (reason == this.REASON_ERROR && !this._cleaningUpFileLogs) {
+          this._log.trace("Scheduling cleanup.");
+          // Note we don't return/yield or otherwise wait on this promise - it
+          // continues in the background
+          this.cleanupLogs().catch(err => {
+            this._log.error("Failed to cleanup logs", err);
+          });
+        }
+      }
+    } catch (ex) {
+      this._log.error("Failed to resetFileLog", ex)
+    }
+  }),
 
   /**
    * Finds all logs older than maxErrorAge and deletes them using async I/O.
@@ -255,7 +252,8 @@ LogManager.prototype = {
 
     this._log.debug("Log cleanup threshold time: " + threshold);
     yield iterator.forEach(Task.async(function* (entry) {
-      if (!entry.name.startsWith(this.logFilePrefix + "-")) {
+      if (!entry.name.startsWith("error-" + this.logFilePrefix + "-") &&
+          !entry.name.startsWith("success-" + this.logFilePrefix + "-")) {
         return;
       }
       try {

services/common/tests/unit/test_logmanager.js

@@ -23,7 +23,7 @@ function getAppenders(log) {
 }
 
 // Test that the correct thing happens when no prefs exist for the log manager.
-add_test(function test_noPrefs() {
+add_task(function* test_noPrefs() {
   // tell the log manager to init with a pref branch that doesn't exist.
   let lm = new LogManager("no-such-branch.", ["TestLog"], "test");
 
@@ -36,11 +36,10 @@ add_test(function test_noPrefs() {
   equal(fapps.length, 1, "only 1 file appender");
   equal(fapps[0].level, Log.Level.Debug);
   lm.finalize();
-  run_next_test();
 });
 
 // Test that changes to the prefs used by the log manager are updated dynamically.
-add_test(function test_PrefChanges() {
+add_task(function* test_PrefChanges() {
   Services.prefs.setCharPref("log-manager.test.log.appender.console", "Trace");
   Services.prefs.setCharPref("log-manager.test.log.appender.dump", "Trace");
   Services.prefs.setCharPref("log-manager.test.log.appender.file.level", "Trace");
@@ -66,11 +65,10 @@ add_test(function test_PrefChanges() {
   equal(dapp.level, Log.Level.Error);
   equal(fapp.level, Log.Level.Debug);
   lm.finalize();
-  run_next_test();
 });
 
 // Test that the same log used by multiple log managers does the right thing.
-add_test(function test_SharedLogs() {
+add_task(function* test_SharedLogs() {
   // create the prefs for the first instance.
   Services.prefs.setCharPref("log-manager-1.test.log.appender.console", "Trace");
   Services.prefs.setCharPref("log-manager-1.test.log.appender.dump", "Trace");
@@ -102,6 +100,4 @@ add_test(function test_SharedLogs() {
 
   lm1.finalize();
   lm2.finalize();
-
-  run_next_test();
 });

services/sync/tests/unit/test_errorhandler.js

@@ -1770,7 +1770,7 @@ add_task(function test_sync_engine_generic_fail() {
       let entries = logsdir.directoryEntries;
       do_check_true(entries.hasMoreElements());
       let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
-      do_check_true(logfile.leafName.startsWith("sync-error-"), logfile.leafName);
+      do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
 
       clean();
       server.stop(deferred.resolve);
@@ -1801,7 +1801,7 @@ add_test(function test_logs_on_sync_error_despite_shouldReportError() {
     let entries = logsdir.directoryEntries;
     do_check_true(entries.hasMoreElements());
     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
-    do_check_true(logfile.leafName.startsWith("sync-error-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
 
     clean();
     run_next_test();
@@ -1828,7 +1828,7 @@ add_test(function test_logs_on_login_error_despite_shouldReportError() {
     let entries = logsdir.directoryEntries;
     do_check_true(entries.hasMoreElements());
     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
-    do_check_true(logfile.leafName.startsWith("sync-error-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
 
     clean();
     run_next_test();
@@ -1862,7 +1862,7 @@ add_task(function test_engine_applyFailed() {
     let entries = logsdir.directoryEntries;
     do_check_true(entries.hasMoreElements());
     let logfile = entries.getNext().QueryInterface(Ci.nsILocalFile);
-    do_check_true(logfile.leafName.startsWith("sync-error-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
 
     clean();
     server.stop(deferred.resolve);

services/sync/tests/unit/test_errorhandler_filelog.js

@@ -108,7 +108,7 @@ add_test(function test_logOnSuccess_true() {
     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("sync-success-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("success-sync-"), logfile.leafName);
     do_check_false(entries.hasMoreElements());
 
     // Ensure the log message was actually written to file.
@@ -175,7 +175,7 @@ add_test(function test_sync_error_logOnError_true() {
     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("sync-error-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
     do_check_false(entries.hasMoreElements());
 
     // Ensure the log message was actually written to file.
@@ -242,7 +242,7 @@ add_test(function test_login_error_logOnError_true() {
     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("sync-error-"), logfile.leafName);
+    do_check_true(logfile.leafName.startsWith("error-sync-"), logfile.leafName);
     do_check_false(entries.hasMoreElements());
 
     // Ensure the log message was actually written to file.
@@ -281,7 +281,7 @@ add_test(function test_logErrorCleanup_age() {
   _("Making some files.");
   for (let i = 0; i < numLogs; i++) {
     let now = Date.now();
-    let filename = "sync-error-" + now + "" + i + ".txt";
+    let filename = "error-sync-" + now + "" + i + ".txt";
     let newLog = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
     let foStream = FileUtils.openFileOutputStream(newLog);
     foStream.write(errString, errString.length);