Closed Bug 1342679 Opened 7 years ago Closed 7 years ago

Tab sync to/from desktop working only very intermittently

Categories

(Firefox :: Sync, defect, P1)

defect

Tracking

()

RESOLVED FIXED

People

(Reporter: JanH, Unassigned)

References

Details

Attachments

(6 files)

Attached file sync log tabs.txt
A few days ago, the sync account I'm using to sync between Desktop and Android release builds stopped working properly.

I've already tried resetting the sync account by changing the password and then reuploading everything from Desktop - afterwards, the initial sync from Android worked okay, but afterwards everything has gone wonky again.

At the moment, the Desktop tabs on my phone are updated only if I sign out of sync and then back in again.
In the other direction, tabs still seem to be sent by Android, but for some reason they're only displayed on Desktop if I restart my desktop Firefox - just clicking "Sync now" doesn't seem to bring them up.
Attached file Fennec Sync 2.txt
I've actually tried to sync again on mobile and this time the desktop tabs actually came through.
At the same time I've also noticed that some page I'd bookmarked on mobile has now appeared on my desktop as well.

This seems to have been a one-time fluke only though, since further sync attempts on my phone reverted to simply skipping all stages (or at most *sending* tabs) and some bookmark changes I'd previously (i.e. before the successful one-time tab sync mentioned above) made on Desktop haven't yet made their way to my phone.
Desktop is likewise still only updating the remote tabs list after a restart.

I also think I've seen something similar yesterday - after desktop Firefox had already uploaded its changes to sync and was closed down, repeated sync attempts from my phone continued to show "Skippings stage ..." in the logs and didn't pull in anything new, until a few minutes later all of a sudden the changes finally came through after all.
Summary: Sync stopped working properly → Sync working only very intermittently
How are you trying to trigger a sync?

02-25 21:12:13.883 25304-25603 I/FxAccounts: firefox :: Utils :: Asked to sync 'clients, tabs' and to skip ''.

implies that you're pulling to refresh on the Remote Tabs page, which won't sync bookmarks.

You can expect bookmarks to sync up and down in two instances: shortly after you launch the browser, or every few hours via background syncs.

You're also hitting rate limits on foreground syncs:

FxAccountSyncAdapter :: Not syncing (rate): must wait another 43365ms.

and background syncs:

FxAccountSyncAdapter :: Not syncing (background): must wait another 3523196ms.


You can see from that that your next background sync is no sooner than 1 hour from now…
Flags: needinfo?(jh+bugzilla)
(In reply to Jan Henning [:JanH] from comment #1)

> Desktop is likewise still only updating the remote tabs list after a restart.

That might be a separate bug, but do bear in mind that desktop will only see your Android device's tabs after (a) Android has synced the Tabs engine, and (b) desktop has subsequently synced.

If you still see this behavior, please ping markh!
(In reply to Richard Newman [:rnewman] from comment #2)
> How are you trying to trigger a sync?
> 
> 02-25 21:12:13.883 25304-25603 I/FxAccounts: firefox :: Utils :: Asked to
> sync 'clients, tabs' and to skip ''.
> 
> implies that you're pulling to refresh on the Remote Tabs page, which won't
> sync bookmarks.

Ah, that explains that bit - I guess I should have tried forcing a sync from the account settings for that? In any case it looks like some further bookmarks and history syncing has successfully taken place since then. Since unlike tabs I've rarely actively waited for changes there to immediately sync over, I can't say whether everything is working again as rapidly as it used to there, but it seems probable.

Tabs still don't seem to be quite working - I know for certain that previously forcing a sync first on my phone and then on desktop (or vice versa) was enough to make sure the tabs list was up to date on the other device. I'll watch it for a bit, though...
Thinking some more about it, I wonder whether Fennec's involvement might not after all possibly be a red herring? Given how my desktop Firefox has trouble seeing any updated tabs sent from Fennec unless its the first sync after a restart, it might equally be possible that it has trouble uploading tabs as well - which at least would be an obvious explanation why Fennec isn't getting any updated tabs from sync.
Flags: needinfo?(jh+bugzilla)
Summary: Sync working only very intermittently → Tab sync to/from desktop working only very intermittently
Mark, Richard said to ping you for this.

To summarize:
I have a sync account that I use for syncing between between the release versions (51.0.x) of Firefox on my Windows desktop and my Android phone.
A few days ago, tab syncing stopped working properly, even though I can't remember changing anything in my browser configuration at that time (I can't rule it out absolutely, though).

As of now, assuming that Firefox on my phone is in fact still working normally, it looks like
- Desktop uploads its tabs to sync only when I uncheck and then afterwards recheck the settings option to sync tabs. Just pressing "Sync now" or restarting the browser and then syncing doesn't seem to work for me - even after forcing a sync, my phone doesn't receive any updates for its list of remote tabs.
- In the reverse direction, it seems like Desktop only updates its list of remote tabs on the first sync after a) unchecking and rechecking the tab syncing setting, or b) a browser restart. Just clicking on "Sync now" while the browser is running and has synced at least once doesn't seem to have any effect as far as the displayed tabs are concerned.

Bookmarks and history sync still seems to be working normally, as does "Send tab to device...".
Temporarily deactivating all add-ons on desktop didn't seem to show any improvement, and neither did changing the password on my sync account to force clear all data.
Flags: needinfo?(markh)
On the first sync after desktop starts, we read all tabs from all remote clients. Subsequent syncs after that only fetch new tabs when the server reports the time has changed on the server version of the tabs - so the logs you have attached for desktop looks normal. Clicking the "Synced Tabs" icon also immediately forces a sync of tabs.

As far as "outgoing" tabs, if you open a single new tab and hit "sync now", the logs should show an entry like:

> Sync.Engine.Tabs	INFO	Posting 1 records of 26149 bytes with batch=true

which is desktop sending its current list of tabs to the server.

The best way to get to the bottom of this is to use the addon at https://addons.mozilla.org/en-US/firefox/addon/about-sync/ and inspecting the "tabs" collection - there is one record per client with all the tabs for that client. That should let you easily see what's going on - ie, whether the server has the tabs you expect to see (and if not, which client isn't sending them when you expect), or whether the server has the tabs but the client isn't seeing them (which implies a client isn't getting them off the server when you expect).

Attaching full logs from the desktop client after a restart might also be helpful.
Flags: needinfo?(markh)
(In reply to Mark Hammond [:markh] from comment #7)
> That should let you easily see what's going on - ie, whether
> the server has the tabs you expect to see (and if not, which client isn't
> sending them when you expect)…

There is a third option, which is that a client has uploaded data, but it is not yet visible to the other client.

This possibility has been hovering around for a while: we've had several Mozillians (including myself) observe that sent tabs sometimes take a while to show up, including across multiple forced syncs on each device. One of the explanations for that is that the server is not behaving as expected when a record is written, whether due to some kind of caching issue or something else.
(In reply to Richard Newman [:rnewman] from comment #8)
> This possibility has been hovering around for a while: we've had several
> Mozillians (including myself) observe that sent tabs sometimes take a while
> to show up, including across multiple forced syncs on each device. One of
> the explanations for that is that the server is not behaving as expected
> when a record is written, whether due to some kind of caching issue or
> something else.

The closest to this that I've ever seen is bug 1321119 - some number of tabs sometimes aren't uploaded due to an erroneous calculation of the max number of tabs we can actually store on the server - but the symptoms there are typically different - *some* tabs appear but some don't - although that *might* look a little like tabs aren't syncing depending on which ones are missing. Note however that the other bug only starts happening with a large number of tabs, which doesn't look like the case here.
To be specific, I mean something like this:

- On my iPhone (or Android, or…), I send a tab.
- A few minutes later, I switch back to my Mac.
- Tools > Sync Now. Huh, no tabs.
- I switch to my phone and force a sync.
- Tools > Sync Now. Huh, still no tabs. Oh well.
- Ten minutes later, a few sent tabs all arrive at once.

That is not expected behavior, but I've seen it myself, and seen it described by others.
From triage meeting: can you check Mark's comment 7 ?
Flags: needinfo?(jh+bugzilla)
Right, so after a fresh start up (https://pastebin.mozilla.org/8980624), about:sync is showing this for tabs:

> date: "Tue, 28 Feb 2017 21:00:13 GMT"
> x-last-modified: "1488104111.51"
> x-weave-timestamp: "1488315613.22"

The tab objects visible there are those that I actually have open on both desktop and my phone.
After opening a tab on desktop and forcing a sync (https://pastebin.mozilla.org/8980625), the log does indeed show
> 1488316095938	Sync.Engine.Tabs	INFO	Posting 1 records of 7204 bytes with batch=true

about:sync is indeed showing the additional tab object for desktop, but apparently the last modified timestamp hasn't changed and syncing on my phone doesn't pull in any updates:
> date: "Tue, 28 Feb 2017 21:09:40 GMT"
> x-last-modified: "1488104111.51"
> x-weave-timestamp: "1488316180.57"

If I then open a tab on my phone and sync it, the tab being uploaded from my phone is shown in logcat and the new tab subsequently appears in about:sync, but not in the regular remote tabs overview, presumably because the timestamp is still unchanged (https://pastebin.mozilla.org/8980626):
> date: "Tue, 28 Feb 2017 21:17:01 GMT"
> x-last-modified: "1488104111.51"
> x-weave-timestamp: "1488316621.09"
Flags: needinfo?(jh+bugzilla)
Oops, I don't think I paid attention to the retention settings, so here are some links that should be good for one month:
https://pastebin.mozilla.org/8980627 first sync
https://pastebin.mozilla.org/8980628 sync after opening a tab on desktop
https://pastebin.mozilla.org/8980629 sync after opening a tab on mobile
It seems like somebody else is experiencing symptoms that sound suspiciously like mine and also started around the same time:

http://forums.mozillazine.org/viewtopic.php?p=14734938#p14734938
Because of bug 1343414, I've reset my sync account once again, that is
- delete it
- recreate it from Desktop with a different password as well
- wait for Desktop to finish the initial sync
- connect my phone as well

The HMAC errors seem to have been fixed, however no difference as far as tab syncing is concerned - "x-last-modified" continues being stuck on what I think is the time I added my phone to the sync account.
Priority: -- → P1
Ditto here; history didn't sync and I saw HMAC errors and recreated my sync account. Those are gone now, but the tab syncing problem (from desktop 53.0a2 to mobile 52.0) remains.

I can get them to partially sync by wiping the tabs data from the server:

1. Disable tabs sync on mobile. Wait for the persistence sync.
2. Sync mobile. This logs that it wiped the tabs data.
3. Sync desktop.
4. Enable tabs sync on desktop.
5. Sync desktop.
6. Sync mobile.

This refreshes the tabs on mobile, but only with a partial set of tabs (4 to 6 of about 12) from the desktop.
I can confirm the problem too. Opened facebook on my phone then synced, tab reflected in about:sync but not in the synced tabs menu.
Attached file before_restart.txt
The tabs show up once we reload Firefox.
Ongoing investigation: x-weave-timestamp seems to be stuck in the past (but the data itself does change).
Update for the people not on IRC: we most likely found the problem.
The timestamps in info/collections are not advancing on writes (with the new batch API), we're working on a fix (hopefully only server-side).
I think I found the server bug causes this strange timestamp behaviour:

  https://github.com/mozilla-services/server-syncstorage/pull/60

I could only reliably trigger it with the "tabs" collection.  However it's not out of the question that there was some sort of race condition that let it trigger occasionally for the "clients" and "meta" collections as well.
Attachment #8844748 - Flags: review?(rhubscher)
Attachment #8844748 - Flags: review?(bwong)
Blocks: 1342881
No longer blocks: 1342881
See Also: → 1342881
Attachment #8844748 - Flags: review?(rhubscher) → review+
Attachment #8844748 - Flags: review?(bwong) → review+
Fixed in https://github.com/mozilla-services/server-syncstorage/pull/60.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.