881991 - Duplicate aborted sessions being inserted

Status: RESOLVED FIXED

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Gregory Szorc [:gps]]

I was chatting with Brendan about FHR oddities today and we were looking at some example payloads. One of the things I noticed is that it appears we're inserting duplicate aborted sessions into the database.

We have code to detect previously-inserted sessions. I suspect an off-by-one bug.

Comment 1

[Gregory Szorc [:gps]]

I reckon the < should be <= in the following:

https://hg.mozilla.org/mozilla-central/file/default/services/healthreport/providers.jsm#l614

The test also appears to be a bit wonky.

Comment 2

[Gregory Szorc [:gps]]

Attachment: Properly detect already inserted sessions

This patch boils down to converting a < to <= and fixing the test to use
day.get("main").length instead of day.size. While I was here, I also
refactored the test slightly to make it more readable. That accounts for
the bulk of the diff. If you want me to remove the tidying, I
understand.

I will request this patch be uplifted as high as I can get it, as it
undermines our ability to track sessions properly.

Comment 3

[Gregory Szorc [:gps]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4790e0169cfe

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 761570 [details] [diff] [review]
Properly detect already inserted sessions

[Approval Request Comment]
Bug caused by (feature/regressing bug #): FHR
User impact if declined: FHR data for sessions won't be properly recorded if Firefox isn't shut down properly. This will prevent Mozilla from knowing what percentage of sessions aren't shut down properly.
Testing completed (on m-c, etc.): Just landed. It should probably bake for a few days.
Risk to taking this patch (and alternatives if risky): Low risk. It is a pretty obvious off-by-1 bug.
String or IDL/UUID changes made by this patch: None

Comment 5

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/4790e0169cfe

Comment 6

[Alex Keybl [:akeybl]]

Comment on attachment 761570 [details] [diff] [review]
Properly detect already inserted sessions

Too late for 22 (we're on our final beta)

Comment 7

[Gregory Szorc [:gps]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/25490ef0aa86

Comment 8

[u279076]

Gregory, is there anything you need from QA here?

Comment 9

[Gregory Szorc [:gps]]

(In reply to Anthony Hughes, Mozilla QA (:ashughes) from comment #8)
> Gregory, is there anything you need from QA here?

The existing test coverage should be largely good. Although, the test was faulty before, so maybe I'm over valuing them.

A spot check that sessions are still recorded properly in FHR would be nice. The real verification will be to comb through a sample of payloads from the wild and verify the issue goes away.

Comment 10

[John Jensen]

(In reply to Alex Keybl [:akeybl] from comment #6)
> Comment on attachment 761570 [details] [diff] [review]
> Properly detect already inserted sessions
> 
> Too late for 22 (we're on our final beta)

Alex -- there is absolutely no chance of another beta?

Comment 11

[Ioana (away)]

Gregory, is there a place where the data in the health report is explained? I'm looking at session data (org.mozilla.appSessions.current and the multiple org.mozilla.appSessions.previous entries) trying to verify this bug and I have no idea what the data there means.

Comment 12

[Gregory Szorc [:gps]]

http://docs.services.mozilla.com/healthreport/index.html

If those docs aren't good enough, please file a new bug to update the docs!

Comment 13

[Paul Silaghi, QA [:pauly]]

I tested this on FF 23b1 Win 7 x64.
If the FF is closed normally, the session seems to be recorded properly.
I might not understand the issue correctly, but killing the FF process with "activeTicks": 23, "totalTime": 139 added in "org.mozilla.appSessions.previous":
"abortedActiveTicks": 7, "abortedTotalTime": 31
Any thoughts?

Comment 14

[Gregory Szorc [:gps]]

(In reply to Paul Silaghi [QA] from comment #13)
> I tested this on FF 23b1 Win 7 x64.
> If the FF is closed normally, the session seems to be recorded properly.
> I might not understand the issue correctly, but killing the FF process with
> "activeTicks": 23, "totalTime": 139 added in
> "org.mozilla.appSessions.previous":
> "abortedActiveTicks": 7, "abortedTotalTime": 31
> Any thoughts?

This is expected behavior. On startup, FHR looks at the "current" session (which at startup is really the previous session). It looks for a flag set during shutdown that basically is the equivalent of "did the session shut down correctly." If the session shut down correctly, it marks it as clean. If not, it's marked as aborted. The previous session is then added to a new preference as a serialized JSON object and the current session's preferences are wiped away.

Comment 15

[Paul Silaghi, QA [:pauly]]

(In reply to Gregory Szorc [:gps] from comment #14)
> If not, it's marked as aborted. The previous session is then added to a new
> preference as a serialized JSON object and the current session's preferences
> are wiped away.
Ok, but I'm talking about the differences between values:
current session: "activeTicks": 23, "totalTime": 139
is recorded as aborted with: "abortedActiveTicks": 7, "abortedTotalTime": 31
Shouldn't be the same?

Comment 16

[u279076]

Gregory, can you please address comment 15?

Comment 17

[Gregory Szorc [:gps]]

Changes to preferences aren't persisted to disk immediately. Instead, preferences are flushed to disk periodically. If the process crashes, increments to the tick count and total time count preferences may be lost and appear reverted to an earlier state.

This is one reason we want to switch how session data is recorded (bug 841561).

Comment 18

[u279076]

Thanks Gregory, I guess that means we can safely mark this verified fixed. I'm not sure there's much more we can do in terms of QA. Please add switch the status flag back to fixed and add the verifyme keyword if you think of something.