1405566 - Uptick of failures in Firefox 57: history fails with "date <some_date> cannot be a future date"

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

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

Around 35% of failures for this engine in 57 are failing with the above error. 57/58 has the lowest general success rate for this engine (99.6% vs the 99.9 we'd expect)

Bug 1377944 seems the likely candidate, but I haven't verified that it can be explained by the patch there.

I suspect that either "this" device has a clock that's behind, or the "other" device has a clock that's forward. It's likely to be easy to fix (ie, we'd just use now()), so we should ASAP and request uplift.

https://nbviewer.jupyter.org/gist/mhammond/649a6f6c5606cff0e0d9d8a4f0b9e9a1/Success-Failure-Error%20rates%20per%20engine%2C%20by%20version.ipynb

Comment 1

[Lina Butler (ex-Mozilla)]

Attachment: Bug 1405566 - Clamp future and far past synced history visit dates.

Review commit: https://reviewboard.mozilla.org/r/186542/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/186542/

Comment 2

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

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

https://reviewboard.mozilla.org/r/186542/#review191628

any chance of a test? ;)

Comment 3

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/186542/diff/1-2/

Comment 4

[Lina Butler (ex-Mozilla)]

[Tracking Requested - why for this release]: This is a visible regression in history sync, per Mark's numbers in comment 0. Users are very likely to hit this in the wild: visits synced from another device with a fast clock, even by a few seconds, will cause the entire history sync to fail.

Comment 5

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

cc Chris as he asked to be informed up 57 uplift requests.

For additional context on Kit's tracking request: The patch here is small and low risk. However, only 0.03% of syncs appear to be hitting this issue, so it's not widespread. But 0.03% more users having broken history sync in 57 is still bad.

To help release management make a decision here: using the metric of "should this be in a dot release if found at release time", I'd say "we'd probably ask for uplift if an existing dot release was being made, but wouldn't ask for one purely for this issue."

Comment 6

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

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

https://reviewboard.mozilla.org/r/186542/#review191660

::: services/sync/modules/engines/history.js:279
(Diff revision 2)
>                         visit.type + "; ignoring.");
>          continue;
>        }
>  
>        // Dates need to be integers.
> -      visit.date = Math.round(visit.date);
> +      let visitDateAsPRTime = Math.round(visit.date);

it seems this will not do the "right thing" in this case, but I believe it's actually impossible to do the right thing in this case :/ However, this will do the "closest possible thing to the right thing", so we have that going for us, which is nice...

Comment 7

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/186542/diff/2-3/

Comment 8

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

https://reviewboard.mozilla.org/r/186542/#review191660

> it seems this will not do the "right thing" in this case, but I believe it's actually impossible to do the right thing in this case :/ However, this will do the "closest possible thing to the right thing", so we have that going for us, which is nice...

Following up on our IRC conversation, I think you're completely correct. The intent is to avoid inserting duplicate visits for the same date, so we should use the clamped date for lookup in `curVisits`, even though it's impossible or extremely unlikely to match. However, we should *also* add clamped visits to `curVisits`, because an incoming record with multiple out-of-bounds visit dates and the same type will clamp to the same date. I added that, and extended the test to cover this.

Comment 9

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

https://reviewboard.mozilla.org/r/186542/#review191694

::: services/sync/modules/engines/history.js:293
(Diff revision 3)
>          continue;
>        }
>  
> -      visit.date = PlacesUtils.toDate(visit.date);
> +      // Note the visit key, so that we don't add duplicate visits with
> +      // clamped timestamps.
> +      curVisits.push(visitKey);

`curVisits` would be more efficient as a set, but I'd like to keep this patch small, and maybe change this in a trivial follow-up.

Comment 10

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

It also occurred to me that we should clamp dates older than `EARLIEST_BOOKMARK_TIMESTAMP` to `EARLIEST_BOOKMARK_TIMESTAMP`, not the current date. What I had before was not a clamp. :-) Mark, would you mind taking another look, please?

Comment 11

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

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

https://reviewboard.mozilla.org/r/186542/#review191700

Great, thanks!

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/85b73d4c4c9c
Clamp future and far past synced history visit dates. r=markh

Comment 13

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/85b73d4c4c9c

Comment 14

[Marcia Knous [:marcia]]

57+ based on Comment 4. This is the type of bug that could bite us post release.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Please request Beta approval on this when you get a chance.

Comment 16

[Lina Butler (ex-Mozilla)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

I hoped to have Sync ping data before requesting approval, but filing the request now so that we don't miss the train.

Approval Request Comment
[Feature/Bug causing the regression]: Bug 1377944.
[User impact if declined]: Users won't see their synced history from other devices if they're syncing history, and the clocks on their other devices are faster.
[Is this code covered by automated tests?]: Yes.
[Has the fix been verified in Nightly?]: Yes. We'll keep an eye on the Sync telemetry ping data this week.
[Needs manual test from QE? If yes, steps to reproduce]: No.
[List of other uplifts needed for the feature/fix]: None.
[Is the change risky?]: No.
[Why is the change risky/not risky?]: The patch adds an extra function call to clamp history visit timestamps, and fixes how we detect duplicate visits. We're not sure it fixes the issue completely yet, but it's an improvement over an outright failure.
[String changes made/needed]: None.

Comment 17

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8915350 [details]
Bug 1405566 - Clamp future and far past synced history visit dates.

Severe recent regression, beta57+

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/dcaaba0bd014

Comment 19

[Andrei Vaida [:avaida]]

(In reply to Kit Cambridge (he/him) [:kitcambridge] (UTC-7) from comment #16)
> [Is this code covered by automated tests?]: Yes.
> [Has the fix been verified in Nightly?]: Yes. We'll keep an eye on the Sync
> telemetry ping data this week.
> [Needs manual test from QE? If yes, steps to reproduce]: No.

Setting qe-verify- based on Kit's assessment on manual testing needs and the fact that this fix has automated coverage.

Comment 20

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

Telemetry implies this patch didn't fix the issue - this error remains the top failure for 57 and 58

Comment 21

[Thom Chiovoloni [:tcsc] (ex-moco)]

Out of idle curiosity, I ran the following query in redash last night: https://sql.telemetry.mozilla.org/queries/48779/source.

This lists the history errors for buildsIds after this patch landed (in 58). It doesn't seem to have a single instance of the reported error, and so, well, I'm not convinced that it's actually not fixed (In fact, I'm fairly convinced of the opposite), I think we just need to (annoyingly) be a bit more careful about how we determine these things.

Comment 22

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

Thanks Thom - I can also confirm with adhoc analysis that later build IDs don't report this error - I don't quite understand why it is still being reported in the larger analysis when most others go away quickly after the fix landing, but I agree this is actually fixed - thanks!