886156 - Partial initialization of ProfileInformationCache

Status: VERIFIED FIXED

(Firefox Health Report Graveyard :: Client: Android, defect, P1)

Description

[Richard Newman [:rnewman]]

Noticed this on my own phone + Nightly. I assume it affects 23, which is running the same code.

I/GeckoApp(31122): Creating BrowserHealthRecorder.
D/GeckoHealthRec(31122): Initializing. Dispatcher is org.mozilla.gecko.util.EventDispatcher@41474438
D/GeckoHealthRec(31122): Initializing profile cache.
I/GeckoLogger(31122): fennec :: GeckoProfileInfo :: Restoring ProfileInformationCache from file.
D/GeckoHealthRec(31122): Successfully restored state. Initializing storage.
D/GeckoHealthRec(31122): Done initializing profile cache. Beginning storage init.
I/GeckoLogger(31122): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.appSessions to 4 (current 4)
I/GeckoLogger(31122): fennec :: HealthReportStorage :: Measurement org.mozilla.appSessions already at v4
I/GeckoLogger(31122): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.searches.counts to 4 (current 4)
I/GeckoLogger(31122): fennec :: HealthReportStorage :: Measurement org.mozilla.searches.counts already at v4

so we init fine... then disable an add-on:

D/GeckoHealthRec(31122): Add-on changed: {46551EC9-40F0-4e47-8E18-8E5CF550CFB8}
W/GeckoHealthRec(31122): Attempted to update add-on cache prior to full init.
W/GeckoHealthRec(31122): java.lang.IllegalStateException: Cannot incrementally update add-ons without first initializing.
W/GeckoHealthRec(31122): 	at org.mozilla.gecko.background.healthreport.ProfileInformationCache.updateJSONForAddon(ProfileInformationCache.java:224)
W/GeckoHealthRec(31122): 	at org.mozilla.gecko.health.BrowserHealthRecorder.onAddonChanged(BrowserHealthRecorder.java:306)
W/GeckoHealthRec(31122): 	at org.mozilla.gecko.health.BrowserHealthRecorder.handleMessage(BrowserHealthRecorder.java:596)

This implies that the PIC got written with a null add-ons field (perhaps because AddonsManager wasn't initialized when we first tried to fetch, which I think we've seen on desktop).

We then won't ever request a full add-ons dump, because we have a PIC loaded from a file, but we also can't record incremental changes.

We need to recover from that situation, because we won't be tracking add-ons until the client recovers, and we'll be dumping errors in the log when they change add-ons. They'll still be able to browse, of course.

I'd consider this for uplift to Beta, so requesting tracking.

Comment 1

[Richard Newman [:rnewman]]

https://github.com/mozilla-services/android-sync/pull/322

Comment 2

[Richard Newman [:rnewman]]

Attachment: Part 1: safety. v1

Comment 3

[Richard Newman [:rnewman]]

Attachment: Part 2: don't init with null addons. v1 (git)

Comment 4

[Nick Alexander :nalexander [he/him]]

Comment on attachment 766950 [details] [diff] [review]
Part 2: don't init with null addons. v1 (git)

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

Comments on github.

Comment 5

[Nick Alexander :nalexander [he/him]]

Comment on attachment 766949 [details] [diff] [review]
Part 1: safety. v1

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

LGTM.

Comment 6

[Richard Newman [:rnewman]]

   https://hg.mozilla.org/integration/mozilla-inbound/rev/0aaf9168dbf5
   https://hg.mozilla.org/integration/mozilla-inbound/rev/fab40457f8f7

Let's see if this works when it makes it to my phone…

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/0aaf9168dbf5
https://hg.mozilla.org/mozilla-central/rev/fab40457f8f7

Comment 8

[Lukas Blakk [:lsblakk] use ?needinfo]

We'll need to get this on Aurora & Beta now, post-merge.

Comment 9

[Richard Newman [:rnewman]]

Need to address Bug 888665 before this is uplifted.

Comment 10

[Richard Newman [:rnewman]]

But it works:

06-29 12:31:35.287 D/GeckoHealthRec(30922): Initializing. Dispatcher is org.mozilla.gecko.util.EventDispatcher@414884a0
06-29 12:31:35.287 D/GeckoHealthRec(30922): Initializing profile cache.
06-29 12:31:35.297 I/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Restoring ProfileInformationCache from file.
06-29 12:31:35.297 W/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Malformed ProfileInformationCache. Not restoring.
06-29 12:31:35.297 D/GeckoHealthRec(30922): Looking for /data/data/org.mozilla.fennec/files/mozilla/c2kcd0q0.default/times.json
06-29 12:31:35.297 D/GeckoHealthRec(30922): Using times.json for profile creation time.
06-29 12:31:35.297 D/GeckoHealthRec(30922): Incorporating environment: times.json profile creation = 1367517607467
06-29 12:31:35.297 D/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Setting profile creation time: 1367517607467
06-29 12:31:35.307 D/GeckoHealthRec(30922): Requested prefs.
06-29 12:31:35.307 D/GeckoSessInfo(30922): Recording start of session: 1372534295283

06-29 12:31:38.490 D/GeckoHealthRec(30922): Incorporating environment: toolkit.telemetry.enabledPreRelease = true
06-29 12:31:38.490 D/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Setting telemetry enabled: true
06-29 12:31:38.490 D/GeckoHealthRec(30922): Incorporating environment: extensions.blocklist.enabled = true
06-29 12:31:38.490 D/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Setting blocklist enabled: true
06-29 12:31:38.490 D/GeckoHealthRec(30922): Requesting all add-ons from Gecko.

06-29 12:31:39.251 D/GeckoHealthRec(30922): Got all add-ons.
06-29 12:31:39.251 I/GeckoHealthRec(30922): Persisting 4 add-ons.
06-29 12:31:39.251 D/GeckoLogger(30922): fennec :: GeckoProfileInfo :: Writing profile information.
06-29 12:31:39.251 D/GeckoHealthRec(30922): Done initializing profile cache. Beginning storage init.
06-29 12:31:39.271 I/GeckoLogger(30922): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.appSessions to 4 (current 4)
06-29 12:31:39.271 I/GeckoLogger(30922): fennec :: HealthReportStorage :: Measurement org.mozilla.appSessions already at v4
06-29 12:31:39.271 I/GeckoLogger(30922): fennec :: HealthReportStorage :: Initializing measurement org.mozilla.searches.counts to 4 (current 4)
06-29 12:31:39.271 I/GeckoLogger(30922): fennec :: HealthReportStorage :: Measurement org.mozilla.searches.counts already at v4
06-29 12:31:39.271 D/GeckoHealthRec(30922): Ensuring environment.
06-29 12:31:39.281 D/GeckoLogger(30922): fennec :: HealthReportStorage :: Inserted ID: 35 for hash V7HFlw4GDLi1/eP9Pt83OGOOoAk=
06-29 12:31:39.281 D/GeckoLogger(30922): fennec :: GeckoEnvBuilder :: Registering current environment: V7HFlw4GDLi1/eP9Pt83OGOOoAk= = 35
06-29 12:31:39.281 D/GeckoHealthRec(30922): Finishing init.
06-29 12:31:39.311 D/GeckoHealthRec(30922): Checking for orphan session.

Comment 11

[Richard Newman [:rnewman]]

And relaunches work as intended:

06-29 12:54:31.544 D/GeckoHealthRec( 2441): Initializing profile cache.
06-29 12:54:31.544 I/GeckoLogger( 2441): fennec :: GeckoProfileInfo :: Restoring ProfileInformationCache from file.
06-29 12:54:31.554 D/GeckoHealthRec( 2441): Successfully restored state. Initializing storage.
06-29 12:54:31.554 D/GeckoHealthRec( 2441): Done initializing profile cache. Beginning storage init.
06-29 12:54:31.554 D/GeckoSessInfo( 2441): Recording start of session: 1372535671541

Comment 12

[Richard Newman [:rnewman]]

Comment on attachment 766949 [details] [diff] [review]
Part 1: safety. v1

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Initial FHR landing.

User impact if declined: 
  Some users could have incorrect add-ons listed in their Firefox Health Report. This particular patch just improves some logging and ensures that exceptions don't bring down the house.

Testing completed (on m-c, etc.): 
  Manual testing, verified on m-c on my own affected device.

Risk to taking this patch (and alternatives if risky): 
  Very slim.

String or IDL/UUID changes made by this patch:
  None.

Comment 13

[Richard Newman [:rnewman]]

Comment on attachment 766950 [details] [diff] [review]
Part 2: don't init with null addons. v1 (git)

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Initial FHR landing.

User impact if declined: 
  Some users could have incorrect add-ons listed in their Firefox Health Report.

Testing completed (on m-c, etc.): 
  Manual testing, verified on m-c on my own affected device.

Risk to taking this patch (and alternatives if risky): 
  Should be none: this ensures that an invalid cache on disk is discarded. Note that Bug 888665 needs to land alongside this to avoid problems for affected users.

String or IDL/UUID changes made by this patch:
  None.

Comment 14

[bhavana bajaj [:bajaj]]

Comment on attachment 766949 [details] [diff] [review]
Part 1: safety. v1

Needed for FHR on Android before Release.

Adding qawanted,verifyme for QA to help with verification once this lands on branches.

Comment 15

[Richard Newman [:rnewman]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/d54c097dc7f6
https://hg.mozilla.org/releases/mozilla-aurora/rev/01af93611916
https://hg.mozilla.org/releases/mozilla-beta/rev/3dc64eab4159
https://hg.mozilla.org/releases/mozilla-beta/rev/243a2aaa3b65