Bug 1018895 - Make AsyncShutdown output easier to parse by TBPL. r=froydnj, r=edmorley

toolkit/crashreporter/test/unit/test_crash_AsyncShutdown.js

@@ -20,15 +20,18 @@ function setup_crash() {
   });
 
   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

toolkit/modules/AsyncShutdown.jsm

@@ -428,12 +428,22 @@ function Barrier(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),
 
     /**
@@ -480,9 +490,12 @@ Barrier.prototype = Object.freeze({
       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;
@@ -536,7 +549,7 @@ Barrier.prototype = Object.freeze({
     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.
@@ -565,7 +578,9 @@ Barrier.prototype = Object.freeze({
           let monitor = {
             isComplete: false,
             name: name,
-            fetchState: fetchState
+            fetchState: fetchState,
+            filename: filename,
+            lineNumber: lineNumber
           };
 
 	  condition = condition.then(null, function onError(error) {
@@ -669,12 +684,16 @@ Barrier.prototype = Object.freeze({
 	  // 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 = {
@@ -682,13 +701,27 @@ Barrier.prototype = Object.freeze({
               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
@@ -697,7 +730,7 @@ Barrier.prototype = Object.freeze({
 
       promise = promise.then(function() {
         timeToCrash.reject();
-      }.bind(this)/* No error is possible here*/);
+      }/* No error is possible here*/);
     }
 
     return promise;

toolkit/modules/tests/xpcshell/test_AsyncShutdown.js

@@ -270,7 +270,35 @@ add_task(function* test_phase_removeBlocker() {
 
 });
 
-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");
 });