1339383 - Recent history not downloaded

Status: NEW

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

Description

[Catalin Suciu [:csuciu]]

master 73e48fa2f8

1. Sync history from desktop to device
2. On device, go to the history tab 

Result: The recent history was not downloaded. Only the 'Last Month' history is listed.

---------------------------
 
2017-02-14 11:18:12.703 [Debug] [HistorySynchronizer.swift:224] onBatchResult > Running another batch.
2017-02-14 11:18:36.164 [Debug] [Downloader.swift:192] handleSuccess > Advancing baseTimestamp to 1484890812900 - 1
2017-02-14 11:18:36.173 [Info] [HistorySynchronizer.swift:202] go(_:greenLight:downloader:history:) > Green light turned red. Stopping history download.
2017-02-14 11:18:36.174 [Debug] [HistorySynchronizer.swift:282] synchronizeLocalHistory(_:withServer:info:greenLight:) > Didn't finish downloading history; not uploading yet.
2017-02-14 11:18:36.174 [Info] [Profile.swift:684] endSyncing > Ending all queued syncs.
2017-02-14 11:18:36.199 [Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for clients: completed
2017-02-14 11:18:36.200 [Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for tabs: completed
2017-02-14 11:18:36.200 [Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for logins: completed
2017-02-14 11:18:36.200 [Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for bookmarks: completed
2017-02-14 11:18:36.200 [Debug] [SyncStatusResolver.swift:73] resolveResults() > Sync status for history: partial
2017-02-14 11:18:36.201 [Debug] [SyncStatusResolver.swift:133] resolveResults() > Resolved sync display state: good
2017-02-14 11:18:36.607 [Debug] [Profile.swift:742] reportEndSyncingStatus(_:engineResults:) > Payload is: 
2017-02-14 11:18:37.233 [Debug] [Profile.swift:755] reportEndSyncingStatus(_:engineResults:) > Sync Status upload response: 502.

----------------------------

Comment 1

[Richard Newman [:rnewman]]

Historical context: Bug 1309571.

This is behaving correctly, even if that's not immediately apparent to the user: if you sync over and over, we will eventually get it all. We sync for a minute at a time, and for large history sets it can take 10+ minutes of syncing.

There are various alternative approaches, like fetch-recent-and-backfill (which Grisha did on Android), or fetch newest-to-oldest (which raises the question of what to do five minutes in when there might be newer history to get!).

Note that it's not quite safe to upload history records until we've downloaded everything — otherwise we can end up with two GUIDs mapping to the same history URL, which is undesirable.

Comment 2

[Stephan Leroux [:sleroux]]

Attachment: Logs 2

This seems to be a different, more severe issue.

When syncing my (smallish) test profile, I only ever receive 21 history items while the profile has many more from last year that never get pulled in. This also occurs in a build before we migrated the codebase to Swift 3 so it doesn't seem co-related to any of the changes made there. I've attached my Xcode logs and a print out of the request we're making to the server.

Comment 3

[Richard Newman [:rnewman]]

Steph, your log looks to be a different issue indeed. And if anything it looks like a server issue. Comment 0 clearly shows an incomplete large download.

How many records does the curl invocation return?

Is it different if you supply "0" as newer instead of "0.00"?

Is it different if you just GET …/history/?full=1 ?

Comment 4

[Stephan Leroux [:sleroux]]

Unfortunately the CURL invocation doesn't work - probably because of SSL pinning or some other network security voodoo since I get 401 Unauthorized.

I re-ran the two cases you highlighted through Xcode and the result is the same 21 records. It's also worth noting that Logins way able to sync my 1000+ test logins fine.

I think this is the same issue Catalin raised about only seeing 'Last Month'. Coincidentally the number of history records I'm able to pull down seems to be the same count of records I've visited in the past 30 days.

Comment 5

[Stephan Leroux [:sleroux]]

Just to clarify - this works fine on desktop when I pull down from the server so something else is going on.

Comment 6

[Richard Newman [:rnewman]]

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

> I re-ran the two cases you highlighted through Xcode and the result is the
> same 21 records. 

Which is *weird*.

That "21" in the log is X-Weave-Records, so the server is claiming that there are 21 matching records.

Is it possible that sort=oldest is broken? Desktop doesn't supply a sort argument. What happens if you don't send it?

If you open a Browser Console on desktop and run

JSON.parse(Weave.Service.resource(Weave.Service.infoURL.replace('collections', 'collection_counts')).get())

What do you get?


> I think this is the same issue Catalin raised about only seeing 'Last
> Month'.

Nah, Catalin's log shows:

2017-02-14 11:18:12.703 [Debug] [HistorySynchronizer.swift:224] onBatchResult > Running another batch.

… so it definitely pulled down more than a thousand records, and:

2017-02-14 11:18:36.164 [Debug] [Downloader.swift:192] handleSuccess > Advancing baseTimestamp to 1484890812900 - 1

which means it downloaded records older than January 19th, and stopped there (because the green light ran out).

"Last month" means it's *older* than 30 days. We do "today" and "yesterday" and such.

Comment 7

[Stephan Leroux [:sleroux]]

So after using my personal FxA account it was able to pull in my 10211 history items fine - including up to today. It's strange that my test account is showing that behavior account though. It doesn't have much history and only includes a few unique items for the last few months so I wonder if that's a factor - having a few sites spread across many months. 

> Nah, Catalin's log shows:
> 2017-02-14 11:18:12.703 [Debug] [HistorySynchronizer.swift:224] onBatchResult > Running another batch.
> ...

I totally didn't see that log message 'Green light turned red'. So it would seem that this is in fact the issue we originally talked about where the light turns red before being able to pull down all the history items. However, it should pick up the remaining history items on the next sync so this doesn't seem as big of a deal.

I feel like this might be a better thing to ship in 8.0 instead of in stabilization for 7.0 but I can be convinced easily =)

Comment 8

[Richard Newman [:rnewman]]

> I feel like this might be a better thing to ship in 8.0 instead of in stabilization for 7.0 but I can be convinced easily =)

If "this" is one of the mitigations I discussed in Comment 1… yes, I agree. It's unpleasant that it might take hours with the browser open to catch up to the user's full history, but it's not a bug per se, and there's no easy 'fix'.

Comment 9

[Stephan Leroux [:sleroux]]

Moving out of this sprint

Comment 10

[Stephan Leroux [:sleroux]]

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

WIP Patch