Bug 1400414 - Defer formatting work in sync logging until we are sure we actually will write the log. r?markh draft
authorThom Chiovoloni <tchiovoloni@mozilla.com>
Fri, 15 Sep 2017 15:13:25 -0700
changeset 665774 53b2115188ef61485f4a29e78f93151222e74350
parent 665165 216079d767e7fd9351abf09e605ae63c2948bd53
child 731879 e70ab5989cc7c3f29611e271d854146765d0de31
push id80170
push userbmo:tchiovoloni@mozilla.com
push dateFri, 15 Sep 2017 22:47:36 +0000
reviewersmarkh
bugs1400414
milestone57.0a1
Bug 1400414 - Defer formatting work in sync logging until we are sure we actually will write the log. r?markh MozReview-Commit-ID: Bx2KTzVRUzF
services/common/logmanager.js
services/common/tests/unit/test_logmanager.js
--- a/services/common/logmanager.js
+++ b/services/common/logmanager.js
@@ -46,36 +46,65 @@ var allBranches = new Set();
 
 // A storage appender that is flushable to a file on disk.  Policies for
 // when to flush, to what file, log rotation etc are up to the consumer
 // (although it does maintain a .sawError property to help the consumer decide
 // based on its policies)
 function FlushableStorageAppender(formatter) {
   Log.StorageStreamAppender.call(this, formatter);
   this.sawError = false;
+  this.pendingMessages = [];
+  this._lazy = false;
 }
 
 FlushableStorageAppender.prototype = {
   __proto__: Log.StorageStreamAppender.prototype,
 
+  get lazy() {
+    return this._lazy;
+  },
+
+  set lazy(v) {
+    if (this._lazy && !v) {
+      this._flushPending();
+    }
+    this._lazy = v;
+  },
+
   append(message) {
     if (message.level >= Log.Level.Error) {
       this.sawError = true;
     }
-    Log.StorageStreamAppender.prototype.append.call(this, message);
+
+    if (this.lazy) {
+      this.pendingMessages.push(message);
+    } else {
+      Log.StorageStreamAppender.prototype.append.call(this, message);
+    }
   },
 
   reset() {
     Log.StorageStreamAppender.prototype.reset.call(this);
+    this.pendingMessages.length = 0;
     this.sawError = false;
   },
 
+  _flushPending() {
+    for (let i = 0; i < this.pendingMessages.length; ++i) {
+      Log.StorageStreamAppender.prototype.append.call(this, this.pendingMessages[i]);
+    }
+    this.pendingMessages.length = 0;
+  },
+
   // Flush the current stream to a file. Somewhat counter-intuitively, you
   // must pass a log which will be written to with details of the operation.
   async flushToFile(subdirArray, filename, log) {
+    if (this._lazy) {
+      this._flushPending();
+    }
     let inStream = this.getInputStream();
     this.reset();
     if (!inStream) {
       log.debug("Failed to flush log to a file - no input stream");
       return;
     }
     log.debug("Flushing file log");
     log.trace("Beginning stream copy to " + filename + ": " + Date.now());
@@ -182,16 +211,20 @@ LogManager.prototype = {
       return observer;
     }
 
     this._observeConsolePref = setupAppender(consoleAppender, "log.appender.console", Log.Level.Fatal, 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 FlushableStorageAppender(formatter);
+    // There's no point to deferring the formatting and writing if we're always
+    // going to do it anyway (which is effectively the case if logOnSuccess is set).
+    fapp.lazy = !this._prefs.get("log.appender.file.logOnSuccess", false);
+
     // 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]) {
--- a/services/common/tests/unit/test_logmanager.js
+++ b/services/common/tests/unit/test_logmanager.js
@@ -128,53 +128,53 @@ add_task(async function test_logFileErro
   // One error log file exists.
   checkLogFile("error");
 
   lm.finalize();
 });
 
 // Test that we correctly write success logs.
 add_task(async function test_logFileSuccess() {
-  Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnError", false);
-  Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnSuccess", false);
-
-  let lm = new LogManager("log-manager.test.", ["TestLog2"], "test");
+  for (let laziness of [true, false]) {
+    Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnError", false);
+    Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnSuccess", false);
+    let lm = new LogManager("log-manager.test.", ["TestLog2"], "test");
+    lm._fileAppender.lazy = laziness;
+    let log = Log.repository.getLogger("TestLog2");
+    log.info("an info message");
+    await lm.resetFileLog();
+    // Zero log files exist.
+    checkLogFile(null);
 
-  let log = Log.repository.getLogger("TestLog2");
-  log.info("an info message");
-  await lm.resetFileLog();
-  // Zero log files exist.
-  checkLogFile(null);
+    // Reset logOnSuccess and do it again - log should appear.
+    Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnSuccess", true);
+    log.info("an info message");
+    await lm.resetFileLog();
 
-  // Reset logOnSuccess and do it again - log should appear.
-  Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnSuccess", true);
-  log.info("an info message");
-  await lm.resetFileLog();
-
-  checkLogFile("success");
+    checkLogFile("success");
 
-  // Now test with no "reason" specified and no "error" record.
-  log.info("an info message");
-  await lm.resetFileLog();
-  // should get a "success" entry.
-  checkLogFile("success");
+    // Now test with no "reason" specified and no "error" record.
+    log.info("an info message");
+    await lm.resetFileLog();
+    // should get a "success" entry.
+    checkLogFile("success");
 
-  // With no "reason" and an error record - should get no success log.
-  log.error("an error message");
-  await lm.resetFileLog();
-  // should get no entry
-  checkLogFile(null);
+    // With no "reason" and an error record - should get no success log.
+    log.error("an error message");
+    await lm.resetFileLog();
+    // should get no entry
+    checkLogFile(null);
 
-  // And finally now with no error, to ensure that the fact we had an error
-  // previously doesn't persist after the .resetFileLog call.
-  log.info("an info message");
-  await lm.resetFileLog();
-  checkLogFile("success");
-
-  lm.finalize();
+    // And finally now with no error, to ensure that the fact we had an error
+    // previously doesn't persist after the .resetFileLog call.
+    log.info("an info message");
+    await lm.resetFileLog();
+    checkLogFile("success");
+    lm.finalize();
+  }
 });
 
 // Test that we correctly write error logs.
 add_task(async function test_logFileError() {
   Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnError", false);
   Services.prefs.setBoolPref("log-manager.test.log.appender.file.logOnSuccess", false);
 
   let lm = new LogManager("log-manager.test.", ["TestLog2"], "test");