1251057 - tokenserver errors don't log useful diagnostics

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

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

I've seen a few logs with entries like:

> 1456349228080	Common.TokenServerClient	DEBUG	Beginning BID assertion exchange: http://xxxx-host-deleted/storage/1.5/1
> 1456349230611	Sync.BrowserIDManager	ERROR	Non-authentication error in _fetchTokenForUser: TokenServerClientNetworkError({"error":{}}) (resource://gre/modules/services-common/tokenserverclient.js:39:36) JS Stack trace: [e-mail]:63:16 < [e-mail]:274:12 < [e-mail]:467:7 < [e-mail]:102:7 < makeSpinningCallback/[e-mail]:156:27 < [e-mail]:1009:7 < [e-mail]:148:21 < [e-mail]:103:16 < [e-mail]:77:16 < [e-mail]:1031:12 < sync/<@service.js:1283:14 < [e-mail]:77:16 < [e-mail]:1279:5
> 1456349230612	Sync.Status	DEBUG	Status.login: error.login.reason.network => error.login.reason.network

(note that xxx-host-deleted was a real self-hosted server name)

This log gives no information about why the call failed - we should try and arrange so there is (eg, an NS_ERROR_ code if the request wasn't created, a response code if it was, etc)

Comment 1

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

Attachment: 0001-Bug-1251057-enable-debug-logging-for-rest.js-request.patch

Hey Drew,

There are a couple of parts to this patch:

* The LogManager, which we created for readinglist to share logging logic with Sync, unconditionally sets all of its logs to the "ALL" level. This was done as a bit of a hack for readinglist, but is flawed in that depending on timing, the log levels may or may not be overridden later, and for some log where the level is *not* overwritten later, that log level may expose information we don't want in logs.

* rest.js has 2 objects (a request and response object) but they used completely different log names. I've fixed that to use a consistent name (dxr tells me there are no references to the name I changed). Worse, services-common.js has a preference to control the log level, but the code uses the wrong preference prefix, meaning those prefs had no effect - I fixed that too.

* rest.js didn't log the URL of the connection it was making until it got a response, which makes the log harder to read then they should be.

* Sync's log manager is configured to log the output from these rest.js loggers to the sync log sinks.

The end result is that we now end up with log lines like the following in sync logs:

> 1457417896798   Services.Common.RESTRequest     DEBUG   GET request to https://token.services.mozilla.com/1.0/sync/1.5
> 1457417896802   Services.Common.RESTRequest     DEBUG   GET https://token.services.mozilla.com/1.0/sync/1.5 failed: 2152398878 - NS_ERROR_UNKNOWN_HOST

etc.

Thanks!

Comment 2

[Pulsebot]

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

Comment 3

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/e36c64327f7a