Bug 1121325 - Improve sync logging with FxA. r=rnewman, r=ckarlof, a=lmandel
authorMark Hammond <mhammond@skippinet.com.au>
Wed, 28 Jan 2015 10:11:08 +1100
changeset 249532 5598d7df1010f2217dc43ed2a1be2eef7c9f965a
parent 249531 f10650c04229504a8dc3e3c2efe525043fd0c3af
child 249533 c785bf627bac4746d9a29b59942cf623f2d56040
push id4489
push userraliiev@mozilla.com
push dateMon, 23 Feb 2015 15:17:55 +0000
treeherdermozilla-beta@fd7c3dc24146 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersrnewman, ckarlof, lmandel
bugs1121325
milestone37.0a2
Bug 1121325 - Improve sync logging with FxA. r=rnewman, r=ckarlof, a=lmandel
services/common/hawkclient.js
services/common/rest.js
services/common/services-common.js
services/common/tokenserverclient.js
services/sync/modules/browserid_identity.js
services/sync/modules/policies.js
--- a/services/common/hawkclient.js
+++ b/services/common/hawkclient.js
@@ -32,34 +32,42 @@ Cu.import("resource://services-common/ut
 Cu.import("resource://services-crypto/utils.js");
 Cu.import("resource://services-common/hawkrequest.js");
 Cu.import("resource://services-common/observers.js");
 Cu.import("resource://gre/modules/Promise.jsm");
 Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 
-// loglevel should be one of "Fatal", "Error", "Warn", "Info", "Config",
+// log.appender.dump should be one of "Fatal", "Error", "Warn", "Info", "Config",
 // "Debug", "Trace" or "All". If none is specified, "Error" will be used by
 // default.
-const PREF_LOG_LEVEL = "services.hawk.loglevel";
+// Note however that Sync will also add this log to *its* DumpAppender, so
+// in a Sync context it shouldn't be necessary to adjust this - however, that
+// also means error logs are likely to be dump'd twice but that's OK.
+const PREF_LOG_LEVEL = "services.common.hawk.log.appender.dump";
 
 // A pref that can be set so "sensitive" information (eg, personally
 // identifiable info, credentials, etc) will be logged.
-const PREF_LOG_SENSITIVE_DETAILS = "services.hawk.log.sensitive";
+const PREF_LOG_SENSITIVE_DETAILS = "services.common.hawk.log.sensitive";
 
 XPCOMUtils.defineLazyGetter(this, "log", function() {
   let log = Log.repository.getLogger("Hawk");
-  log.addAppender(new Log.DumpAppender());
-  log.level = Log.Level.Error;
+  // We set the log itself to "debug" and set the level from the preference to
+  // the appender.  This allows other things to send the logs to different
+  // appenders, while still allowing the pref to control what is seen via dump()
+  log.level = Log.Level.Debug;
+  let appender = new Log.DumpAppender();
+  log.addAppender(appender);
+  appender.level = Log.Level.Error;
   try {
     let level =
       Services.prefs.getPrefType(PREF_LOG_LEVEL) == Ci.nsIPrefBranch.PREF_STRING
       && Services.prefs.getCharPref(PREF_LOG_LEVEL);
-    log.level = Log.Level[level] || Log.Level.Error;
+    appender.level = Log.Level[level] || Log.Level.Error;
   } catch (e) {
     log.error(e);
   }
 
   return log;
 });
 
 // A boolean to indicate if personally identifiable information (or anything
@@ -94,22 +102,27 @@ this.HawkClient = function(host) {
 this.HawkClient.prototype = {
 
   /*
    * Construct an error message for a response.  Private.
    *
    * @param restResponse
    *        A RESTResponse object from a RESTRequest
    *
-   * @param errorString
-   *        A string describing the error
+   * @param error
+   *        A string or object describing the error
    */
-  _constructError: function(restResponse, errorString) {
+  _constructError: function(restResponse, error) {
     let errorObj = {
-      error: errorString,
+      error: error,
+      // This object is likely to be JSON.stringify'd, but neither Error()
+      // objects nor Components.Exception objects do the right thing there,
+      // so we add a new element which is simply the .toString() version of
+      // the error object, so it does appear in JSON'd values.
+      errorString: error.toString(),
       message: restResponse.statusText,
       code: restResponse.status,
       errno: restResponse.status
     };
     errorObj.toString = function() this.code + ": " + this.message;
     let retryAfter = restResponse.headers && restResponse.headers["retry-after"];
     retryAfter = retryAfter ? parseInt(retryAfter) : retryAfter;
     if (retryAfter) {
@@ -185,16 +198,22 @@ this.HawkClient.prototype = {
   request: function(path, method, credentials=null, payloadObj={}, retryOK=true) {
     method = method.toLowerCase();
 
     let deferred = Promise.defer();
     let uri = this.host + path;
     let self = this;
 
     function _onComplete(error) {
+      // |error| can be either a normal caught error or an explicitly created
+      // Components.Exception() error. Log it now as it might not end up
+      // correctly in the logs by the time it's passed through _constructError.
+      if (error) {
+        log.warn("hawk request error", error);
+      }
       let restResponse = this.response;
       let status = restResponse.status;
 
       log.debug("(Response) " + path + ": code: " + status +
                 " - Status text: " + restResponse.statusText);
       if (logPII) {
         log.debug("Response text: " + restResponse.body);
       }
--- a/services/common/rest.js
+++ b/services/common/rest.js
@@ -453,16 +453,17 @@ RESTRequest.prototype = {
     }
 
     // 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 (!statusSuccess) {
       let message = Components.Exception("", statusCode).name;
       let error = Components.Exception(message, statusCode);
+      this._log.debug(this.method + " " + uri + " failed: " + statusCode + " - " + message);
       this.onComplete(error);
       this.onComplete = this.onProgress = null;
       return;
     }
 
     this._log.debug(this.method + " " + uri + " " + this.response.status);
 
     // Additionally give the full response body when Trace logging.
--- a/services/common/services-common.js
+++ b/services/common/services-common.js
@@ -4,9 +4,9 @@
 
 // This file contains default preference values for components in
 // services-common.
 
 pref("services.common.log.logger.rest.request", "Debug");
 pref("services.common.log.logger.rest.response", "Debug");
 
 pref("services.common.storageservice.sendVersionInfo", true);
-pref("services.common.tokenserverclient.logger.level", "Info");
+pref("services.common.log.logger.tokenserverclient", "Debug");
--- a/services/common/tokenserverclient.js
+++ b/services/common/tokenserverclient.js
@@ -8,23 +8,23 @@ this.EXPORTED_SYMBOLS = [
   "TokenServerClient",
   "TokenServerClientError",
   "TokenServerClientNetworkError",
   "TokenServerClientServerError",
 ];
 
 const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 
-Cu.import("resource://gre/modules/Preferences.jsm");
+Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/Log.jsm");
 Cu.import("resource://services-common/rest.js");
 Cu.import("resource://services-common/utils.js");
 Cu.import("resource://services-common/observers.js");
 
-const Prefs = new Preferences("services.common.tokenserverclient.");
+const PREF_LOG_LEVEL = "services.common.log.logger.tokenserverclient";
 
 /**
  * Represents a TokenServerClient error that occurred on the client.
  *
  * This is the base type for all errors raised by client operations.
  *
  * @param message
  *        (string) Error message.
@@ -135,17 +135,21 @@ TokenServerClientServerError.prototype._
  *  - The server sends a JSON response on error. The client does not currently
  *    parse this. It might be convenient if it did.
  *  - Currently most non-200 status codes are rolled into one error type. It
  *    might be helpful if callers had a richer API that communicated who was
  *    at fault (e.g. differentiating a 503 from a 401).
  */
 this.TokenServerClient = function TokenServerClient() {
   this._log = Log.repository.getLogger("Common.TokenServerClient");
-  this._log.level = Log.Level[Prefs.get("logger.level")];
+  let level = "Debug";
+  try {
+    level = Services.prefs.getCharPref(PREF_LOG_LEVEL);
+  } catch (ex) {}
+  this._log.level = Log.Level[level];
 }
 TokenServerClient.prototype = {
   /**
    * Logger instance.
    */
   _log: null,
 
   /**
@@ -399,17 +403,17 @@ TokenServerClient.prototype = {
                                                      k);
         error.cause = "malformed-response";
         error.response = response;
         cb(error, null);
         return;
       }
     }
 
-    this._log.debug("Successful token response: " + result.id);
+    this._log.debug("Successful token response");
     cb(null, {
       id:       result.id,
       key:      result.key,
       endpoint: result.api_endpoint,
       uid:      result.uid,
       duration: result.duration,
     });
   },
--- a/services/sync/modules/browserid_identity.js
+++ b/services/sync/modules/browserid_identity.js
@@ -180,17 +180,17 @@ this.BrowserIDManager.prototype = {
     // While this function returns a promise that resolves once we've started
     // the auth process, that process is complete when
     // this.whenReadyToAuthenticate.promise resolves.
     this._log.trace("initializeWithCurrentIdentity");
 
     // Reset the world before we do anything async.
     this.whenReadyToAuthenticate = Promise.defer();
     this.whenReadyToAuthenticate.promise.then(null, (err) => {
-      this._log.error("Could not authenticate: " + err);
+      this._log.error("Could not authenticate", err);
     });
 
     // initializeWithCurrentIdentity() can be called after the
     // identity module was first initialized, e.g., after the
     // user completes a force authentication, so we should make
     // sure all credentials are reset before proceeding.
     this.resetCredentials();
     this._authFailureReason = null;
@@ -239,21 +239,21 @@ this.BrowserIDManager.prototype = {
           Svc.Prefs.set("firstSync", "resetClient");
           Services.obs.notifyObservers(null, "weave:service:setup-complete", null);
           Weave.Utils.nextTick(Weave.Service.sync, Weave.Service);
         }
       }).then(null, err => {
         this._shouldHaveSyncKeyBundle = true; // but we probably don't have one...
         this.whenReadyToAuthenticate.reject(err);
         // report what failed...
-        this._log.error("Background fetch for key bundle failed: " + err);
+        this._log.error("Background fetch for key bundle failed", err);
       });
       // and we are done - the fetch continues on in the background...
     }).then(null, err => {
-      this._log.error("Processing logged in account: " + err);
+      this._log.error("Processing logged in account", err);
     });
   },
 
   _updateSignedInUser: function(userData) {
     // This object should only ever be used for a single user.  It is an
     // error to update the data if the user changes (but updates are still
     // necessary, as each call may add more attributes to the user).
     // We start with no user, so an initial update is always ok.
@@ -526,24 +526,23 @@ this.BrowserIDManager.prototype = {
     // We need kA and kB for things to work.  If we don't have them, just
     // return null for the token - sync calling unlockAndVerifyAuthState()
     // before actually syncing will setup the error states if necessary.
     if (!this._canFetchKeys()) {
       log.info("_fetchTokenForUser has no keys to use.");
       return null;
     }
 
-    log.info("Fetching assertion and token from: " + tokenServerURI);
-
     let maybeFetchKeys = () => {
       // This is called at login time and every time we need a new token - in
       // the latter case we already have kA and kB, so optimise that case.
       if (userData.kA && userData.kB) {
         return;
       }
+      log.info("Fetching new keys");
       return this._fxaService.getKeys().then(
         newUserData => {
           userData = newUserData;
           this._updateSignedInUser(userData); // throws if the user changed.
         }
       );
     }
 
@@ -560,17 +559,17 @@ this.BrowserIDManager.prototype = {
 
       let kBbytes = CommonUtils.hexToBytes(userData.kB);
       let headers = {"X-Client-State": this._computeXClientState(kBbytes)};
       client.getTokenFromBrowserIDAssertion(tokenServerURI, assertion, cb, headers);
       return deferred.promise;
     }
 
     let getAssertion = () => {
-      log.debug("Getting an assertion");
+      log.info("Getting an assertion from", tokenServerURI);
       let audience = Services.io.newURI(tokenServerURI, null, null).prePath;
       return fxa.getAssertion(audience);
     };
 
     // wait until the account email is verified and we know that
     // getAssertion() will return a real assertion (not null).
     return fxa.whenVerified(this._signedInUser)
       .then(() => maybeFetchKeys())
@@ -597,23 +596,23 @@ this.BrowserIDManager.prototype = {
         } else if (err.code === 401) {
           err = new AuthenticationError(err);
         }
 
         // TODO: write tests to make sure that different auth error cases are handled here
         // properly: auth error getting assertion, auth error getting token (invalid generation
         // and client-state error)
         if (err instanceof AuthenticationError) {
-          this._log.error("Authentication error in _fetchTokenForUser: " + err);
+          this._log.error("Authentication error in _fetchTokenForUser", err);
           // set it to the "fatal" LOGIN_FAILED_LOGIN_REJECTED reason.
           this._authFailureReason = LOGIN_FAILED_LOGIN_REJECTED;
         } else {
-          this._log.error("Non-authentication error in _fetchTokenForUser: "
-                          + (err.message || err));
-          // for now assume it is just a transient network related problem.
+          this._log.error("Non-authentication error in _fetchTokenForUser", err);
+          // for now assume it is just a transient network related problem
+          // (although sadly, it might also be a regular unhandled exception)
           this._authFailureReason = LOGIN_FAILED_NETWORK_ERROR;
         }
         // this._authFailureReason being set to be non-null in the above if clause
         // ensures we are in the correct currentAuthState, and
         // this._shouldHaveSyncKeyBundle being true ensures everything that cares knows
         // that there is no authentication dance still under way.
         this._shouldHaveSyncKeyBundle = true;
         Weave.Status.login = this._authFailureReason;
@@ -652,17 +651,17 @@ this.BrowserIDManager.prototype = {
    * of a RESTRequest or AsyncResponse object.
    */
   _getAuthenticationHeader: function(httpObject, method) {
     let cb = Async.makeSpinningCallback();
     this._ensureValidToken().then(cb, cb);
     try {
       cb.wait();
     } catch (ex) {
-      this._log.error("Failed to fetch a token for authentication: " + ex);
+      this._log.error("Failed to fetch a token for authentication", ex);
       return null;
     }
     if (!this._token) {
       return null;
     }
     let credentials = {algorithm: "sha256",
                        id: this._token.id,
                        key: this._token.key,
@@ -737,16 +736,17 @@ BrowserIDClusterManager.prototype = {
       );
     }.bind(this);
 
     let cb = Async.makeSpinningCallback();
     promiseClusterURL().then(function (clusterURL) {
       cb(null, clusterURL);
     }).then(
       null, err => {
+      log.info("Failed to fetch the cluster URL", err);
       // service.js's verifyLogin() method will attempt to fetch a cluster
       // URL when it sees a 401.  If it gets null, it treats it as a "real"
       // auth error and sets Status.login to LOGIN_FAILED_LOGIN_REJECTED, which
       // in turn causes a notification bar to appear informing the user they
       // need to re-authenticate.
       // On the other hand, if fetching the cluster URL fails with an exception,
       // verifyLogin() assumes it is a transient error, and thus doesn't show
       // the notification bar under the assumption the issue will resolve
--- a/services/sync/modules/policies.js
+++ b/services/sync/modules/policies.js
@@ -587,18 +587,23 @@ ErrorHandler.prototype = {
     let dapp = new Log.DumpAppender(formatter);
     dapp.level = Log.Level[Svc.Prefs.get("log.appender.dump")];
     root.addAppender(dapp);
 
     let fapp = this._logAppender = new Log.StorageStreamAppender(formatter);
     fapp.level = Log.Level[Svc.Prefs.get("log.appender.file.level")];
     root.addAppender(fapp);
 
-    // Arrange for the FxA logs to also go to our file.
-    Log.repository.getLogger("FirefoxAccounts").addAppender(fapp);
+    // Arrange for the FxA, Hawk and TokenServer logs to also go to our appenders.
+    for (let extra of ["FirefoxAccounts", "Hawk", "Common.TokenServerClient"]) {
+      let log = Log.repository.getLogger(extra);
+      for (let appender of [fapp, dapp, capp]) {
+        log.addAppender(appender);
+      }
+    }
   },
 
   observe: function observe(subject, topic, data) {
     this._log.trace("Handling " + topic);
     switch(topic) {
       case "weave:engine:sync:applied":
         if (subject.newFailed) {
           // An engine isn't able to apply one or more incoming records.