Bug 1131410 followup - addressing review comments I missed in part1, r=adw/rnewman a=readinglist
authorMark Hammond <mhammond@skippinet.com.au>
Thu, 26 Feb 2015 18:48:11 +1100
changeset 248477 312551e075004fcf9a90aefb0c6935831dc60ee6
parent 248476 214e71c08482583542c79e337b1967f608b494c4
child 248478 20d4b2b21a8f9e24f470388d61b362b6ce6bbb62
push id7837
push userjwein@mozilla.com
push dateFri, 27 Mar 2015 00:27:16 +0000
treeherdermozilla-aurora@cb0db44ce60e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersadw, rnewman, readinglist
bugs1131410
milestone38.0a2
Bug 1131410 followup - addressing review comments I missed in part1, r=adw/rnewman a=readinglist
services/common/logmanager.js
services/common/tests/unit/test_logmanager.js
services/sync/tests/unit/test_errorhandler.js
services/sync/tests/unit/test_errorhandler_filelog.js
--- a/services/common/logmanager.js
+++ b/services/common/logmanager.js
@@ -1,39 +1,39 @@
 /* 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',
-  'resource://gre/modules/Services.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'Preferences',
-  'resource://gre/modules/Preferences.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'FileUtils',
-  'resource://gre/modules/FileUtils.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'Log',
-  'resource://gre/modules/Log.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'Task',
-  'resource://gre/modules/Task.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'OS',
-  'resource://gre/modules/osfile.jsm');
-XPCOMUtils.defineLazyModuleGetter(this, 'CommonUtils',
-  'resource://services-common/utils.js');
+XPCOMUtils.defineLazyModuleGetter(this, "Services",
+  "resource://gre/modules/Services.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "FileUtils",
+  "resource://gre/modules/FileUtils.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "Log",
+  "resource://gre/modules/Log.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "OS",
+  "resource://gre/modules/osfile.jsm");
+XPCOMUtils.defineLazyModuleGetter(this, "CommonUtils",
+  "resource://services-common/utils.js");
+
+Cu.import("resource://gre/modules/Preferences.jsm");
+Cu.import("resource://gre/modules/Task.jsm");
 
 this.EXPORTED_SYMBOLS = [
   "LogManager",
 ];
 
 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
 // of the minimum (ie, most verbose) level and use that.
 // This avoids (a) the most recent setter winning (as that is indeterminate)
 // and (b) multiple dump/console appenders being added to the same log multiple
 // times, which would cause messages to appear twice.
 
@@ -98,17 +98,17 @@ LogManager.prototype = {
       return observer;
     }
 
     this._observeConsolePref = setupAppender(consoleAppender, "log.appender.console", Log.Level.Error, true);
     this._observeDumpPref = setupAppender(dumpAppender, "log.appender.dump", Log.Level.Error, true);
 
     // 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);
 
     // now attach the appenders to all our logs.
     for (let logName of logNames) {
       let log = Log.repository.getLogger(logName);
       for (let appender of [fapp, dumpAppender, consoleAppender]) {
         log.addAppender(appender);
@@ -146,121 +146,119 @@ LogManager.prototype = {
    * completion or rejected if there is an error.
    */
   _copyStreamToFile: Task.async(function* (inputStream, outputFile) {
     // The log data could be large, so we don't want to pass it all in a single
     // message, so use BUFFER_SIZE chunks.
     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} );
     try {
       while (true) {
         let available = binaryStream.available();
         if (!available) {
           break;
         }
         let chunk = binaryStream.readByteArray(Math.min(available, BUFFER_SIZE));
         yield output.write(new Uint8Array(chunk));
       }
     } finally {
-      inputStream.close();
-      binaryStream.close();
-      yield output.close();
+      try {
+        binaryStream.close(); // inputStream is closed by the binaryStream
+        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;
   }),
 
   /**
    * Possibly generate a log file for all accumulated log messages and refresh
    * the input & output streams.
    * Returns a promise that resolves on completion or rejects if the file could
    * not be written.
    */
-  resetFileLog(reason) {
-    return new Promise((resolve, reject) => {
-      try {
-        let flushToFile;
-        let reasonPrefix;
-        switch (reason) {
-          case this.REASON_SUCCESS:
-            flushToFile = this._prefs.get("log.appender.file.logOnSuccess");
-            reasonPrefix = "success";
-            break;
-          case this.REASON_ERROR:
-            flushToFile = this._prefs.get("log.appender.file.logOnError");
-            reasonPrefix = "error";
-            break;
-          default:
-            return reject(new Error("Invalid reason"));
-        }
+  resetFileLog: Task.async(function* (reason) {
+    try {
+      let flushToFile;
+      let reasonPrefix;
+      switch (reason) {
+        case this.REASON_SUCCESS:
+          flushToFile = this._prefs.get("log.appender.file.logOnSuccess", false);
+          reasonPrefix = "success";
+          break;
+        case this.REASON_ERROR:
+          flushToFile = this._prefs.get("log.appender.file.logOnError", true);
+          reasonPrefix = "error";
+          break;
+        default:
+          throw new Error("Invalid reason");
+      }
 
-        let inStream = this._fileAppender.getInputStream();
+      // might as well avoid creating an input stream if we aren't going to use it.
+      if (!flushToFile) {
         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();
+        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;
         }
-      } catch (ex) {
-        this._log.error("Failed to resetFileLog", ex)
-        reject(ex);
+        // 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.
    */
   cleanupLogs: Task.async(function* () {
     this._cleaningUpFileLogs = true;
     let iterator = new OS.File.DirectoryIterator(this._logFileDirectory.path);
     let maxAge = this._prefs.get("log.appender.file.maxErrorAge", DEFAULT_MAX_ERROR_AGE);
     let threshold = Date.now() - 1000 * maxAge;
 
     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 {
         // need to call .stat() as the enumerator doesn't give that to us on *nix.
         let info = yield OS.File.stat(entry.path);
         if (info.lastModificationDate.getTime() >= threshold) {
           return;
         }
--- a/services/common/tests/unit/test_logmanager.js
+++ b/services/common/tests/unit/test_logmanager.js
@@ -18,34 +18,33 @@ function getAppenders(log) {
   equal(capps.length, 1, "should only have one console appender");
   let dapps = log.appenders.filter(app => app instanceof Log.DumpAppender);
   equal(dapps.length, 1, "should only have one dump appender");
   let fapps = log.appenders.filter(app => app instanceof Log.StorageStreamAppender);
   return [capps[0], dapps[0], fapps];
 }
 
 // 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");
 
   let log = Log.repository.getLogger("TestLog");
   let [capp, dapp, fapps] = getAppenders(log);
   // the "dump" and "console" appenders should get Error level
   equal(capp.level, Log.Level.Error);
   equal(dapp.level, Log.Level.Error);
   // and the file (stream) appender gets Dump by default
   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");
   let lm = new LogManager("log-manager.test.", ["TestLog2"], "test");
 
   let log = Log.repository.getLogger("TestLog2");
   let [capp, dapp, [fapp]] = getAppenders(log);
   equal(capp.level, Log.Level.Trace);
@@ -61,21 +60,20 @@ add_test(function test_PrefChanges() {
   // and invalid values should cause them to fallback to their defaults.
   Services.prefs.setCharPref("log-manager.test.log.appender.console", "xxx");
   Services.prefs.setCharPref("log-manager.test.log.appender.dump", "xxx");
   Services.prefs.setCharPref("log-manager.test.log.appender.file.level", "xxx");
   equal(capp.level, Log.Level.Error);
   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");
   Services.prefs.setCharPref("log-manager-1.test.log.appender.file.level", "Trace");
   let lm1 = new LogManager("log-manager-1.test.", ["TestLog3"], "test");
 
   // and the second.
   Services.prefs.setCharPref("log-manager-2.test.log.appender.console", "Debug");
@@ -97,11 +95,9 @@ add_test(function test_SharedLogs() {
   Services.prefs.setCharPref("log-manager-1.test.log.appender.dump", "Error");
   Services.prefs.setCharPref("log-manager-1.test.log.appender.file.level", "Error");
 
   equal(capp.level, Log.Level.Debug);
   equal(dapp.level, Log.Level.Debug);
 
   lm1.finalize();
   lm2.finalize();
-
-  run_next_test();
 });
--- a/services/sync/tests/unit/test_errorhandler.js
+++ b/services/sync/tests/unit/test_errorhandler.js
@@ -1783,17 +1783,17 @@ add_task(function test_sync_engine_gener
       _("Status.engines: " + JSON.stringify(Status.engines));
       do_check_eq(Status.engines["catapult"], ENGINE_UNKNOWN_FAIL);
       do_check_eq(Status.service, SYNC_FAILED_PARTIAL);
 
       // Test Error log was written on SYNC_FAILED_PARTIAL.
       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);
     });
   });
 
   do_check_true(yield setUp(server));
   Service.sync();
@@ -1814,17 +1814,17 @@ add_test(function test_logs_on_sync_erro
 
   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
 
     // Test that error log was written.
     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();
   });
   Svc.Obs.notify("weave:service:sync:error", {});
 });
 
 add_test(function test_logs_on_login_error_despite_shouldReportError() {
@@ -1841,17 +1841,17 @@ add_test(function test_logs_on_login_err
 
   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
 
     // Test that error log was written.
     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();
   });
   Svc.Obs.notify("weave:service:login:error", {});
 });
 
 // This test should be the last one since it monkeypatches the engine object
@@ -1875,17 +1875,17 @@ add_task(function test_engine_applyFaile
 
     do_check_eq(Status.engines["catapult"], ENGINE_APPLY_FAIL);
     do_check_eq(Status.service, SYNC_FAILED_PARTIAL);
 
     // Test Error log was written on SYNC_FAILED_PARTIAL.
     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);
   });
 
   do_check_eq(Status.engines["catapult"], undefined);
   do_check_true(yield setUp(server));
   Service.sync();
--- a/services/sync/tests/unit/test_errorhandler_filelog.js
+++ b/services/sync/tests/unit/test_errorhandler_filelog.js
@@ -103,17 +103,17 @@ add_test(function test_logOnSuccess_true
   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
 
     // Exactly one log file was written.
     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("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.
     readFile(logfile, function (error, data) {
       do_check_true(Components.isSuccessCode(error));
       do_check_neq(data.indexOf(MESSAGE), -1);
 
       // Clean up.
@@ -170,17 +170,17 @@ add_test(function test_sync_error_logOnE
   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
 
     // Exactly one log file was written.
     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("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.
     readFile(logfile, function (error, data) {
       do_check_true(Components.isSuccessCode(error));
       do_check_neq(data.indexOf(MESSAGE), -1);
 
       // Clean up.
@@ -237,17 +237,17 @@ add_test(function test_login_error_logOn
   Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() {
     Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog);
 
     // Exactly one log file was written.
     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("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.
     readFile(logfile, function (error, data) {
       do_check_true(Components.isSuccessCode(error));
       do_check_neq(data.indexOf(MESSAGE), -1);
 
       // Clean up.
@@ -276,17 +276,17 @@ add_test(function test_logErrorCleanup_a
   let errString = "some error log\n";
 
   Svc.Prefs.set("log.appender.file.logOnError", true);
   Svc.Prefs.set("log.appender.file.maxErrorAge", maxAge);
 
   _("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);
     foStream.close();
     _("  > Created " + filename);
     oldLogs.push(newLog.leafName);
   }