Bug 623080: make Resource more loggy and robust. r=mconnor
authorRichard Newman <rnewman@mozilla.com>
Fri, 01 Apr 2011 15:27:19 -0700
changeset 67764 7b7cb3e1360d53b4f25017aec367d40288bfbbe3
parent 67763 6b5bee7bbb01b7e9551b36a516c0f89a626ce78c
child 67765 5f926a6429fc8e57ad1f7e7b4e657c5a0a3b6d96
push id19427
push userpweitershausen@mozilla.com
push dateSun, 10 Apr 2011 18:54:44 +0000
treeherdermozilla-central@21ce62e6aebe [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmconnor
bugs623080
milestone2.0b13pre
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 623080: make Resource more loggy and robust. r=mconnor
services/sync/modules/resource.js
--- a/services/sync/modules/resource.js
+++ b/services/sync/modules/resource.js
@@ -16,16 +16,17 @@
  * The Initial Developer of the Original Code is Mozilla.
  * Portions created by the Initial Developer are Copyright (C) 2007
  * the Initial Developer. All Rights Reserved.
  *
  * Contributor(s):
  *  Dan Mills <thunder@mozilla.com>
  *  Anant Narayanan <anant@kix.in>
  *  Philipp von Weitershausen <philipp@weitershausen.de>
+ *  Richard Newman <rnewman@mozilla.com>
  *
  * Alternatively, the contents of this file may be used under the terms of
  * either the GNU General Public License Version 2 or later (the "GPL"), or
  * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
  * in which case the provisions of the GPL or the LGPL are applicable instead
  * of those above. If you wish to allow use of your version of this file only
  * under the terms of either the GPL or the LGPL, and not to allow others to
  * use your version of this file under the terms of the MPL, indicate your
@@ -122,31 +123,31 @@ AuthMgr.prototype = {
  *   post(data, callback)
  *   delete(callback)
  * 
  * 'callback' is a function with the following signature:
  * 
  *   function callback(error, result) {...}
  * 
  * 'error' will be null on successful requests. Likewise, result will not be
- * passes (=undefined) when an error occurs. Note that this is independent of
+ * passed (=undefined) when an error occurs. Note that this is independent of
  * the status of the HTTP response.
  */
 function AsyncResource(uri) {
   this._log = Log4Moz.repository.getLogger(this._logName);
   this._log.level =
     Log4Moz.Level[Utils.prefs.getCharPref("log.logger.network.resources")];
   this.uri = uri;
   this._headers = {};
   this._onComplete = Utils.bind2(this, this._onComplete);
 }
 AsyncResource.prototype = {
   _logName: "Net.Resource",
 
-  // Wait 5 minutes before killing a request
+  // Wait 5 minutes before killing a request.
   ABORT_TIMEOUT: 300000,
 
   // ** {{{ Resource.authenticator }}} **
   //
   // Getter and setter for the authenticator module
   // responsible for this particular resource. The authenticator
   // module may modify the headers to perform authentication
   // while performing a request for the resource, for example.
@@ -218,39 +219,39 @@ AsyncResource.prototype = {
 
     // Always validate the cache:
     channel.loadFlags |= Ci.nsIRequest.LOAD_BYPASS_CACHE;
     channel.loadFlags |= Ci.nsIRequest.INHIBIT_CACHING;
 
     // Setup a callback to handle bad HTTPS certificates.
     channel.notificationCallbacks = new BadCertListener();
 
-    // Avoid calling the authorizer more than once
+    // Avoid calling the authorizer more than once.
     let headers = this.headers;
     for (let key in headers) {
       if (key == 'Authorization')
         this._log.trace("HTTP Header " + key + ": ***** (suppressed)");
       else
         this._log.trace("HTTP Header " + key + ": " + headers[key]);
       channel.setRequestHeader(key, headers[key], false);
     }
     return channel;
   },
 
   _onProgress: function Res__onProgress(channel) {},
 
   _doRequest: function _doRequest(action, data, callback) {
+    this._log.trace("In _doRequest.");
     this._callback = callback;
     let channel = this._channel = this._createRequest();
 
     if ("undefined" != typeof(data))
       this._data = data;
 
-    // PUT and POST are trreated differently because
-    // they have payload data.
+    // PUT and POST are treated differently because they have payload data.
     if ("PUT" == action || "POST" == action) {
       // Convert non-string bodies into JSON
       if (this._data.constructor.toString() != String)
         this._data = JSON.stringify(this._data);
 
       this._log.debug(action + " Length: " + this._data.length);
       this._log.trace(action + " Body: " + this._data);
 
@@ -269,83 +270,113 @@ AsyncResource.prototype = {
     // is performed asynchronously.
     let listener = new ChannelListener(this._onComplete, this._onProgress,
                                        this._log, this.ABORT_TIMEOUT);
     channel.requestMethod = action;
     channel.asyncOpen(listener, null);
   },
 
   _onComplete: function _onComplete(error, data) {
+    this._log.trace("In _onComplete. Error is " + error + ".");
+
     if (error) {
       this._callback(error);
       return;
     }
 
     this._data = data;
     let channel = this._channel;
     let action = channel.requestMethod;
 
-    // Set some default values in-case there's no response header
-    let headers = {};
+    this._log.trace("Channel: " + channel);
+    this._log.trace("Action: "  + action);
+
+    // Process status and success first. This way a problem with headers
+    // doesn't fail to include accurate status information.
     let status = 0;
     let success = false;
+
     try {
-      // Read out the response headers if available
+      status  = channel.responseStatus;
+      success = channel.requestSucceeded;    // HTTP status.
+
+      this._log.trace("Status: " + status);
+      this._log.trace("Success: " + success);
+
+      // Log the status of the request.
+      let mesg = [action, success ? "success" : "fail", status,
+                  channel.URI.spec].join(" ");
+      this._log.debug("mesg: " + mesg);
+
+      if (mesg.length > 200)
+        mesg = mesg.substr(0, 200) + "…";
+      this._log.debug(mesg);
+
+      // Additionally give the full response body when Trace logging.
+      if (this._log.level <= Log4Moz.Level.Trace)
+        this._log.trace(action + " body: " + data);
+
+    } catch(ex) {
+      // Got a response, but an exception occurred during processing.
+      // This shouldn't occur.
+      this._log.warn("Caught unexpected exception " + Utils.exceptionStr(ex) +
+                     " in _onComplete.");
+      this._log.debug(Utils.stackTrace(ex));
+    }
+
+    // Process headers. They can be empty, or the call can otherwise fail, so
+    // put this in its own try block.
+    let headers = {};
+    try {
+      this._log.trace("Processing response headers.");
+
+      // Read out the response headers if available.
       channel.visitResponseHeaders({
         visitHeader: function visitHeader(header, value) {
           headers[header.toLowerCase()] = value;
         }
       });
-      status = channel.responseStatus;
-      success = channel.requestSucceeded;
-
-      // Log the status of the request
-      let mesg = [action, success ? "success" : "fail", status,
-                  channel.URI.spec].join(" ");
-      if (mesg.length > 200)
-        mesg = mesg.substr(0, 200) + "…";
-      this._log.debug(mesg);
-      // Additionally give the full response body when Trace logging
-      if (this._log.level <= Log4Moz.Level.Trace)
-        this._log.trace(action + " body: " + data);
 
       // This is a server-side safety valve to allow slowing down
       // clients without hurting performance.
       if (headers["x-weave-backoff"])
         Observers.notify("weave:service:backoff:interval",
                          parseInt(headers["x-weave-backoff"], 10));
 
       if (success && headers["x-weave-quota-remaining"])
         Observers.notify("weave:service:quota:remaining",
                          parseInt(headers["x-weave-quota-remaining"], 10));
-    }
-    // Got a response but no header; must be cached (use default values)
-    catch(ex) {
-      this._log.debug(action + " cached: " + status);
+    } catch (ex) {
+      this._log.debug("Caught exception " + Utils.exceptionStr(ex) +
+                      " visiting headers in _onComplete.");
+      this._log.debug(Utils.stackTrace(ex));
     }
 
-    let ret = new String(data);
+    let ret     = new String(data);
+    ret.status  = status;
+    ret.success = success;
     ret.headers = headers;
-    ret.status = status;
-    ret.success = success;
 
-    // Make a lazy getter to convert the json response into an object
+    // Make a lazy getter to convert the json response into an object.
+    // Note that this can cause a parse error to be thrown far away from the
+    // actual fetch, so be warned!
     Utils.lazy2(ret, "obj", function() JSON.parse(ret));
 
-    // Notify if we get a 401 to maybe try again with a new uri
+    // Notify if we get a 401 to maybe try again with a new URI.
+    // TODO: more retry logic.
     if (status == 401) {
-      // Create an object to allow observers to decide if we should try again
+      // Create an object to allow observers to decide if we should try again.
       let subject = {
         newUri: "",
         resource: this,
         response: ret
       }
       Observers.notify("weave:resource:status:401", subject);
 
-      // Do the same type of request but with the new uri
+      // Do the same type of request but with the new URI.
       if (subject.newUri != "") {
         this.uri = subject.newUri;
         this._doRequest(action, this._data, this._callback);
         return;
       }
     }
 
     this._callback(null, ret);
@@ -472,46 +503,56 @@ function ChannelListener(onComplete, onP
   this._onProgress = onProgress;
   this._log = logger;
   this._timeout = timeout;
   this.delayAbort();
 }
 ChannelListener.prototype = {
 
   onStartRequest: function Channel_onStartRequest(channel) {
+    this._log.trace("onStartRequest called for channel " + channel + ".");
     channel.QueryInterface(Ci.nsIHttpChannel);
 
-    // Save the latest server timestamp when possible
+    // Save the latest server timestamp when possible.
     try {
       Resource.serverTime = channel.getResponseHeader("X-Weave-Timestamp") - 0;
     }
     catch(ex) {}
 
-    this._log.trace(channel.requestMethod + " " + channel.URI.spec);
+    this._log.trace("onStartRequest: " + channel.requestMethod + " " +
+                    channel.URI.spec);
     this._data = '';
     this.delayAbort();
   },
 
   onStopRequest: function Channel_onStopRequest(channel, context, status) {
-    // Clear the abort timer now that the channel is done
+    // Clear the abort timer now that the channel is done.
     this.abortTimer.clear();
 
+    let success = Components.isSuccessCode(status);
+    this._log.trace("Channel for " + channel.requestMethod + " " +
+                    channel.URI.spec + ": isSuccessCode(" + status + ")? " +
+                    success);
+
     if (this._data == '')
       this._data = null;
 
     // Throw the failure code and stop execution.  Use Components.Exception()
     // instead of Error() so the exception is QI-able and can be passed across
     // XPCOM borders while preserving the status code.
-    if (!Components.isSuccessCode(status)) {
+    if (!success) {
       let message = Components.Exception("", status).name;
       let error = Components.Exception(message, status);
       this._onComplete(error);
       return;
     }
 
+    this._log.trace("Channel: flags = " + channel.loadFlags +
+                    ", URI = " + channel.URI.spec +
+                    ", HTTP success? " + channel.requestSucceeded);
     this._onComplete(null, this._data);
   },
 
   onDataAvailable: function Channel_onDataAvail(req, cb, stream, off, count) {
     let siStream = Cc["@mozilla.org/scriptableinputstream;1"].
       createInstance(Ci.nsIScriptableInputStream);
     siStream.init(stream);
     try {