Bug 1121325 - improve sync logging with FxA. r=rnewman/ckarlof
--- 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.
@@ -527,24 +527,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()) {
return Promise.resolve(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.
}
);
}
@@ -561,17 +560,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())
@@ -598,23 +597,23 @@ this.BrowserIDManager.prototype = {
} else if (err.code && 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;
@@ -656,17 +655,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,
@@ -752,16 +751,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.