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

VERIFIED FIXED

Status

()

Firefox for Android
Android Sync
VERIFIED FIXED
4 years ago
5 months ago

People

(Reporter: aaronmt, Unassigned)

Tracking

({reproducible})

Firefox 29
ARM
Android
reproducible
Points:
---

Firefox Tracking Flags

(firefox28 unaffected, firefox29 affected, fennec29+)

Details

(Whiteboard: [qa+])

Attachments

(2 attachments)

(Reporter)

Description

4 years ago
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)
(Reporter)

Comment 1

4 years ago
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.
(Reporter)

Comment 2

4 years ago
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
> 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.
Whiteboard: [qa+]
tracking-fennec: ? → 29+
status-firefox28: --- → unaffected
(Reporter)

Comment 4

4 years ago
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.
(Reporter)

Comment 5

4 years ago
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
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.

Updated

4 years ago
Duplicate of this bug: 966045
(Reporter)

Comment 8

4 years ago
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.
(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?
Flags: needinfo?(aaron.train)
(Reporter)

Comment 10

4 years ago
Created attachment 8370898 [details]
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
Flags: needinfo?(aaron.train)
Attachment #8370898 - Attachment mime type: text/x-log → text/plain
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?
(Reporter)

Comment 12

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

Comment 13

4 years ago
(Also noting about:sync-tabs is empty on desktop)
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
---
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?

Updated

4 years ago
Flags: needinfo?(rnewman)
Created attachment 8371063 [details]
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.
Ah, newlines format.  So maybe a server but with newlines format them.
Depends on: 968512
Flags: needinfo?(rnewman)
This now works for me after deploying the fix in Bug 968512.
(Reporter)

Comment 19

4 years ago
Great! This works now for me as well. Fixed via bug 968512
Status: NEW → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Verified with Nightly from 20140206
Status: RESOLVED → VERIFIED
note, i see my other tabs after i kill and restart the process on android

Updated

5 months ago
Product: Android Background Services → Firefox for Android
You need to log in before you can comment on or make changes to this bug.