1309571 - Syncing after fresh install only pulls down history items from a month ago and beyond

Status: RESOLVED FIXED

(Firefox for iOS :: Sync, defect, P1)

Description

[Stephan Leroux [:sleroux]]

Noticed this when testing this morning on master.

STR

1. Signed into my personal FxA account on a master build of Firefox (cef88e9a6d5cf50a2e5b7acd8ad4b598aa11e04a) containing lots of history items spanning a more than a month
2. Allowed sync to finished

Expected:

Recent history items should appear under the history tab (recent = last 24 hours or so)

Actual:

History items begin at 'last month'.

------

Its also pretty noticeable for the highlights returned on the Activity Stream panel because all my highlights are a month old.

Comment 1

[Stephan Leroux [:sleroux]]

After waiting a bit and pulling down to refresh on the history panel, all my history is gone... Performing a re-sync does not pull down anymore history items.

Comment 2

[Richard Newman [:rnewman]]

Take a look at the code -- are we downloading with sort=oldest and limit=5000? This might have changed with the batching stuff.

Comment 3

[Stephan Leroux [:sleroux]]

Force closing the app and relaunched made my history items re-appear.

Comment 4

[Aaron Train [:aaronmt]]

Simon are you able to reproduce this using a large Sync profile?

If so, I'd like to see this fixed on 6.0

Comment 5

[Stephan Leroux [:sleroux]]

Looks like the batch downloader is ordering by oldest-first and batching limit is set to 500 which is why we're seeing older records come in but not the most recent ones. One solution would be to download the most recent 500 first then batch download the others oldest -> latest.

Moving to 6.0/P2.

Comment 6

[Richard Newman [:rnewman]]

Android's current solution for this is to not limit downloads at all. On modern devices it's probably fine to grab all of the user's history.

We can maintain a limit by:

- arbitrarily picking a date and fetching batch-wise from that point.
- fetching IDs and using those to construct either an ID-based fetch or a timestamp-based fetch.
- fetching with a limit newest-to-oldest. This has the potential to miss records.

Comment 7

[Simon Basca [:SimonB]]

(In reply to Aaron Train [:aaronmt] from comment #4)
> Simon are you able to reproduce this using a large Sync profile?

Tested on devices running iOS 10.0.3 and iOS 9.x.

I am able to reproduce this with a large Sync profile. The only difference observed is that when swiping down to refresh the list will update with the correct history.

Comment 8

[Stephan Leroux [:sleroux]]

> Android's current solution for this is to not limit downloads at all. On modern devices it's probably fine to grab all of the user's history.

Would this mean we wouldn't be batching anymore and just one-shot download everything? It would be nice to keep a limit and batch since we already have some nice code for doing that but downloading in one go is easier.

One thing I'm a bit confused about is _why_ we're missing recent records. I know we're starting from oldest->newest, but since we're batching 500 at a time, shouldn't we eventually get the last set of records? Since it's missing records since roughly a month ago it seems that the batch client might have a one-off error and just not grabbing the latest/last batch.

From a UX perspective, it would make sense to download the latest batch first since those are the history items most visible from the panels. Technically, if we set an arbitrary date to start with (ex. records in the last month), how do we know we won't be missing records from the end of the lastest->newest batching and the latest months worth of records?

Lastly, do you see this change being made to the Downloader and affect bookmarks/logins/history or just something history specific?

Comment 9

[Richard Newman [:rnewman]]

(In reply to Stephan Leroux [:sleroux] from comment #8)

> Would this mean we wouldn't be batching anymore and just one-shot download
> everything? It would be nice to keep a limit and batch since we already have
> some nice code for doing that but downloading in one go is easier.

No, it still batches.

Grisha's current approach fetches:

  limit=500&sort=newest

(that is, the 500 most recent history items), then fetches:

  sort=oldest&batch=true&...

to fill in the backlog.

We just reintroduced 'older' in Bug 1314171 so we can avoid re-fetching those 500 most recent records.

If older+sort=oldest now gives us the ability to batch backwards, we could do that instead.



> One thing I'm a bit confused about is _why_ we're missing recent records. I
> know we're starting from oldest->newest, but since we're batching 500 at a
> time, shouldn't we eventually get the last set of records? Since it's
> missing records since roughly a month ago it seems that the batch client
> might have a one-off error and just not grabbing the latest/last batch.

That would be nice!

Comment 10

[Stephan Leroux [:sleroux]]

Attachment: Link to Github pull-request: https://github.com/mozilla-mobile/firefox-ios/pull/2231

First part of resolving this issue. I haven't been seeing the month old issue on the history panel so lets see if this does it.

Comment 11

[Richard Newman [:rnewman]]

I do *not* see recent history reappear if I swipe down in History, or re-sync multiple times. Reproduced in 5.3.

Interestingly, both devices end up on exactly the same last history item from September 26th.

Comment 12

[Richard Newman [:rnewman]]

Copying a note from the PR: that's definitely only the first part of a fix. My fresh installs that exhibit this bug don't find the missing history even by text search in the awesomebar, so it seems that the data is really not there.

Comment 13

[Richard Newman [:rnewman]]

Hypothesis:

- We call HistorySynchronizer.synchronizeLocalHistory().
- It calls go() with the greenLight.
- Several batches are downloaded and applied.
- The green light turns red, and we return Success to synchronizeLocalHistory.
- We move on and call the upload flow!

        return self.go(info, greenLight: greenLight, downloader: downloader, history: history)
           >>> { self.uploadOutgoingFromStorage(history, lastTimestamp: 0, withServer: historyClient) }
           >>> { return deferMaybe(.Completed) }

- The upload flow doesn't have a green light, and when it's done (unless it has no records to upload) it calls `setTimestamp` on the synchronizer, which sets `lastFetched` so that we skip our own records.

    func uploadRecords<T>(records: [Record<T>], lastTimestamp: Timestamp, storageClient: Sync15CollectionClient<T>, onUpload: (POSTResult, Timestamp?) -> DeferredTimestamp) -> DeferredTimestamp {
        if records.isEmpty {
            log.debug("No modified records to upload.")
            return deferMaybe(lastTimestamp)
        }

        let batch = storageClient.newBatch(ifUnmodifiedSince: (lastTimestamp == 0) ? nil : lastTimestamp, onCollectionUploaded: onUpload)
        return batch.addRecords(records)
            >>> batch.endBatch
            >>> {
                let timestamp = batch.ifUnmodifiedSince ?? lastTimestamp
                self.setTimestamp(timestamp)
                return deferMaybe(timestamp)
            }
    }



As such: if there's _any_ history to upload, we won't ever redownload more than we get in our first sync.

Solutions:

- Check the green light before calling `uploadOutgoingFromStorage`.
- Indeed, don't upload until we're done batching. That will require `go` to return a status flag rather than mere success or failure.

Comment 14

[Richard Newman [:rnewman]]

Stealing this for the follow-up PR.

Comment 15

[Richard Newman [:rnewman]]

The sweet, sweet logs of success.

[Debug] [Downloader.swift:157] downloadNextBatchWithLimit(_:infoModified:) > Fetching newer=0, offset=Optional("1474939836960:19").
[Debug] [StorageClient.swift:759] getSince(_:sort:limit:offset:) > Issuing GET with newer = 0.
[Debug] [StorageClient.swift:356] failFromResponse > Status code: 200.
[Debug] [Downloader.swift:175] handleSuccess > Handling success.
[Debug] [Downloader.swift:209] handleSuccess > Got success response with Optional(500) records.
[Debug] [HistorySynchronizer.swift:208] onBatchResult > Running another batch.
[Debug] [Downloader.swift:192] handleSuccess > Advancing baseTimestamp to 1474939843330 - 1
[Info] [HistorySynchronizer.swift:186] go(_:greenLight:downloader:history:) > Green light turned red. Stopping history download.
[Debug] [HistorySynchronizer.swift:266] synchronizeLocalHistory(_:withServer:info:greenLight:) > Didn't finish downloading history; not uploading yet.
[Info] [Profile.swift:1161] syncSeveral > Nothing left to sync
[Info] [Profile.swift:706] endSyncing > Ending all queued syncs.
[Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for clients: Completed
[Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for tabs: Completed
[Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for logins: Completed
[Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for bookmarks: Completed
[Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for history: Partial
[Debug] [SyncStatusResolver.swift:133] resolveResults() > Resolved sync display state: Good

And it's running subsequent batches correctly, too.

Comment 16

[Richard Newman [:rnewman]]

Attachment: Don't continue and upload unless download finished.

Comment 17

[Stephan Leroux [:sleroux]]

Comment on attachment 8810660 [details] [review]
Don't continue and upload unless download finished.

LGTM!

Comment 18

[Stephan Leroux [:sleroux]]

Landed fix for AS panel showing month old data:

master https://github.com/mozilla-mobile/firefox-ios/commit/c0e77cf4072253e1407cf2658c2b2900742051d4

Comment 19

[Richard Newman [:rnewman]]

Rebased and merged (4 commits):

https://github.com/mozilla-mobile/firefox-ios/commit/30cab8eb265cb86b5b3974316c0177c73fa01a90

Bug 1317543 covers speeding up the history panel in the face of this much data.

sleroux, does this need uplift anywhere?

Comment 20

[Stephan Leroux [:sleroux]]

Yup - lets uplift your patch for 6.0

Comment 21

[Stephan Leroux [:sleroux]]

v6.x 48b72f177def0470d4c5b8d9082a03e27a642030