1006943 - Ensure FxA logs are included with the sync logs.

Status: VERIFIED FIXED

(Firefox :: Sync, defect)

Description

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

Sync logs don't include FxA logs - see also bug 1006360

Comment 1

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

Attachment: 0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

There are 3 main parts to this patch:

* In FxAccountsCommon we default the log itself to "Debug", but set the level of the DumpAppender to "Error" - this means that by default only errors are written to the console, but more detailed information is kept for the log itself.

* In Sync's log setup, we add the FxA log to the StorageStreamAppender, which is where the log files come from.  This means that by default, the sync log files will include Debug level FxA logs.

* Tweak some of the log levels in hawk and FxA so that sensitive information is emitted at level Trace.  In some cases we log at *both* Debug and Trace levels - debug logs a boolean to indicate if the data exists, and trace logs the data itself.  The end result is that by default, sensitive information like the keys aren't logged by default (although they can still be logged by tweaking the prefs).

With this patch, you can expect to see stuff like the following in the sync log files:

1399858128404	Sync.Service	INFO	collection keys reports that a key update is needed.
1399858128405	Sync.BrowserIDManager	INFO	Fetching assertion and token from: https://token.services.mozilla.com/1.0/sync/1.5
1399858128405	FirefoxAccounts	DEBUG	already verified
1399858128406	Sync.BrowserIDManager	DEBUG	Getting an assertion
1399858128406	FirefoxAccounts	DEBUG	enter getAssertion()
1399858128407	FirefoxAccounts	DEBUG	getKeyPair: already have a keyPair
1399858128408	FirefoxAccounts	DEBUG	getCertificate already had one
1399858128408	FirefoxAccounts	DEBUG	getAssertionFromCert
1399858128410	FirefoxAccounts	DEBUG	getAssertionFromCert returning signed: true

(Note the last line - we just log ": true" to indicate we got an assertion, but do not log the assertion value - prefs would need to be tweaked so set the level to Trace to see them)

Comment 2

[Chris Karlof [:ckarlof]]

Comment on attachment 8420724 [details] [diff] [review]
0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

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

Overall looks good, but I'm not qualified to comment on the details of the Fx-specific log infrastructure changes.

Comment 3

[Richard Newman [:rnewman]]

Comment on attachment 8420724 [details] [diff] [review]
0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

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

From what I remember of Log4Moz, this seems correct to me. If it works, great! :)

::: services/fxaccounts/FxAccounts.jsm
@@ +98,5 @@
>      }
>  
>      return this.fxaInternal.signedInUserStorage.get().then(
>        user => {
> +        log.trace("getUserAccountData -> " + JSON.stringify(user));

It might be worth wrapping some of these in guards, perhaps naming the variable something like 'debug' or 'pii'. Doing a check prior to stringifying saves the work in building the string.

Comment 4

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

Attachment: 0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

FxAccountsCommon now exports a (lazy) boolean 'logSensitiveDetails' which is based on a non-default pref, and all the code I previously moved to use .trace() now sticks with .debug, but only when that bool is true.

Happy to change the name of the bool if a better one can be thought of :) (although I don't really like 'pii' as (a) IMO it's not obvious to a casual reader what it stands for and (b) some of the stuff we decline to log may not be identifiable, but still sensitive.)

Comment 5

[Richard Newman [:rnewman]]

Comment on attachment 8422186 [details] [diff] [review]
0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

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

We've used "PII" in the past (would be "logPII" in this case). Might be briefer, might just be more abstruse. Up to you.

Comment 6

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

Thanks!  Went with logPII

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

Comment 7

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/95cc116fac5a

Comment 8

[Bogdan Maris, Desktop Test Engineering]

Using a old Nightly from 2014-05-14 no FirefoxAccounts logs are seen, using latest Nightly on Windows 7 64bit, Ubuntu 12.04 32bit and Mac OS X 10.9.2 I can see FirefoxAccounts logs such as:

1400248780029	FirefoxAccounts	DEBUG	checkEmailStatus -> {"email":"[e-mail]","verified":true}
1400248780037	Sync.BrowserIDManager	INFO	Starting fetch for key bundle.
1400248780037	FirefoxAccounts	DEBUG	fetchKeys: true
1400248780040	Sync.BrowserIDManager	INFO	Fetching assertion and token from: https://token.services.mozilla.com/1.0/sync/1.5
1400248780040	FirefoxAccounts	DEBUG	already verified
1400248780274	FirefoxAccounts	DEBUG	(Response) /account/keys: code: 200 - Status text: OK
1400248780274	FirefoxAccounts	DEBUG	Clock offset vs https://api.accounts.firefox.com/v1: -1274
1400248780275	FirefoxAccounts	DEBUG	Keys Obtained: kA=true, kB=true
1400248780280	FirefoxAccounts	DEBUG	Notifying observers of fxaccounts:onverified
1400248780283	Sync.BrowserIDManager	DEBUG	Getting an assertion
1400248780283	FirefoxAccounts	DEBUG	enter getAssertion()
1400248780299	FirefoxAccounts	DEBUG	got keyPair
1400248780331	FirefoxAccounts	DEBUG	getCertificateSigned: true true
1400248780571	FirefoxAccounts	DEBUG	(Response) /certificate/sign: code: 200 - Status text: OK
1400248780571	FirefoxAccounts	DEBUG	Clock offset vs https://api.accounts.firefox.com/v1: -571
1400248780572	FirefoxAccounts	DEBUG	getCertificate got a new one: true
1400248780572	FirefoxAccounts	DEBUG	getAssertionFromCert
1400248780573	FirefoxAccounts	DEBUG	getAssertionFromCert returning signed: true

Comment 9

[Lukas Blakk [:lsblakk] use ?needinfo]

Please nominate for branch uplift asap.

Comment 10

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

Comment on attachment 8422186 [details] [diff] [review]
0001-Bug-1006943-non-sensitive-FxA-log-info-is-included-w.patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): FxA Sync
User impact if declined: Developers will have a harder time diagnosing sync logs.
Testing completed (on m-c, etc.): Landed on MC
Risk to taking this patch (and alternatives if risky): Low
String or IDL/UUID changes made by this patch: None

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/0150eb887ea0
https://hg.mozilla.org/releases/mozilla-beta/rev/107fdcd0b146

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/107fdcd0b146