Bug 1121325 - improve sync logging with FxA. r=rnewman/ckarlof
☠☠ backed out by 609564eb346d ☠ ☠
authorMark Hammond <mhammond@skippinet.com.au>
Fri, 23 Jan 2015 12:05:14 +1100
changeset 252366 a7e7d68537a87b3282cceab5d9ec5fe5fd3da5ea
parent 252365 dc96b4eac0750e3a7c3516166431b96cedc2742d
child 252367 316298f580fd1649e8a180abd8aa231d792a944e
push id4610
push userjlund@mozilla.com
push dateMon, 30 Mar 2015 18:32:55 +0000
treeherdermozilla-beta@4df54044d9ef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersrnewman, ckarlof
bugs1121325
milestone38.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 1121325 - improve sync logging with FxA. r=rnewman/ckarlof
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,25 @@ 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,
+      // This object is likely to be JSON.stringify'd, but neither Error()
+      // objects nor Components.Exception objects do the right thing there,
+      // but .toString() works in both cases.
+      error: 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 +196,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,17 @@ 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")];
+  this._log.level = Log.Level[Services.prefs.getCharPref(PREF_LOG_LEVEL)];
 }
 TokenServerClient.prototype = {
   /**
    * Logger instance.
    */
   _log: null,
 
   /**
@@ -399,17 +399,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.