Changed AsyncException so that it dynamically subclasses the exception it's wrapping, and adds an 'asyncStack' property to allow access to the asynchronous call stack. This, along with my previous few commits, makes the processing of stack traces in our code much more streamlined, and also allows our debugging output to be more informative, as stack information is now logged from the point at which an exception was thrown, rather than the point at which it was caught.
authorAtul Varma <varmaa@toolness.com>
Wed, 25 Jun 2008 04:43:07 -0700
changeset 44739 bd3accb2fccae83cde40c1b902e4a2bf7d01a61a
parent 44738 13571441ff63672cef23d1608c1ef7f7fcc17fef
child 44740 28fbf7bce40aa896291642b6cdb859fd6afde4bd
push id14033
push useredward.lee@engineering.uiuc.edu
push dateWed, 23 Jun 2010 22:21:35 +0000
treeherderautoland@227db4ad8cdf [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
Changed AsyncException so that it dynamically subclasses the exception it's wrapping, and adds an 'asyncStack' property to allow access to the asynchronous call stack. This, along with my previous few commits, makes the processing of stack traces in our code much more streamlined, and also allows our debugging output to be more informative, as stack information is now logged from the point at which an exception was thrown, rather than the point at which it was caught. Also renamed some things in async.js to be more descriptive and easier-to-understand, albeit a bit more verbose.
services/sync/modules/async.js
services/sync/modules/engines.js
services/sync/modules/service.js
services/sync/modules/util.js
services/sync/tests/unit/test_async_exceptions.js
--- a/services/sync/modules/async.js
+++ b/services/sync/modules/async.js
@@ -70,35 +70,41 @@ NamableTracker.prototype = {
       yield name;
   }
 }
 
 let gCurrentId = 0;
 let gCurrentCbId = 0;
 let gOutstandingGenerators = new NamableTracker();
 
-function AsyncException(initFrame, message) {
-  this.message = message;
-  this._traceback = initFrame;
-}
-AsyncException.prototype = {
-  get message() { return this._message; },
-  set message(value) { this._message = value; },
+// The AsyncException class represents an exception that's been thrown
+// by an asynchronous coroutine-based function.  For the most part, it
+// behaves just like the "real" exception it wraps, only it adds some
+// embellishments that provide information about what other
+// asynchronous coroutine-based functions our current one was called
+// from.
+function AsyncException(asyncStack, exceptionToWrap) {
+  this._exceptionToWrap = exceptionToWrap;
+  this._asyncStack = asyncStack;
 
-  get traceback() { return this._traceback; },
-  set traceback(value) { this._traceback = value; },
+  // Here we'll have our exception instance's prototype be dynamically
+  // generated; this ultimately allows us to dynamically "subclass"
+  // the exception we're wrapping at runtime.
+  this.__proto__ = {
+    get asyncStack() {
+      return this._asyncStack;
+    },
 
-  addFrame: function AsyncException_addFrame(frame) {
-    this.traceback += (this.traceback? "\n" : "") + formatFrame(frame);
-  },
-
-  toString: function AsyncException_toString() {
-    return this.message;
-  }
-};
+    addAsyncFrame: function AsyncException_addAsyncFrame(frame) {
+      this._asyncStack += ((this._asyncStack? "\n" : "") +
+                           formatAsyncFrame(frame));
+    }
+  };
+  this.__proto__.__proto__ = this._exceptionToWrap;
+}
 
 function Generator(thisArg, method, onComplete, args) {
   this._outstandingCbs = 0;
   this._log = Log4Moz.Service.getLogger("Async.Generator");
   this._log.level =
     Log4Moz.Level[Utils.prefs.getCharPref("log.logger.async")];
   this._thisArg = thisArg;
   this._method = method;
@@ -118,17 +124,17 @@ Generator.prototype = {
   get name() { return this._method.name + "-" + this._id; },
   get generator() { return this._generator; },
 
   get cb() {
     let caller = Components.stack.caller;
     let cbId = gCurrentCbId++;
     this._outstandingCbs++;
     this._log.trace(this.name + ": cb-" + cbId + " generated at:\n" +
-                    formatFrame(caller));
+                    formatAsyncFrame(caller));
     let self = this;
     let cb = function(data) {
       self._log.trace(self.name + ": cb-" + cbId + " called.");
       self._cont(data);
     };
     cb.parentGenerator = this;
     return cb;
   },
@@ -156,43 +162,44 @@ Generator.prototype = {
     };
   },
   set onComplete(value) {
     if (value && typeof value != "function")
       throw "Generator: expected type 'function', got type '" + typeof(value) + "'";
     this._onComplete = value;
   },
 
-  get traceback() {
-    return "unknown (async) :: " + this.name + "\n" + traceAsyncFrame(this._initFrame);
+  get asyncStack() {
+    return ("unknown (async) :: " + this.name + "\n" +
+            traceAsyncFrame(this._initFrame));
   },
 
   _handleException: function AsyncGen__handleException(e) {
     if (e instanceof StopIteration) {
       this._log.trace(this.name + ": End of coroutine reached.");
       // skip to calling done()
 
     } else if (this.onComplete.parentGenerator instanceof Generator) {
       this._log.trace("[" + this.name + "] Saving exception and stack trace");
       this._log.trace("Exception: " + Utils.exceptionStr(e));
 
         if (e instanceof AsyncException) {
           // FIXME: attempt to skip repeated frames, which can happen if the
           // child generator never yielded.  Would break for valid repeats (recursion)
-          if (e.traceback.indexOf(formatFrame(this._initFrame)) == -1)
-            e.addFrame(this._initFrame);
+          if (e.asyncStack.indexOf(formatAsyncFrame(this._initFrame)) == -1)
+            e.addAsyncFrame(this._initFrame);
         } else {
-          e = new AsyncException(this.traceback, e);
+          e = new AsyncException(this.asyncStack, e);
         }
 
       this._exception = e;
 
     } else {
       this._log.error("Exception: " + Utils.exceptionStr(e));
-      this._log.debug("Stack trace:\n" + (e.traceback? e.traceback : this.traceback));
+      this._log.debug("Stack trace:\n" + Utils.stackTrace(e));
     }
 
     // continue execution of caller.
     // in the case of StopIteration we could return an error right
     // away, but instead it's easiest/best to let the caller handle
     // the error after a yield / in a callback.
     if (!this._timer) {
       this._log.trace("[" + this.name + "] running done() from _handleException()");
@@ -259,17 +266,17 @@ Generator.prototype = {
                      "' may have outstanding callbacks.");
     this._timer = Utils.makeTimerForCall(cb);
   },
 
   _done: function AsyncGen__done(retval) {
     if (!this._generator) {
       this._log.error("Async method '" + this.name + "' is missing a 'yield' call " +
                       "(or called done() after being finalized)");
-      this._log.trace("Initial stack trace:\n" + this.traceback);
+      this._log.trace("Initial async stack trace:\n" + this.asyncStack);
     } else {
       this._generator.close();
     }
     this._generator = null;
     this._timer = null;
 
     if (this._exception) {
       this._log.trace("[" + this.name + "] Propagating exception to parent generator");
@@ -277,25 +284,25 @@ Generator.prototype = {
     } else {
       try {
         this._log.trace("[" + this.name + "] Running onComplete()");
         this.onComplete(retval);
       } catch (e) {
         this._log.error("Exception caught from onComplete handler of " +
                         this.name + " generator");
         this._log.error("Exception: " + Utils.exceptionStr(e));
-        this._log.trace("Current stack trace:\n" + traceAsyncFrame(Components.stack));
-        this._log.trace("Initial stack trace:\n" + this.traceback);
+        this._log.trace("Current stack trace:\n" + Utils.stackTrace(e));
+        this._log.trace("Initial async stack trace:\n" + this.asyncStack);
       }
     }
     gOutstandingGenerators.remove(this);
   }
 };
 
-function formatFrame(frame) {
+function formatAsyncFrame(frame) {
   // FIXME: sort of hackish, might be confusing if there are multiple
   // extensions with similar filenames
   let tmp = frame.filename.replace(/^file:\/\/.*\/([^\/]+.js)$/, "module:$1");
   tmp += ":" + frame.lineNumber + " :: " + frame.name;
   return tmp;
 }
 
 function traceAsyncFrame(frame, str) {
@@ -304,17 +311,17 @@ function traceAsyncFrame(frame, str) {
 
   // skip our frames
   // FIXME: we should have a pref for this, for debugging async.js itself
   while (frame.name && frame.name.match(/^Async(Gen|)_/))
     frame = frame.caller;
 
   if (frame.caller)
     str = traceAsyncFrame(frame.caller, str);
-  str = formatFrame(frame) + (str? "\n" : "") + str;
+  str = formatAsyncFrame(frame) + (str? "\n" : "") + str;
 
   return str;
 }
 
 
 Async = {
   get outstandingGenerators() { return gOutstandingGenerators; },
 
@@ -345,13 +352,9 @@ Async = {
   // Note that 'this' refers to the method being called, not the
   // Async object.
 
   sugar: function Async_sugar(thisArg, onComplete  /* , arg1, arg2, ... */) {
     let args = Array.prototype.slice.call(arguments, 1);
     args.unshift(thisArg, this);
     Async.run.apply(Async, args);
   },
-
-  exceptionStr: function Async_exceptionStr(gen, ex) {
-    return "Exception caught in " + gen.name + ": " + Utils.exceptionStr(ex);
-  }
 };
--- a/services/sync/modules/engines.js
+++ b/services/sync/modules/engines.js
@@ -236,17 +236,17 @@ Engine.prototype = {
 
   _sync: function Engine__sync() {
     let self = yield;
 
     this._log.info("Beginning sync");
 
     try {
       yield this._remote.openSession(self.cb);
-    } catch (e if e.message.status == 404) {
+    } catch (e if e.status == 404) {
       yield this._initialUpload.async(this, self.cb);
       return;
     }
 
     if (this._remote.status.data.GUID != this._snapshot.GUID) {
       this._log.debug("Remote/local sync GUIDs do not match.  " +
                      "Forcing initial sync.");
       this._log.trace("Remote: " + this._remote.status.data.GUID);
--- a/services/sync/modules/service.js
+++ b/services/sync/modules/service.js
@@ -694,18 +694,17 @@ WeaveSvc.prototype = {
   _syncEngine: function WeaveSvc__syncEngine(engine) {
     let self = yield;
     try {
       engine.sync(self.cb);
       yield;
       engine._tracker.resetScore();
     } catch(e) {
       this._log.error(Utils.exceptionStr(e));
-      if (e.traceback)
-        this._log.trace(e.traceback);
+      this._log.error(Utils.stackTrace(e));
     }
   },
 
   resetServer: function WeaveSync_resetServer(onComplete) {
     this._notify("reset-server",
                  this._lock(this._resetServer)).async(this, onComplete);
   },
   _resetServer: function WeaveSync__resetServer() {
--- a/services/sync/modules/util.js
+++ b/services/sync/modules/util.js
@@ -229,16 +229,21 @@ let Utils = {
       }
     } else if (e.stack)
       // It's a standard JS exception
       output += e.stack;
     else
       // It's some other thrown object, e.g. a bare string.
       output += "No traceback available.\n";
 
+    if (e.asyncStack) {
+      output += "This exception was raised by an asynchronous coroutine.\n";
+      output += "Initial async stack trace:\n" + e.asyncStack;
+    }
+
     return output;
   },
 
   checkStatus: function Weave_checkStatus(code, msg, ranges) {
     if (!ranges)
       ranges = [[200,300]];
 
     for (let i = 0; i < ranges.length; i++) {
--- a/services/sync/tests/unit/test_async_exceptions.js
+++ b/services/sync/tests/unit/test_async_exceptions.js
@@ -1,45 +1,56 @@
 Cu.import("resource://weave/util.js");
 Cu.import("resource://weave/async.js");
 
 Function.prototype.async = Async.sugar;
 
+function _ensureExceptionIsValid(e) {
+  do_check_eq(e.message, "intentional failure");
+  do_check_eq(typeof(e.asyncStack), "string");
+  do_check_true(e.asyncStack.indexOf("thirdGen") > -1);
+  do_check_true(e.asyncStack.indexOf("secondGen") > -1);
+  do_check_true(e.asyncStack.indexOf("runTestGenerator") > -1);
+  do_check_true(e.stack.indexOf("thirdGen") > -1);
+  do_check_eq(e.stack.indexOf("secondGen"), -1);
+  do_check_eq(e.stack.indexOf("runTestGenerator"), -1);
+}
+
 function thirdGen() {
   let self = yield;
 
   Utils.makeTimerForCall(self.cb);
   yield;
 
   throw new Error("intentional failure");
 }
 
 function secondGen() {
   let self = yield;
 
   thirdGen.async({}, self.cb);
   try {
     let result = yield;
   } catch (e) {
-    do_check_eq(e.message, "Error: intentional failure");
+    ensureExceptionIsValid(e);
     throw e;
   }
 
   self.done();
 }
 
 function runTestGenerator() {
   let self = yield;
 
   secondGen.async({}, self.cb);
   let wasCaught = false;
   try {
     let result = yield;
   } catch (e) {
-    do_check_eq(e.message, "Error: intentional failure");
+    ensureExceptionIsValid(e);
     wasCaught = true;
   }
 
   do_check_true(wasCaught);
   self.done();
 }
 
 function run_test() {