Bug 1121325 - improve sync logging with FxA. r=rnewman/ckarlof

services/common/hawkclient.js

@@ -37,24 +37,32 @@ 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);
   }
@@ -99,12 +107,15 @@ this.HawkClient.prototype = {
    * @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
@@ -190,6 +201,12 @@ this.HawkClient.prototype = {
     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;
 

services/common/rest.js

@@ -458,6 +458,7 @@ RESTRequest.prototype = {
     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;

services/common/services-common.js

@@ -9,4 +9,4 @@ 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");

services/common/tokenserverclient.js

@@ -13,13 +13,13 @@ this.EXPORTED_SYMBOLS = [
 
 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.
@@ -140,7 +140,7 @@ TokenServerClientServerError.prototype._toStringFields = function() {
  */
 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 = {
   /**
@@ -404,7 +404,7 @@ TokenServerClient.prototype = {
       }
     }
 
-    this._log.debug("Successful token response: " + result.id);
+    this._log.debug("Successful token response");
     cb(null, {
       id:       result.id,
       key:      result.key,

services/sync/modules/browserid_identity.js

@@ -185,7 +185,7 @@ this.BrowserIDManager.prototype = {
     // 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
@@ -244,11 +244,11 @@ this.BrowserIDManager.prototype = {
         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);
     });
   },
 
@@ -531,14 +531,13 @@ this.BrowserIDManager.prototype = {
       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;
@@ -565,7 +564,7 @@ this.BrowserIDManager.prototype = {
     }
 
     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);
     };
@@ -602,13 +601,13 @@ this.BrowserIDManager.prototype = {
         // 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
@@ -657,7 +656,7 @@ this.BrowserIDManager.prototype = {
     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) {
@@ -742,6 +741,7 @@ BrowserIDClusterManager.prototype = {
       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

services/sync/modules/policies.js

@@ -592,8 +592,13 @@ ErrorHandler.prototype = {
     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) {