Bug 1006943 - non-sensitive FxA log info is included with sync logs. r=rnewman

services/common/hawkclient.js

@@ -155,9 +155,11 @@ this.HawkClient.prototype = {
       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.

services/fxaccounts/FxAccounts.jsm

@@ -99,7 +99,11 @@ AccountState.prototype = {
 
     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;
@@ -131,7 +135,11 @@ AccountState.prototype = {
 
 
   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");
@@ -143,6 +151,7 @@ AccountState.prototype = {
                                                  keyPair.serializedPublicKey,
                                                  CERT_LIFETIME).then(
       cert => {
+        log.debug("getCertificate got a new one: " + !!cert);
         this.cert = {
           cert: cert,
           validUntil: willBeValidUntil
@@ -353,7 +362,10 @@ FxAccountsInternal.prototype = {
    * 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);
   },
 
@@ -594,7 +606,9 @@ FxAccountsInternal.prototype = {
    },
 
   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.
@@ -618,13 +632,18 @@ FxAccountsInternal.prototype = {
       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
@@ -652,7 +671,10 @@ FxAccountsInternal.prototype = {
         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);
       }
     });
@@ -660,7 +682,10 @@ FxAccountsInternal.prototype = {
   },
 
   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),

services/fxaccounts/FxAccountsCommon.js

@@ -9,19 +9,40 @@ 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);
   }
@@ -29,6 +50,16 @@ XPCOMUtils.defineLazyGetter(this, 'log', function() {
   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";
 

services/sync/modules/policies.js

@@ -539,6 +539,9 @@ ErrorHandler.prototype = {
     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) {