Bug 965527 - Further AsyncShutdown error reporting for OS.File. r=yoric
authorDavid Rajchenbach-Teller <dteller@mozilla.com>
Mon, 24 Feb 2014 10:15:47 -0500
changeset 170824 03545057aff2fc4b0b275735251864f2406f2e0d
parent 170823 0ed9572044c105c4f3562c7bbad048342bcfa15e
child 170825 6021d523a810e00803ef290d56842d21a9ea61b6
push id270
push userpvanderbeken@mozilla.com
push dateThu, 06 Mar 2014 09:24:21 +0000
reviewersyoric
bugs965527
milestone30.0a1
Bug 965527 - Further AsyncShutdown error reporting for OS.File. r=yoric
toolkit/components/osfile/modules/osfile_async_front.jsm
toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
--- a/toolkit/components/osfile/modules/osfile_async_front.jsm
+++ b/toolkit/components/osfile/modules/osfile_async_front.jsm
@@ -102,17 +102,17 @@ function lazyPathGetter(constProp, dirKe
       delete SharedAll.Constants.Path[constProp];
       SharedAll.Constants.Path[constProp] = path;
     } catch (ex) {
       // Ignore errors if the value still isn't available. Hopefully
       // the next access will return it.
     }
 
     return path;
-  }
+  };
 }
 
 for (let [constProp, dirKey] of [
   ["localProfileDir", "ProfLD"],
   ["profileDir", "ProfD"],
   ["userApplicationDataDir", "UAppData"],
   ["winAppDataDir", "AppData"],
   ["winStartMenuProgsDir", "Progs"],
@@ -151,26 +151,27 @@ let Scheduler = {
   /**
    * A promise resolved once all operations are complete.
    *
    * This promise is never rejected and the result is always undefined.
    */
   queue: Promise.resolve(),
 
   /**
-   * The latest message sent and still waiting for a reply. This
-   * field is stored only in DEBUG builds, to avoid hoarding memory in
-   * release builds.
+   * The latest message sent and still waiting for a reply. In DEBUG
+   * builds, the entire message is stored, which may be memory-consuming.
+   * In non-DEBUG builds, only the method name is stored.
    */
   latestSent: undefined,
 
   /**
    * The latest reply received, or null if we are waiting for a reply.
-   * This field is stored only in DEBUG builds, to avoid hoarding
-   * memory in release builds.
+   * In DEBUG builds, the entire response is stored, which may be
+   * memory-consuming.  In non-DEBUG builds, only exceptions and
+   * method names are stored.
    */
   latestReceived: undefined,
 
   /**
    * A timer used to automatically shut down the worker after some time.
    */
   resetTimer: null,
 
@@ -236,41 +237,50 @@ let Scheduler = {
 
     // By convention, the last argument of any message may be an |options| object.
     let options;
     let methodArgs = args[0];
     if (methodArgs) {
       options = methodArgs[methodArgs.length - 1];
     }
     return this.push(() => Task.spawn(function*() {
+      Scheduler.latestReceived = null;
       if (OS.Constants.Sys.DEBUG) {
         // Update possibly memory-expensive debugging information
-        Scheduler.latestReceived = null;
-        Scheduler.latestSent = [method, ...args];
+        Scheduler.latestSent = [Date.now(), method, ...args];
+      } else {
+        Scheduler.latestSent = [Date.now(), method];
       }
       let data;
       let reply;
+      let isError = false;
       try {
         data = yield worker.post(method, ...args);
         reply = data;
       } catch (error if error instanceof PromiseWorker.WorkerError) {
         reply = error;
+        isError = true;
         throw EXCEPTION_CONSTRUCTORS[error.data.exn || "OSError"](error.data);
       } catch (error if error instanceof ErrorEvent) {
         reply = error;
         let message = error.message;
         if (message == "uncaught exception: [object StopIteration]") {
           throw StopIteration;
         }
+        isError = true;
         throw new Error(message, error.filename, error.lineno);
       } finally {
+        Scheduler.latestSent = Scheduler.latestSent.slice(0, 2);
         if (OS.Constants.Sys.DEBUG) {
           // Update possibly memory-expensive debugging information
-          Scheduler.latestSent = null;
-          Scheduler.latestReceived = reply;
+          Scheduler.latestReceived = [Date.now(), reply];
+        } else if (isError) {
+          Scheduler.latestReceived = [Date.now(), reply.message, reply.fileName, reply.lineNumber];
+        } else {
+          Scheduler.latestReceived = [Date.now()];
         }
         if (firstLaunch) {
           Scheduler._updateTelemetry();
         }
 
         // Don't restart the timer when reseting the worker, since that will
         // lead to an endless "resetWorker()" loop.
         if (method != "Meta_reset") {
@@ -1294,22 +1304,40 @@ this.OS.Path = Path;
 
 // Auto-flush OS.File during profile-before-change. This ensures that any I/O
 // that has been queued *before* profile-before-change is properly completed.
 // To ensure that I/O queued *during* profile-before-change is completed,
 // clients should register using AsyncShutdown.addBlocker.
 AsyncShutdown.profileBeforeChange.addBlocker(
   "OS.File: flush I/O queued before profile-before-change",
   // Wait until the latest currently enqueued promise is satisfied/rejected
-  (() => Scheduler.queue),
+  function() {
+    let DEBUG = false;
+    try {
+      DEBUG = Services.prefs.getBoolPref("toolkit.osfile.debug.failshutdown");
+    } catch (ex) {
+      // Ignore
+    }
+    if (DEBUG) {
+      // Return a promise that will never be satisfied
+      return Promise.defer().promise;
+    } else {
+      return Scheduler.queue;
+    }
+  },
   function getDetails() {
     let result = {
       launched: Scheduler.launched,
       shutdown: Scheduler.shutdown,
+      worker: !!worker,
       pendingReset: !!Scheduler.resetTimer,
+      latestSent: Scheduler.latestSent,
+      latestReceived: Scheduler.latestReceived
     };
-    if (OS.Constants.Sys.DEBUG) {
-      result.latestSent = Scheduler.latestSent;
-      result.latestReceived - Scheduler.latestReceived;
-    };
+    // Convert dates to strings for better readability
+    for (let key of ["latestSent", "latestReceived"]) {
+      if (result[key] && typeof result[key][0] == "number") {
+        result[key][0] = Date(result[key][0]);
+      }
+    }
     return result;
   }
 );
--- a/toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
+++ b/toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
@@ -1,11 +1,13 @@
 /* Any copyright is dedicated to the Public Domain.
  * http://creativecommons.org/publicdomain/zero/1.0/ */
 
+// Test that AsyncShutdown report errors correctly
+
 function setup_crash() {
   Components.utils.import("resource://gre/modules/AsyncShutdown.jsm", this);
   Components.utils.import("resource://gre/modules/Services.jsm", this);
   Components.utils.import("resource://gre/modules/Promise.jsm", this);
 
   Services.prefs.setBoolPref("toolkit.asyncshutdown.testing", true);
   Services.prefs.setIntPref("toolkit.asyncshutdown.crash_timeout", 10);
 
@@ -24,11 +26,69 @@ function setup_crash() {
 function after_crash(mdump, extra) {
   do_print("after crash: " + extra.AsyncShutdownTimeout);
   let info = JSON.parse(extra.AsyncShutdownTimeout);
   do_check_eq(info.phase, "testing-async-shutdown-crash");
   do_print("Condition: " + JSON.stringify(info.conditions));
   do_check_true(JSON.stringify(info.conditions).indexOf("A blocker that is never satisfied") != -1);
 }
 
+// Test that AsyncShutdown + OS.File reports errors correctly, in a case in which
+// the latest operation succeeded
+
+function setup_osfile_crash_noerror() {
+  Components.utils.import("resource://gre/modules/Services.jsm", this);
+  Components.utils.import("resource://gre/modules/osfile.jsm", this);
+
+  Services.prefs.setBoolPref("toolkit.osfile.debug.failshutdown", true);
+  Services.prefs.setIntPref("toolkit.asyncshutdown.crash_timeout", 1);
+
+  OS.File.getCurrentDirectory();
+  Services.obs.notifyObservers(null, "profile-before-change", null);
+  dump("Waiting for crash\n");
+};
+
+function after_osfile_crash_noerror(mdump, extra) {
+  do_print("after OS.File crash: " + JSON.stringify(extra.AsyncShutdownTimeout));
+  let info = JSON.parse(extra.AsyncShutdownTimeout);
+  let state = info.conditions[0].state;
+  do_print("Keys: " + Object.keys(state).join(", "));
+  do_check_eq(info.phase, "profile-before-change");
+  do_check_true(state.launched);
+  do_check_false(state.shutdown);
+  do_check_true(state.worker);
+  do_check_true(!!state.latestSent);
+  do_check_eq(state.latestSent[1], "getCurrentDirectory");
+}
+
+// Test that AsyncShutdown + OS.File reports errors correctly, in a case in which
+// the latest operation failed
+
+function setup_osfile_crash_exn() {
+  Components.utils.import("resource://gre/modules/Services.jsm", this);
+  Components.utils.import("resource://gre/modules/osfile.jsm", this);
+
+  Services.prefs.setBoolPref("toolkit.osfile.debug.failshutdown", true);
+  Services.prefs.setIntPref("toolkit.asyncshutdown.crash_timeout", 1);
+
+  OS.File.read("I do not exist");
+  Services.obs.notifyObservers(null, "profile-before-change", null);
+  dump("Waiting for crash\n");
+};
+
+function after_osfile_crash_exn(mdump, extra) {
+  do_print("after OS.File crash: " + JSON.stringify(extra.AsyncShutdownTimeout));
+  let info = JSON.parse(extra.AsyncShutdownTimeout);
+  let state = info.conditions[0].state;
+  do_print("Keys: " + Object.keys(state).join(", "));
+  do_check_eq(info.phase, "profile-before-change");
+  do_check_true(state.launched);
+  do_check_false(state.shutdown);
+  do_check_true(state.worker);
+  do_check_true(!!state.latestSent);
+  do_check_eq(state.latestSent[1], "read");
+}
+
 function run_test() {
   do_crash(setup_crash, after_crash);
+  do_crash(setup_osfile_crash_noerror, after_osfile_crash_noerror);
+  do_crash(setup_osfile_crash_exn, after_osfile_crash_exn);
 }