1121325 - Better FxA logging in Sync logs

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0002-Bug-XXXXXX-improve-sync-logging-with-FxA.patch

In looking at logs in bug 1116689, I found them less than helpful for some error states.  Eg:

> 1420656139890	FirefoxAccounts	DEBUG	enter getAssertion()
> 1420656139901	FirefoxAccounts	DEBUG	got keyPair
> 1420656139901	FirefoxAccounts	DEBUG	getCertificateSigned: true true
> 1420656139909	Sync.RESTResponse	DEBUG	Caught exception fetching HTTP status code:[Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE)...
> <snip a few repeated lines>
> 1420656139915	FirefoxAccounts	ERROR	error POSTing /certificate/sign: {"error":{},"message":null,"code":null,"errno":null}
> 1420656139915	FirefoxAccounts	ERROR	HAWK.signCertificate error: {"error":{},"message":null,"code":null,"errno":null}

Which is a completely opaque error signing a certificate.

The following patch does the following:

* Arranges for hawk and tokenserverclient logs to appear in sync logs.

* Changes the error object thrown by hawk so when it is serialized by browserid_identity it has more details (specifically, it calls error.toString() instead of returning the object directly, as error objects don't JSON.stringify to anything useful.

* Uses a recently added Log.jsm facility to get better error information - eg:

-          this._log.error("Authentication error in _fetchTokenForUser: " + err);
+          this._log.error("Authentication error in _fetchTokenForUser", err);

  Will cause a better representation of the error, including a stack, to appear in the logs.

* A couple of other minor fixes (eg, don't log the token's |id| as it doesn't seem to have diagnostic value and might be sensitive, don't log "Fetching assertion and token.." when we aren't necessarily doing that)

With this patch applied and simulating an error (ie, setting a breakpoint as hawk is making a request and disabling my network adaptor) I see:

> 1421209588991	FirefoxAccounts	DEBUG	fetchKeys: true
> 1421209589006	FirefoxAccounts	DEBUG	already verified
> 1421209589006	Sync.BrowserIDManager	INFO	Fetching new keys
> 1421209631537	Hawk	WARN	hawk request error: [Exception... "NS_ERROR_UNKNOWN_HOST"  nsresult: "0x804b001e (NS_ERROR_UNKNOWN_HOST)"  location: "JS frame :: resource://services-common/rest.js :: ...
> 1421209631541	Sync.RESTResponse	DEBUG	Caught exception fetching HTTP status code:[Exception... 
> <snip repeated lines>
> 1421209631542	Hawk	DEBUG	(Response) /account/keys: code: null - Status text: null
> 1421209632536	FirefoxAccounts	ERROR	error GETing /account/keys: {"error":"[Exception... \"NS_ERROR_UNKNOWN_HOST\"  nsresult: \"0x804b001e (NS_ERROR_UNKNOWN_HOST)\"  location: ...
> 1421209656874	Sync.BrowserIDManager	ERROR	Non-authentication error in _fetchTokenForUser: {"error":"[Exception... \"NS_ERROR_UNKNOWN_HOST\"  nsresult: \"0x804b001e ...
> 1421209656875	Sync.Status	DEBUG	Status.login: error.login.reason.account => error.login.reason.network

which is much more useful.

Comment 1

[Chris Karlof [:ckarlof]]

Comment on attachment 8548646 [details] [diff] [review]
0002-Bug-XXXXXX-improve-sync-logging-with-FxA.patch

Review of attachment 8548646 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM, thanks Mark!

Comment 2

[Marco Mucci [:MarcoM]]

Hi Mark, can you provide a point value.

Comment 3

[Richard Newman [:rnewman]]

Comment on attachment 8548646 [details] [diff] [review]
0002-Bug-XXXXXX-improve-sync-logging-with-FxA.patch

Review of attachment 8548646 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry for the delayed review, Mark; ISTR you were on PTO, so I put it off!

For extra points, take this opportunity to fix pref names.

::: services/common/hawkclient.js
@@ +58,4 @@
>    try {
>      let level =
>        Services.prefs.getPrefType(PREF_LOG_LEVEL) == Ci.nsIPrefBranch.PREF_STRING
>        && Services.prefs.getCharPref(PREF_LOG_LEVEL);

The pref fetched here should be named:

  services.common.hawk.log.appender.dump

I think.

::: services/common/services-common.js
@@ +8,5 @@
>  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", "Debug");

The pattern Sync and this file use is:

  services.dir.log.logger.some.module = Debug
  services.dir.log.appender.dump = Debug

so I think this pref should actually be

  services.common.log.logger.tokenserverclient = Debug

Now might be a decent time to change it, 'cos you're changing the default value.

Comment 4

[Mark Hammond [:markh] [:mhammond]]

https://hg.mozilla.org/integration/fx-team/rev/a7e7d68537a8

Comment 5

[Mark Hammond [:markh] [:mhammond]]

backed out in https://hg.mozilla.org/integration/fx-team/rev/609564eb346d

Comment 6

[Mark Hammond [:markh] [:mhammond]]

https://hg.mozilla.org/integration/fx-team/rev/378edc6d1ff9 - try at https://treeherder.mozilla.org/#/jobs?repo=try&revision=366c12f4995e

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/378edc6d1ff9

Comment 8

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8548646 [details] [diff] [review]
0002-Bug-XXXXXX-improve-sync-logging-with-FxA.patch

Approval Request Comment
[Feature/regressing bug #]: N/A
[User impact if declined]: Users with Sync issues and who upload logs might not provide enough diagnostic information to solve the problem.  This is particularly desired for the Sync Migration project which will start on 37.
[Describe test coverage new/current, TreeHerder]: All tests pass
[Risks and why]: Low risk, limited to logging.
[String/UUID change made/needed]: None

Comment 9

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8548646 [details] [diff] [review]
0002-Bug-XXXXXX-improve-sync-logging-with-FxA.patch

I agree that we'll want the ability to debug issues related to sync. It is early enough in the cycle to get this type of change. All changes in the patch are logging related. Aurora+

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/5598d7df1010