Bug 1018895 - Make AsyncShutdown output easier to parse by TBPL. r=froydnj, r=edmorley
authorDavid Rajchenbach-Teller <dteller@mozilla.com>
Tue, 03 Jun 2014 01:14:00 -0400
changeset 205552 993e88c0c67e39856062971dbb32930493582d14
parent 205551 816084978ed14216fd76c2ea83cefe4c2bc62a13
child 205553 54e8f6d1410a7e395272fd0ced12ed793dec8bc1
push id3741
push userasasaki@mozilla.com
push dateMon, 21 Jul 2014 20:25:18 +0000
treeherdermozilla-beta@4d6f46f5af68 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersfroydnj, edmorley
bugs1018895
milestone32.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1018895 - Make AsyncShutdown output easier to parse by TBPL. r=froydnj, r=edmorley
toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
toolkit/modules/AsyncShutdown.jsm
toolkit/modules/tests/xpcshell/test_AsyncShutdown.js
--- a/toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
+++ b/toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js
@@ -15,25 +15,28 @@ function setup_crash() {
   let phase = AsyncShutdown._getPhase(TOPIC);
   phase.addBlocker("A blocker that is never satisfied", function() {
     dump("Installing blocker\n");
     let deferred = Promise.defer();
     return deferred.promise;
   });
 
   Services.obs.notifyObservers(null, TOPIC, null);
+  dump(new Error().stack + "\n");
   dump("Waiting for crash\n");
 }
 
 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);
+  Assert.equal(info.phase, "testing-async-shutdown-crash");
+  Assert.equal(info.conditions[0].name, "A blocker that is never satisfied");
+  // This test spawns subprocesses by using argument "-e" of xpcshell, so
+  // this is the filename known to xpcshell.
+  Assert.equal(info.conditions[0].filename, "-e");
 }
 
 // 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);
--- a/toolkit/modules/AsyncShutdown.jsm
+++ b/toolkit/modules/AsyncShutdown.jsm
@@ -423,22 +423,32 @@ function Barrier(name) {
       if (fetchState && typeof fetchState != "function") {
         throw new TypeError("Expected nothing or a function as third argument");
       }
       if (!this._conditions) {
 	throw new Error("Phase " + this._name +
 			" has already begun, it is too late to register" +
 			" completion condition '" + name + "'.");
       }
+
+      // Determine the filename and line number of the caller.
+      let leaf = Components.stack;
+      let frame;
+      for (frame = leaf; frame != null && frame.filename == leaf.filename; frame = frame.caller) {
+        // Climb up the stack
+      }
       let set = this._conditions.get(condition);
       if (!set) {
         set = [];
         this._conditions.set(condition, set);
       }
-      set.push({name: name, fetchState: fetchState});
+      set.push({name: name,
+                fetchState: fetchState,
+                filename: frame ? frame.filename : "?",
+                lineNumber: frame ? frame.lineNumber : -1});
     }.bind(this),
 
     /**
      * Remove the blocker for a condition.
      *
      * If several blockers have been registered for the same
      * condition, remove all these blockers. If no blocker has been
      * registered for this condition, this is a noop.
@@ -475,19 +485,22 @@ Barrier.prototype = Object.freeze({
   get state() {
     if (this._conditions) {
       return "Not started";
     }
     if (!this._monitors) {
       return "Complete";
     }
     let frozen = [];
-    for (let {name, isComplete, fetchState} of this._monitors) {
+    for (let {name, isComplete, fetchState, filename, lineNumber} of this._monitors) {
       if (!isComplete) {
-        frozen.push({name: name, state: safeGetState(fetchState)});
+        frozen.push({name: name,
+                     state: safeGetState(fetchState),
+                     filename: filename,
+                     lineNumber: lineNumber});
       }
     }
     return frozen;
   },
 
   /**
    * Wait until all currently registered blockers are complete.
    *
@@ -531,17 +544,17 @@ Barrier.prototype = Object.freeze({
 
     // Information to determine and report to the user which conditions
     // are not satisfied yet.
     this._monitors = [];
 
     for (let _condition of conditions.keys()) {
       for (let current of conditions.get(_condition)) {
         let condition = _condition; // Avoid capturing the wrong variable
-        let {name, fetchState} = current;
+        let {name, fetchState, filename, lineNumber} = current;
 
         // An indirection on top of condition, used to let clients
         // cancel a blocker through removeBlocker.
         let indirection = Promise.defer();
         this._indirections.set(condition, indirection);
 
         // Gather all completion conditions
 
@@ -560,17 +573,19 @@ Barrier.prototype = Object.freeze({
           // function returned |undefined| or failed), that new promise
           // isn't going to be terribly interesting, but it will behave
           // as a promise.
           condition = Promise.resolve(condition);
 
           let monitor = {
             isComplete: false,
             name: name,
-            fetchState: fetchState
+            fetchState: fetchState,
+            filename: filename,
+            lineNumber: lineNumber
           };
 
 	  condition = condition.then(null, function onError(error) {
             let msg = "A completion condition encountered an error" +
               " while we were spinning the event loop." +
 	      " Condition: " + name +
               " Phase: " + topic +
               " State: " + safeGetState(fetchState);
@@ -664,45 +679,63 @@ Barrier.prototype = Object.freeze({
       // can do to avoid leaving the user's computer in an unstable (and
       // battery-sucking) situation is report the issue and crash.
       timeToCrash = looseTimer(crashAfterMS);
       timeToCrash.promise.then(
         function onTimeout() {
 	  // Report the problem as best as we can, then crash.
 	  let state = this.state;
 
-	  let msg = "At least one completion condition failed to complete" +
+          // If you change the following message, please make sure
+          // that any information on the topic and state appears
+          // within the first 200 characters of the message. This
+          // helps automatically sort oranges.
+          let msg = "AsyncShutdown timeout in " + topic +
+            " Conditions: " + JSON.stringify(state) +
+            " At least one completion condition failed to complete" +
 	    " within a reasonable amount of time. Causing a crash to" +
 	    " ensure that we do not leave the user with an unresponsive" +
 	    " process draining resources." +
-	    " Conditions: " + JSON.stringify(state) +
-	    " Barrier: " + topic;
 	  err(msg);
 	  if (gCrashReporter && gCrashReporter.enabled) {
             let data = {
               phase: topic,
               conditions: state
 	    };
             gCrashReporter.annotateCrashReport("AsyncShutdownTimeout",
-            JSON.stringify(data));
+              JSON.stringify(data));
 	  } else {
             warn("No crash reporter available");
 	  }
 
-	  let error = new Error();
-	  gDebug.abort(error.fileName, error.lineNumber + 1);
+          // To help sorting out bugs, we want to make sure that the
+          // call to nsIDebug.abort points to a guilty client, rather
+          // than to AsyncShutdown itself. We search through all the
+          // clients until we find one that is guilty and use its
+          // filename/lineNumber, which have been determined during
+          // the call to `addBlocker`.
+          let filename = "?";
+          let lineNumber = -1;
+          for (let monitor of this._monitors) {
+            if (monitor.isComplete) {
+              continue;
+            }
+            filename = monitor.filename;
+            lineNumber = monitor.lineNumber;
+          }
+	  gDebug.abort(filename, lineNumber);
         }.bind(this),
 	  function onSatisfied() {
             // The promise has been rejected, which means that we have satisfied
             // all completion conditions.
           });
 
       promise = promise.then(function() {
         timeToCrash.reject();
-      }.bind(this)/* No error is possible here*/);
+      }/* No error is possible here*/);
     }
 
     return promise;
   },
 });
 
 
 
--- a/toolkit/modules/tests/xpcshell/test_AsyncShutdown.js
+++ b/toolkit/modules/tests/xpcshell/test_AsyncShutdown.js
@@ -265,12 +265,40 @@ add_task(function* test_phase_removeBloc
 
     do_print("Attempt to remove non-registered blocker after wait()");
     do_check_false(lock.removeBlocker("foo"));
     do_check_false(lock.removeBlocker(null));
   }
 
 });
 
-add_task(function() {
+add_task(function* test_state() {
+  do_print("Testing information contained in `state`");
+
+  let BLOCKER_NAME = "test_state blocker " + Math.random();
+
+  // Set up the barrier. Note that we cannot test `barrier.state`
+  // immediately, as it initially contains "Not started"
+  let barrier = new AsyncShutdown.Barrier("test_filename");
+  let deferred = Promise.defer();
+  let {filename, lineNumber} = Components.stack;
+  barrier.client.addBlocker(BLOCKER_NAME,
+    function() {
+      return deferred.promise;
+    });
+
+  let promiseDone = barrier.wait();
+
+  // Now that we have called `wait()`, the state contains interesting things
+  let state = barrier.state[0];
+  do_print("State: " + JSON.stringify(barrier.state, null, "\t"));
+  Assert.equal(state.filename, filename);
+  Assert.equal(state.lineNumber, lineNumber + 2);
+  Assert.equal(state.name, BLOCKER_NAME);
+  
+  deferred.resolve();
+  yield promiseDone;
+});
+
+add_task(function*() {
   Services.prefs.clearUserPref("toolkit.asyncshutdown.testing");
 });