Closed Bug 886156 Opened 9 years ago Closed 9 years ago

Partial initialization of ProfileInformationCache

Categories

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

All
Android
defect

Tracking

(firefox23+ fixed, firefox24+ fixed)

VERIFIED FIXED
Firefox 25
Tracking Status
firefox23 + fixed
firefox24 + fixed

People

(Reporter: rnewman, Assigned: rnewman)

References

()

Details

(Keywords: qawanted, verifyme)

Attachments

(2 files)

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.
Attachment #766949 - Flags: review?(nalexander)
Attachment #766950 - Flags: review?(nalexander)
Flags: needinfo?(nalexander)
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.
Attachment #766950 - Flags: review?(nalexander)
Comment on attachment 766949 [details] [diff] [review]
Part 1: safety. v1

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

LGTM.
Attachment #766949 - Flags: review?(nalexander) → review+
   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…
Target Milestone: --- → Firefox 25
We'll need to get this on Aurora & Beta now, post-merge.
Blocks: 888665
Need to address Bug 888665 before this is uplifted.
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.
Status: RESOLVED → VERIFIED
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 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.
Attachment #766949 - Flags: approval-mozilla-beta?
Attachment #766949 - Flags: approval-mozilla-aurora?
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.
Attachment #766950 - Flags: review+
Attachment #766950 - Flags: approval-mozilla-beta?
Attachment #766950 - Flags: approval-mozilla-aurora?
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.
Attachment #766949 - Flags: approval-mozilla-beta?
Attachment #766949 - Flags: approval-mozilla-beta+
Attachment #766949 - Flags: approval-mozilla-aurora?
Attachment #766949 - Flags: approval-mozilla-aurora+
Attachment #766950 - Flags: approval-mozilla-beta?
Attachment #766950 - Flags: approval-mozilla-beta+
Attachment #766950 - Flags: approval-mozilla-aurora?
Attachment #766950 - Flags: approval-mozilla-aurora+
Product: Firefox Health Report → Firefox Health Report Graveyard
You need to log in before you can comment on or make changes to this bug.