Bug 1006943 - Non-sensitive FxA log info is included with sync logs. r=rnewman, a=lsblakk
authorMark Hammond <mhammond@skippinet.com.au>
Thu, 15 May 2014 12:00:59 +1000
changeset 192307 107fdcd0b146
parent 192306 54f0d0bea5e6
child 192308 09a9c1859b6b
push id3566
push userryanvm@gmail.com
push date2014-05-20 13:28 +0000
treeherdermozilla-beta@7d6a74b90622 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersrnewman, lsblakk
bugs1006943
milestone30.0
Bug 1006943 - Non-sensitive FxA log info is included with sync logs. r=rnewman, a=lsblakk
services/common/hawkclient.js
services/fxaccounts/FxAccounts.jsm
services/fxaccounts/FxAccountsCommon.js
services/sync/modules/policies.js
--- a/services/common/hawkclient.js
+++ b/services/common/hawkclient.js
@@ -150,19 +150,21 @@ this.HawkClient.prototype = {
     let deferred = Promise.defer();
     let uri = this.host + path;
     let self = this;
 
     function onComplete(error) {
       let restResponse = this.response;
       let status = restResponse.status;
 
-      log.debug("(Response) code: " + status +
-                " - Status text: " + restResponse.statusText,
-                " - Response text: " + restResponse.body);
+      log.debug("(Response) " + path + ": code: " + status +
+                " - Status text: " + restResponse.statusText);
+      if (logPII) {
+        log.debug("Response text: " + restResponse.body);
+      }
 
       // All responses may have backoff headers, which are a server-side safety
       // valve to allow slowing down clients without hurting performance.
       self._maybeNotifyBackoff(restResponse, "x-weave-backoff");
       self._maybeNotifyBackoff(restResponse, "x-backoff");
 
       if (error) {
         // When things really blow up, reconstruct an error object that follows
--- a/services/fxaccounts/FxAccounts.jsm
+++ b/services/fxaccounts/FxAccounts.jsm
@@ -95,17 +95,21 @@ AccountState.prototype = {
   getUserAccountData: function() {
     // Skip disk if user is cached.
     if (this.signedInUser) {
       return this.resolve(this.signedInUser.accountData);
     }
 
     return this.fxaInternal.signedInUserStorage.get().then(
       user => {
-        log.debug("getUserAccountData -> " + JSON.stringify(user));
+        if (logPII) {
+          // don't stringify unless it will be written. We should replace this
+          // check with param substitutions added in bug 966674
+          log.debug("getUserAccountData -> " + JSON.stringify(user));
+        }
         if (user && user.version == this.version) {
           log.debug("setting signed in user");
           this.signedInUser = user;
         }
         return this.resolve(user ? user.accountData : null);
       },
       err => {
         if (err instanceof OS.File.Error && err.becauseNoSuchFile) {
@@ -127,28 +131,33 @@ AccountState.prototype = {
       this.signedInUser = record;
       return this.fxaInternal.signedInUserStorage.set(record)
         .then(() => this.resolve(accountData));
     });
   },
 
 
   getCertificate: function(data, keyPair, mustBeValidUntil) {
-    log.debug("getCertificate" + JSON.stringify(this.signedInUser));
+    if (logPII) {
+      // don't stringify unless it will be written. We should replace this
+      // check with param substitutions added in bug 966674
+      log.debug("getCertificate" + JSON.stringify(this.signedInUser));
+    }
     // TODO: get the lifetime from the cert's .exp field
     if (this.cert && this.cert.validUntil > mustBeValidUntil) {
       log.debug(" getCertificate already had one");
       return this.resolve(this.cert.cert);
     }
     // else get our cert signed
     let willBeValidUntil = this.fxaInternal.now() + CERT_LIFETIME;
     return this.fxaInternal.getCertificateSigned(data.sessionToken,
                                                  keyPair.serializedPublicKey,
                                                  CERT_LIFETIME).then(
       cert => {
+        log.debug("getCertificate got a new one: " + !!cert);
         this.cert = {
           cert: cert,
           validUntil: willBeValidUntil
         };
         return cert;
       }
     ).then(result => this.resolve(result));
   },
@@ -308,17 +317,20 @@ FxAccountsInternal.prototype = {
   checkEmailStatus: function checkEmailStatus(sessionToken) {
     return this.fxAccountsClient.recoveryEmailStatus(sessionToken);
   },
 
   /**
    * Once the user's email is verified, we can request the keys
    */
   fetchKeys: function fetchKeys(keyFetchToken) {
-    log.debug("fetchKeys: " + keyFetchToken);
+    log.debug("fetchKeys: " + !!keyFetchToken);
+    if (logPII) {
+      log.debug("fetchKeys - the token is " + keyFetchToken);
+    }
     return this.fxAccountsClient.accountKeys(keyFetchToken);
   },
 
   // set() makes sure that polling is happening, if necessary.
   // get() does not wait for verification, and returns an object even if
   // unverified. The caller of get() must check .verified .
   // The "fxaccounts:onverified" event will fire only when the verified
   // state goes from false to true, so callers must register their observer
@@ -527,17 +539,19 @@ FxAccountsInternal.prototype = {
           err => currentState.whenKeysReadyDeferred.reject(err)
         );
       }
       return currentState.whenKeysReadyDeferred.promise;
     }).then(result => currentState.resolve(result));
    },
 
   fetchAndUnwrapKeys: function(keyFetchToken) {
-    log.debug("fetchAndUnwrapKeys: token: " + keyFetchToken);
+    if (logPII) {
+      log.debug("fetchAndUnwrapKeys: token: " + keyFetchToken);
+    }
     let currentState = this.currentAccountState;
     return Task.spawn(function* task() {
       // Sign out if we don't have a key fetch token.
       if (!keyFetchToken) {
         yield this.signOut();
         return null;
       }
 
@@ -550,23 +564,28 @@ FxAccountsInternal.prototype = {
         throw new Error("Signed in user changed while fetching keys!");
       }
 
       // Next statements must be synchronous until we setUserAccountData
       // so that we don't risk getting into a weird state.
       let kB_hex = CryptoUtils.xor(CommonUtils.hexToBytes(data.unwrapBKey),
                                    wrapKB);
 
-      log.debug("kB_hex: " + kB_hex);
+      if (logPII) {
+        log.debug("kB_hex: " + kB_hex);
+      }
       data.kA = CommonUtils.bytesAsHex(kA);
       data.kB = CommonUtils.bytesAsHex(kB_hex);
 
       delete data.keyFetchToken;
 
-      log.debug("Keys Obtained: kA=" + data.kA + ", kB=" + data.kB);
+      log.debug("Keys Obtained: kA=" + !!data.kA + ", kB=" + !!data.kB);
+      if (logPII) {
+        log.debug("Keys Obtained: kA=" + data.kA + ", kB=" + data.kB);
+      }
 
       yield currentState.setUserAccountData(data);
       // We are now ready for business. This should only be invoked once
       // per setSignedInUser(), regardless of whether we've rebooted since
       // setSignedInUser() was called.
       this.notifyObservers(ONVERIFIED_NOTIFICATION);
       return data;
     }.bind(this)).then(result => currentState.resolve(result));
@@ -584,25 +603,31 @@ FxAccountsInternal.prototype = {
     let currentState = this.currentAccountState;
     // "audience" should look like "http://123done.org".
     // The generated assertion will expire in two minutes.
     jwcrypto.generateAssertion(cert, keyPair, audience, options, (err, signed) => {
       if (err) {
         log.error("getAssertionFromCert: " + err);
         d.reject(err);
       } else {
-        log.debug("getAssertionFromCert returning signed: " + signed);
+        log.debug("getAssertionFromCert returning signed: " + !!signed);
+        if (logPII) {
+          log.debug("getAssertionFromCert returning signed: " + signed);
+        }
         d.resolve(signed);
       }
     });
     return d.promise.then(result => currentState.resolve(result));
   },
 
   getCertificateSigned: function(sessionToken, serializedPublicKey, lifetime) {
-    log.debug("getCertificateSigned: " + sessionToken + " " + serializedPublicKey);
+    log.debug("getCertificateSigned: " + !!sessionToken + " " + !!serializedPublicKey);
+    if (logPII) {
+      log.debug("getCertificateSigned: " + sessionToken + " " + serializedPublicKey);
+    }
     return this.fxAccountsClient.signCertificate(
       sessionToken,
       JSON.parse(serializedPublicKey),
       lifetime
     );
   },
 
   getUserAccountData: function() {
--- a/services/fxaccounts/FxAccountsCommon.js
+++ b/services/fxaccounts/FxAccountsCommon.js
@@ -4,36 +4,67 @@
 
 const { interfaces: Ci, utils: Cu } = Components;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
 Cu.import("resource://gre/modules/Log.jsm");
 
 // loglevel should be one of "Fatal", "Error", "Warn", "Info", "Config",
-// "Debug", "Trace" or "All". If none is specified, "Error" will be used by
-// default.
+// "Debug", "Trace" or "All". If none is specified, "Debug" will be used by
+// default.  Note "Debug" is usually appropriate so that when this log is
+// included in the Sync file logs we get verbose output.
 const PREF_LOG_LEVEL = "identity.fxaccounts.loglevel";
+// The level of messages that will be dumped to the console.  If not specified,
+// "Error" will be used.
+const PREF_LOG_LEVEL_DUMP = "identity.fxaccounts.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 = "identity.fxaccounts.log.sensitive";
 
 XPCOMUtils.defineLazyGetter(this, 'log', function() {
   let log = Log.repository.getLogger("FirefoxAccounts");
-  log.addAppender(new Log.DumpAppender());
-  log.level = Log.Level.Error;
+  // We set the log level to debug, but the default dump appender is set to
+  // the level reflected in the pref.  Other code that consumes FxA may then
+  // choose to add another appender at a different level.
+  log.level = Log.Level.Debug;
+  let appender = new Log.DumpAppender();
+  appender.level = Log.Level.Error;
+
+  log.addAppender(appender);
   try {
+    // The log itself.
     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;
+    log.level = Log.Level[level] || Log.Level.Debug;
+
+    // The appender.
+    level =
+      Services.prefs.getPrefType(PREF_LOG_LEVEL_DUMP) == Ci.nsIPrefBranch.PREF_STRING
+      && Services.prefs.getCharPref(PREF_LOG_LEVEL_DUMP);
+    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
+// else sensitive, such as credentials) should be logged.
+XPCOMUtils.defineLazyGetter(this, 'logPII', function() {
+  try {
+    return Services.prefs.getBoolPref(PREF_LOG_SENSITIVE_DETAILS);
+  } catch (_) {
+    return false;
+  }
+});
+
 this.DATA_FORMAT_VERSION = 1;
 this.DEFAULT_STORAGE_FILENAME = "signedInUser.json";
 
 // Token life times.
 // Having this parameter be short has limited security value and can cause
 // spurious authentication values if the client's clock is skewed and
 // we fail to adjust. See Bug 983256.
 this.ASSERTION_LIFETIME = 1000 * 3600 * 24 * 365 * 25; // 25 years
--- a/services/sync/modules/policies.js
+++ b/services/sync/modules/policies.js
@@ -532,16 +532,19 @@ 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);
   },
 
   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.