961806 - Firefox Accounts (Sync) - Synced Remote Tabs not syncing, or not showing up in our tab listing

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: Android Sync, defect)

Description

[Aaron Train [:aaronmt]]

Currently, I have three devices on my desk:

1) LG Nexus 4 (Android 4.4.2, Nightly 01/20)
2) Samsung Galaxy SII (Android 4.1, Nightly 01/20)
3) Asus Nexus 7 (Android 4.4.2, Nightly 01/20)

* On all three devices, I have a  single tab open with: http://www.reddit.com

* I have successfully signed-in with the same account on all three devices and made sure to checkmark all boxes (including open-tabs)

* I have successfully Synced between all three devices. All three devices have bookmarks, and history). I have not tested passwords yet. All three devices are showing the same listing of data exactly the same

* Upon checking the remote tabs listing in our UI, there are no entries. Each device has no entries in the remote tab listing

Expected:

* LG Nexus 4
↪ "<user>'s Asus Nexus 7 - Reddit (http://www.reddit.com"
↪ "<user>'s Galaxy SII - Reddit http://www.reddit.com"

* Asus Nexus 7
↪ "<user>'s LG Nexus 4 - Reddit (http://www.reddit.com"
↪ "<user>'s Galaxy SII - Reddit http://www.reddit.com"

* Samsung Galaxy II
↪ "<user>'s LG Nexus 4 - Reddit (http://www.reddit.com"
↪ "<user>'s Asus Nexus 7 - Reddit (http://www.reddit.com"

Actual: No entries on all devices

On each device:

I/FxAccounts( 8049): fennec :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@41e26818)...

I/FxAccounts( 8049): fennec :: ServerSyncStage :: Stage tabs received 0 and sent 0 records in 0.07 seconds.

--
Nightly (01/2)

Comment 1

[Aaron Train [:aaronmt]]

In the off-chance that this is related

On tap of the remote tabs listing in Nightly (01/20), I continue to get

W/GeckoProfile(24239): Requested profile directory missing.

Comment 2

[Aaron Train [:aaronmt]]

During initial-sync

I/FxAccounts(28276): fennec :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@421a4428)...
W/FxAccounts(28276): fennec :: ServerSyncStage :: Remote engine syncID different from local engine syncID: resetting local engine and assuming remote engine syncID.
I/FxAccounts(28276): fennec :: ServerSyncStage :: Setting syncID for org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@421a4428 to 'a5ypvyCzpeFK'.
I/FxAccounts(28276): fennec :: ServerSyncStage :: Reset timestamps for org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@421a4428
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
W/GeckoProfile(28276): Requested profile directory missing.
I/FxAccounts(28276): fennec :: ServerSyncStage :: Stage tabs received 7 and sent 1 records in 1.24 seconds.

Which makes me believe that we're not displaying them properly now actually

Comment 3

[Nick Alexander :nalexander [he/him]]

> Which makes me believe that we're not displaying them properly now actually

That's more likely.  It's a little tricky to figure out when tabs actually get written to the DB; see Bug 780279 and Bug 849072.

Comment 4

[Aaron Train [:aaronmt]]

Tried this again on Nightly (M-C, 01/29) against two devices, new account, two tabs open on each and this worked once for me today.

Attempts afterwards with new tabs open on both devices and force-syncing both would not fetch new data to both devices.

Comment 5

[Aaron Train [:aaronmt]]

Also tested against two devices running http://tbpl.mozilla.org/?tree=Try&rev=fa88edfc4af6 with tabs open on both devices and after sign-in on both and initial sync, our remote tab listing remains empty

Comment 6

[Richard Newman [:rnewman]]

This should be just Bug 962644, particularly

https://hg.mozilla.org/mozilla-central/rev/f8bdcea0085b#l1.32

If you're testing a Nightly before Feb 1, you won't have that commit.

Comment 8

[Aaron Train [:aaronmt]]

I'm using Nightly (02/05) and Aurora (02/05) and continue to see this issue; also have open tabs on desktop Nightly (02/05). Madhava also mentioned seeing this.

Comment 9

[Richard Newman [:rnewman]]

(In reply to Aaron Train [:aaronmt] from comment #8)
> I'm using Nightly (02/05) and Aurora (02/05) and continue to see this issue;
> also have open tabs on desktop Nightly (02/05). Madhava also mentioned
> seeing this.

OK, so you have two Androids and a desktop. Either they're not uploading or they're not downloading.

1.

If you turn on logOnSuccess on desktop (and restart), then change tabs and force a sync, do you see it uploading tabs?

How many clients does it report seeing in the log?


2.

On Android:

  adb shell setprop log.tag.GeckoTabsProvider VERBOSE

and restart.

When you're browsing on Android (with a few pauses here and there), do you see GeckoTabsProvider logging about handling inserts?

Then when it syncs, do you see it uploading or downloading tabs records?

Comment 10

[Aaron Train [:aaronmt]]

Attachment: desktop.log

(In reply to Richard Newman [:rnewman] from comment #9)
> (In reply to Aaron Train [:aaronmt] from comment #8)
> > I'm using Nightly (02/05) and Aurora (02/05) and continue to see this issue;
> > also have open tabs on desktop Nightly (02/05). Madhava also mentioned
> > seeing this.
> 

[..]

> If you turn on logOnSuccess on desktop (and restart), then change tabs and
> force a sync, do you see it uploading tabs?
> 
> How many clients does it report seeing in the log?

Attached a desktop log

> 2.
> 
> On Android:
> 
> When you're browsing on Android (with a few pauses here and there), do you
> see GeckoTabsProvider logging about handling inserts?

I do. E.g, 

D/GeckoTabsProvider(20997): Inserted ID in database: 33

V/GeckoTabsProvider(20997): Calling insert in transaction on URI: content://org.mozilla.fennec.db.tabs/tabs

V/GeckoTabsProvider(20997): Getting writable database for URI: content://org.mozilla.fennec.db.tabs/tabs

D/GeckoTabsProvider(20997): Inserting tab in database with URL: http://www.bing.com/
 
> Then when it syncs, do you see it uploading or downloading tabs records?

I/FxAccounts(20997): fennec :: GlobalSession :: Running next stage syncTabs (org.mozilla.gecko.sync.stage.FennecTabsServerSyncStage@420193a8)...

I/FxAccounts(20997): fennec :: ServerSyncStage :: Stage tabs received 0 and sent 1 records in 0.24 seconds.

Those messages?

The only thing from GeckoTabsProvider related to tabs during Sync is

V/GeckoTabsProvider(20997): Getting readable database for URI: content://org.mozilla.fennec.db.tabs/tabs
V/GeckoTabsProvider(20997): Query is on TABS: content://org.mozilla.fennec.db.tabs/tabs
V/GeckoTabsProvider(20997): Running built query.
V/GeckoTabsProvider(20997): Getting readable database for URI: content://org.mozilla.fennec.db.tabs/tabs
V/GeckoTabsProvider(20997): Query is on TABS: content://org.mozilla.fennec.db.tabs/tabs
D/GeckoTabsProvider(20997): Using sort order position ASC.
V/GeckoTabsProvider(20997): Running built query.
V/GeckoTabsProvider(20997): Getting readable database for URI: content://org.mozilla.fennec.db.tabs/tabs
V/GeckoTabsProvider(20997): Query is on TABS: content://org.mozilla.fennec.db.tabs/tabs
D/GeckoTabsProvider(20997): Using sort order position ASC.
V/GeckoTabsProvider(20997): Running built query.

but no insert messages

Comment 11

[Richard Newman [:rnewman]]

OK, so everyone is exchanging client records, and Android is persisting and uploading tabs successfully.

I suspect your problem is this:

* On all three devices, I have a  single tab open with: http://www.reddit.com

We remove tabs that are already open on the local device, because what's the point? Try opening some different tabs in different places and try to repro again?

Comment 12

[Aaron Train [:aaronmt]]

I have a variety of different tabs opens on all my devices and desktop (Nightly 02/05). I didn't use Reddit just now.

Comment 13

[Aaron Train [:aaronmt]]

(Also noting about:sync-tabs is empty on desktop)

Comment 14

[Richard Newman [:rnewman]]

Something is horribly wrong in clients-land.

First desktop client:
---
1391634994677	Sync.Engine.Clients	DEBUG	Old engine data: ,1
1391634994865	Sync.Resource	DEBUG	mesg: DELETE success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391634994867	Sync.Resource	DEBUG	DELETE success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391634994871	Sync.Engine.Clients	DEBUG	Resetting clients last sync time
1391634994877	Sync.Engine.Clients	DEBUG	First sync, uploading all items
1391634994879	Sync.Tracker.Clients	TRACE	Clearing changed ID list
1391634994881	Sync.Engine.Clients	INFO	1 outgoing items pre-reconciliation
1391634994883	Sync.Engine.Clients	TRACE	Downloading & applying server changes
1391634994899	Sync.Engine.Clients	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1391634994903	Sync.Engine.Clients	TRACE	Uploading local changes to server.
1391634994905	Sync.Engine.Clients	TRACE	Preparing 1 outgoing records
1391634994914	Sync.Engine.Clients	TRACE	Outgoing: { id: 7bibMruuFyBV  index: 0  modified: undefined  ttl: 1814400  payload: {"id":"7bibMruuFyBV","name":"rnewman's Firefox on jetfire","type":"desktop","version":"29.0a2","protocols":["1.1"]}  collection: clients }
1391634994938	Sync.Engine.Clients	INFO	Uploading all of 1 records
1391634994960	Sync.Collection	DEBUG	POST Length: 357
1391634995100	Sync.Collection	DEBUG	mesg: POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391634995101	Sync.Collection	DEBUG	POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391634995108	Sync.Engine.Clients	TRACE	Finishing up sync
1391634995110	Sync.Engine.Clients	TRACE	Event: weave:engine:sync:finish
1391634995113	Sync.SyncScheduler	DEBUG	Client count: 0 -> 1
1391634995118	Sync.Synchronizer	INFO	Updating enabled engines: 1 clients.
---


Second desktop client:
---
1391635722732	Sync.Engine.Clients	INFO	1 outgoing items pre-reconciliation
1391635722734	Sync.Engine.Clients	TRACE	Downloading & applying server changes
1391635723123	Sync.Collection	DEBUG	mesg: GET success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients?full=1
1391635723125	Sync.Collection	DEBUG	GET success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients?full=1
1391635723133	Sync.Engine.Clients	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1391635723137	Sync.Engine.Clients	TRACE	Uploading local changes to server.
1391635723138	Sync.Engine.Clients	TRACE	Preparing 1 outgoing records
1391635723149	Sync.Engine.Clients	TRACE	Outgoing: { id: bDzbYEI4xC3q  index: 0  modified: undefined  ttl: 1814400  payload: {"id":"bDzbYEI4xC3q","name":"rnewman's Firefox on jetfire","type":"desktop","version":"29.0a2","protocols":["1.1"]}  collection: clients }
1391635723173	Sync.Engine.Clients	INFO	Uploading all of 1 records
1391635723195	Sync.Collection	DEBUG	POST Length: 357
1391635723338	Sync.Collection	DEBUG	mesg: POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391635723339	Sync.Collection	DEBUG	POST success 200 https://sync-2-us-east-1.sync.services.mozilla.com/1.5/10476/storage/clients
1391635723346	Sync.Engine.Clients	TRACE	Finishing up sync
1391635723348	Sync.Engine.Clients	TRACE	Event: weave:engine:sync:finish
1391635723352	Sync.SyncScheduler	DEBUG	Client count: 0 -> 1
---

Comment 15

[Ryan Kelly [:rfkelly]]

I've reproduced this against my dev sync server, so it's not memcached related nor it is some deployment jank in prod.

What's strange though, is that the server *appears* to be sending the correct information back to the client.  If I hit the request URLs directly, they return what appears to be sensible data.  Richard, is there filtering logic or something in the client that might cause it to ignore client records returned by the server, e.g. if we get timestamps screwed up somehow?

Comment 16

[Ryan Kelly [:rfkelly]]

Attachment: success-1391640148990.txt

Attaching a sync log with response-body debugging enabled.  Interesting part:

1391640144887	Sync.Collection	DEBUG	GET success 200 https://sync-1-us-east-1.sync.services.mozilla.com/1.5/10502/storage/clients?full=1
1391640144887	Sync.Collection	TRACE	GET body: {"payload": "{\"ciphertext\":\"PE72kSxq1tgEfHkiV/jQtRWKx+XxgIvFfjzKD2XRaLa1GWy78Kv10REQ2NkwTsaUzYG0QhxQCde6opd62PbnVdkZyBLHzsH1OAh46JMmSg6E3RBhV0MYEvhVo9PV6jPWyPYdggelAgOONQN9KNO7X1Q37KShz2KvbtBRVxmXCFs=\",\"IV\":\"uCMqbnxr5AZk+DRo/oCzow==\",\"hmac\":\"cca44a750eeb02d4ca5604492730a56b4e7009fc8e59a7a5de1b04c71fd63532\"}", "modified": 1391640064.43, "id": "jl_M3mQBjMWq"}
1391640144887	Sync.Collection	TRACE	Processing response headers.
1391640144888	Sync.Engine.Clients	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.

It seems to retrieve an item from the server, but it's not wrapped in a JSON list for some reason..?  I'm pretty sure the server sends them wrapped in a list.  Will check it out server-side.

Comment 17

[Ryan Kelly [:rfkelly]]

Ah, newlines format.  So maybe a server but with newlines format them.

Comment 18

[Ryan Kelly [:rfkelly]]

This now works for me after deploying the fix in Bug 968512.

Comment 19

[Aaron Train [:aaronmt]]

Great! This works now for me as well. Fixed via bug 968512

Comment 20

[Tracy Walker [:tracy]]

Verified with Nightly from 20140206

Comment 21

[Edwin Wong [:edwong]]

note, i see my other tabs after i kill and restart the process on android