Closed Bug 1395547 Opened 2 years ago Closed 2 years ago

Sync tab list is empty on Desktop.

Categories

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

All
iOS
defect

Tracking

()

VERIFIED FIXED
Iteration:
1.30
Tracking Status
fxios 9.1 ---
fxios-v9.0 --- verified
fxios-v10.0 --- affected

People

(Reporter: SimonB, Assigned: jhugman)

References

Details

(Whiteboard: [MobileCore])

Attachments

(6 files, 1 obsolete file)

Priority: -- → P2
Assignee: nobody → jhugman
Status: NEW → ASSIGNED
Just to be clear, this is about regular tab syncing. Not Send Tab via notifications?
Flags: needinfo?(simion.basca)
Attached image Screen Shot
This is about the synced tabs on desktop. Attaching screenshot.
Flags: needinfo?(simion.basca)
With similar STR, I'm unable to reproduce the problem, using master for iOS and release (55.0.3) for Desktop.

STR differences: I a previously logged in account on both desktop and iOS.

I do have to sync the iOS client first, then desktop. Also (missing but implied) I did have to verify the account via email before anything started working.

However, when using a new install with an existing account, I am able to reproduce.
Tabs synchronizing thinks it has worked. 

Tap record uploaded: 
{
  "id" : "237bMkHgJKpz",
  "clientName" : "Fennec (jhugman) on Rhinestone 7+",
  "tabs" : [
    {
      "icon" : null,
      "title" : "This 'tree' has the environmental benefits of a forest - CNN",
      "lastUsed" : "1504873816.12",
      "urlHistory" : [
        "http:\/\/edition.cnn.com\/style\/article\/citytree-urban-pollution\/index.html"
      ]
    },
    {
      "icon" : null,
      "title" : "Most Forbidden Places in the World - Page 20 of 39 - the Brofessional",
      "lastUsed" : "1504877641.69",
      "urlHistory" : [
        "http:\/\/www.thebrofessional.net\/forbidden-places-world\/20\/?v=p&src=taboola&utm_source=taboola&utm_medium=CRAIG_TheBrofessional.net-Desktop-UK-NoGo-C2&utm_term=slashdot&utm_campaign=Even+The+US+President+Can%27t+Visit+These+39+Forbidden+Places",
        "http:\/\/www.thebrofessional.net\/forbidden-places-world\/20\/?v=p&src=taboola&utm_source=taboola&utm_medium=CRAIG_TheBrofessional.net-Desktop-UK-NoGo-C2&utm_term=slashdot&utm_campaign=Even+The+US+President+Can%27t+Visit+These+39+Forbidden+Places"
      ]
    }
  ]
}

Client as seen by desktop:

commands: Array[0]
protocols: Array[1]
   0: "1.5"
name: "Fennec (jhugman) on Rhinestone 7+"
appPackage: "org.mozilla.ios.Fennec"
id: "237bMkHgJKpz"
os: "iOS"
application: "Fennec (jhugman)"
fxaDeviceId: "966628c0526e8c9dc61537a2cc937e89"
version: "8.0"
formfactor: "phone"
type: "mobile"
device: "iPhone"

Vijay, could I get some of your eyes on this please?
Flags: needinfo?(vbudhram)
I think I may have the same problem with tab push notifications. I installed the last 9.0 beta (clean install) and then logged in to FxA. But I am unable to receive notifications. Would be good to get a confirmation on this from a second person and find out if this is related.
Flags: needinfo?(jhugman)
Whiteboard: [MobileCore]
Can confirm comment 5. This may be related to Bug 1382561.
Flags: needinfo?(jhugman)
See Also: → 1382561
Whiteboard: [MobileCore] → [MobileCore][needsuplift]
Not sure about comment 5. I cleanly installed 8.3 and 9.0 beta and they both work as expected against my existing account and also against a new account. I was able to see tabs from both sides and push notifications work great.

Temporary glitch in the matrix?

Let's re-test this.
Flags: needinfo?(simion.basca)
I'm seeing some off behaviour here:

2017-09-11 10:06:56.410 [Debug] [Profile.swift:1091] syncWith(synchronizers:account:statsSession:why:) > Syncing clients…
2017-09-11 10:06:56.411 [Debug] [Profile.swift:942] syncClientsWithDelegate(_:prefs:ready:why:) > Syncing clients to storage.
2017-09-11 10:06:56.411 [Info] [Synchronizer.swift:194] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.clients...'
2017-09-11 10:06:56.411 [Debug] [ClientsSynchronizer.swift:389] synchronizeLocalClients(_:withServer:info:) > Synchronizing clients.
2017-09-11 10:06:56.411 [Debug] [StorageClient.swift:787] getSince(_:sort:limit:offset:) > Issuing GET with newer = 0, offset = nil, sort = nil.
2017-09-11 10:06:56.797 [Debug] [StorageClient.swift:381] failFromResponse > Status code: 200.
2017-09-11 10:06:56.800 [Debug] [ClientsSynchronizer.swift:330] applyStorageResponse(_:toLocalClients:withServer:) > Applying clients response.
2017-09-11 10:06:56.800 [Debug] [ClientsSynchronizer.swift:337] applyStorageResponse(_:toLocalClients:withServer:) > Got 10 client records.
2017-09-11 10:06:56.800 [Debug] [ClientsSynchronizer.swift:351] applyStorageResponse(_:toLocalClients:withServer:) > Skipping our own unmodified record.
2017-09-11 10:06:56.803 [Debug] [ClientsSynchronizer.swift:222] processCommandsFromRecord(_:withServer:) > Processing commands from downloaded record.
2017-09-11 10:06:56.804 [Debug] [ClientsSynchronizer.swift:306] maybeUploadOurRecord(_:ifUnmodifiedSince:toServer:) > Should we upload our client record? Caller = false, expired = false.
2017-09-11 10:06:56.804 [Debug] [SQLiteRemoteClientsAndTabs.swift:420] getCommands() > Found 0 client sync commands in the DB.
2017-09-11 10:06:56.804 [Debug] [ClientsSynchronizer.swift:378] applyStorageResponse(_:toLocalClients:withServer:) > Running 0 commands.
2017-09-11 10:06:56.804 [Debug] [Profile.swift:951] syncClientsWithDelegate(_:prefs:ready:why:) > Updating FxA devices list.
2017-09-11 10:06:57.250 [Debug] [Profile.swift:1091] syncWith(synchronizers:account:statsSession:why:) > Syncing tabs…
2017-09-11 10:06:57.250 [Info] [Synchronizer.swift:194] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.tabs...'
2017-09-11 10:06:57.251 [Debug] [SQLiteRemoteClientsAndTabs.swift:266] getTabsForClientWithGUID > Looking for tabs for client with guid: nil
2017-09-11 10:06:57.251 [Debug] [Profile.swift:1091] syncWith(synchronizers:account:statsSession:why:) > Syncing logins…
2017-09-11 10:06:57.251 [Debug] [Profile.swift:971] syncLoginsWithDelegate(_:prefs:ready:why:) > Syncing logins to storage.
2017-09-11 10:06:57.251 [Info] [Synchronizer.swift:194] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.passwords...'
2017-09-11 10:06:57.251 [Debug] [SQLiteRemoteClientsAndTabs.swift:269] getTabsForClientWithGUID > Found 3 tabs for client with guid: nil
2017-09-11 10:06:57.251 [Debug] [LoginsSynchronizer.swift:169] synchronizeLocalLogins(_:withServer:info:) > Synchronizing passwords. Last fetched: 1504193011320.
2017-09-11 10:06:57.251 [Debug] [StorageClient.swift:787] getSince(_:sort:limit:offset:) > Issuing GET with newer = 1504193011320, offset = nil, sort = nil.
2017-09-11 10:06:57.251 [Debug] [TabsSynchronizer.swift:68] uploadOurTabs(_:toServer:) > Uploading our tabs: 3.
2017-09-11 10:06:57.347 [Debug] [StorageClient.swift:381] failFromResponse > Status code: 200.
2017-09-11 10:06:57.348 [Debug] [LoginsSynchronizer.swift:174] synchronizeLocalLogins(_:withServer:info:) > Applying incoming password records from response timestamped 1505138881660, last modified 1504193011320.
2017-09-11 10:06:57.348 [Debug] [LoginsSynchronizer.swift:175] synchronizeLocalLogins(_:withServer:info:) > Records header hint: 0



First, it looks like tabs and logins are synced at the same time?

Then there is:

- Looking for tabs for client with guid: nil
- Found 3 tabs for client with guid: nil


But also:

2017-09-11 10:06:57.251 [Debug] [TabsSynchronizer.swift:68] uploadOurTabs(_:toServer:) > Uploading our tabs: 3.
2017-09-11 10:06:57.347 [Debug] [StorageClient.swift:381] failFromResponse > Status code: 200.
Asking rnewman to take a peek too to this.
Flags: needinfo?(rnewman)
Catalin confirmed that he got my tabs. But also that he was able to reproduce this issue again.
Attached file Log
Full log of my testing session
Attached image Screenshot
Still reproducing this issue with a different account but only on that specific device with latest master ffdce75bae212.
Flags: needinfo?(simion.basca)
Chasing down the nil guid in the log. It seems this is explicity coded for, and used:

https://github.com/mozilla-mobile/firefox-ios/blob/15407ccab90713793e7a3c83d4a4950922699285/Sync/Synchronizers/TabsSynchronizer.swift#L58

:rnewman Does this look right?
(In reply to James Hugman [:jhugman] [@jhugman] from comment #13)

> :rnewman Does this look right?

SQL `NULL` (and Swift `nil` in the interface) is used for our own client, because its GUID can change over time. That code is correct.

(In reply to Stefan Arentz [:st3fan] from comment #8)

> First, it looks like tabs and logins are synced at the same time?

This looks totally sequential to me.
 
> Then there is:
> 
> - Looking for tabs for client with guid: nil
> - Found 3 tabs for client with guid: nil

This is when we upload our own tabs.


It seems to me that this is due to desktop excluding records without a corresponding FxA device ID; in order for desktop to see tabs for a device (if I understand the current state correctly), it must:

- Have registered with FxA and got a device ID
- Have uploaded its tabs under its client GUID
- Have uploaded its client record under that GUID, including its FxA device ID
Flags: needinfo?(rnewman)
I thought that this was a problem with not having the fxaDeviceId available in time for the client record to be uploaded.

This seems to be happening when I've stepped through with a debugger.

However, cutting and pasting from about:sync, I'm not seeing an tabs with the given ids.

Clients:
commands: Array[0]
application: "Fennec (jhugman)"
device: "iPhone"
name: "Fennec (jhugman) on jhugman-10147"
os: "iOS"
appPackage: "org.mozilla.ios.Fennec"
fxaDeviceId: "20b823c593ed6bf6f043e5050204674e"
protocols: Array[1]
id: "1yUr_XF2ESo5"
version: "8.0"
type: "mobile"
formfactor: "phone"

Tabs:
clientName: "Fennec (jhugman) on jhugman-10147"
tabs: Array[0]
id: "1yUr_XF2ESo5"

From Comment 4, I can see the tabs leaving the device, with a client GUID attached.
AFAIU comment 14, the tabs don't need an fxaDeviceId, only a client GUID, so as shown by about:sync, this seems to have happened.

Attaching log from the simulator that is currently exhibiting this bug.
Attached file Simulator log
This simulator log exhibits the bug.

Fresh install, logged into an existing account. Needed to confirm the login via email.
The device that I added to this account (Fennec (sarentz) on Risa) did not have this problem. Maybe we can see a difference between my and James' device?
Attached file aboutsync-logfiles.zip
Sync logs from corresponding desktop.
From the desktop sync logs:

1505159106569	Sync.Doctor	INFO	Skipping check of tabs - disabled via preferences

?
Group: mozilla-employee-confidential
I was able to reproduce briefly. Pages I opened in order:

- The "What new with Firefox" default page did now show up when I hit Sync on iOS and Sync on desktop. 
- I opened accounts.firefox.com. (hit sync on ios + sync on desktop) It did not show up. 
- Opened some random page in the history AND changed sync engine preferences to not Sync passwords (because I'm paranoid to sync passwords with test accounts). The random page as well as the 2 others showed up on Desktop.
Group: mozilla-employee-confidential
Since the first comment was deleted, here is that comment without the PII:

>Build: 9.0(5607)
>Device: iPhone 7
>iOS: 10.3.3

>Steps to reproduce:
>1. Create a new FxA 
>2. Log in to Dektop and iOS
>3. Open a few tabs and load a few pages on iOS
>4. Sync on both desktop and iOS
>5. On desktop, go to Sync Tabs list

>Actual results:
>- The Sync Tabs list is empty on desktop. I am seeing the device in the list but no open tabs. 

>Note
>- Tested with Clean profile on desktop
>- Send tabs from desktop to iOS work and vice-versa 
>- On iOS, I am seeing the opened tabs from desktop
>- Tested on several devices and found that the same account is showing the synced tabs on some devices and on two (iPhone 7 and iPad Air 2) does not work
Late to the game, but I was also not able to reproduce https://bugzilla.mozilla.org/show_bug.cgi?id=1395547#c0 or https://bugzilla.mozilla.org/show_bug.cgi?id=1395547#c5. I tested this with FxiOS 9 (TestFlight latest) and production FxA environment. This was with a new account, an existing account and having to confirm login. 

In each scenario, I was able to see tab list, receive and send push notifications to a desktop client. Sometimes there was a delay in receiving the notification, maybe a minute, but nothing that seemed out of the ordinary.
Flags: needinfo?(vbudhram)
In slack, :st3fan hypothesizes that this may be caused by non-ascii characters in the iOS device name.
I've been able to reproduce this problem without emoji involvement. (see Simulator logs and about:sync logs).
(In reply to James Hugman [:jhugman] [@jhugman] from comment #15)
> Tabs:
> clientName: "Fennec (jhugman) on jhugman-10147"
> tabs: Array[0]
> id: "1yUr_XF2ESo5"

I hope I'm not stating the obvious, but the above is the root of the problem - the server simply has no tabs from the client.

> From Comment 4, I can see the tabs leaving the device, with a client GUID
> attached.
> AFAIU comment 14, the tabs don't need an fxaDeviceId, only a client GUID, so
> as shown by about:sync, this seems to have happened.
> 
> Attaching log from the simulator that is currently exhibiting this bug.

I'm not really sure how to read those logs, but this sticks out:

> 2017-09-11 20:44:48.787 [Debug] [SQLiteRemoteClientsAndTabs.swift:340] getClientsAndTabs() > Found 27 raw tabs in the DB.

I assume that's saying there are 27 tabs in the local store.
...

> 2017-09-11 20:44:48.811 [Debug] [Telemetry.swift:54] send(ping:docType:) > Ping payload: {"events":[],"why":"schedule","uid":"4654f1c09505b1cde62f90b96011d053","deviceID":"55d82162c54e3210fb5cfd665d0305e2707a073492611bd3c5c4359f4f1d504c","version":1,"syncs":[{"didLogin":false,"why":"user","devices":[{"version":"55.0.3","id":"6aa48ff0f4fa4fe8fd6c6137e06f7f986c253ba03f6ab2bb6812430be72bdfde","os":"Darwin"}],"engines":[{"took":625,"name":"clients","incoming":{"newFailed":0,"reconciled":0,"failed":0,"applied":9,"succeeded":9}},{"name":"tabs","took":17081}],"when":1505159070393,"took":18392}]}

That seems to imply that the tab sync saw no incoming records nor sent any records (but apparently took 17 seconds to do nothing?)

> 2017-09-11 20:44:48.812 [Debug] [SQLiteRemoteClientsAndTabs.swift:340] getClientsAndTabs() > Found 27 raw tabs in the DB.

But still 27 in the local store.

I can't see any other evidence of tabs being uploaded. Is it possible that for some reason the tab sync thinks it has nothing to do? (eg, maybe because the last-modified on the server is somehow later than the current time on the device, or something else as equally obscure?)
While on the same simulator/desktop/session I didn't collect tabs upload, I did see evidence of a tabs record being uploaded – this is Comment 4.

I'll get a full set of a) client log b) desktop log c) tabs record JSON exhibiting the problem.
Iteration: --- → 1.30
Priority: P2 → P1
Working on a theory:

FxALoginHelper tries to verify the account. After the first time it account.advance(), it stores the fxaDeviceId in the scratchpad for sync to be ready to upload our client record.

At the same time, there is a scheduled sync happening, which needs the fxaDeviceId to upload a client record.

If a scheduled sync[2] or onAdded sync[3] happens before the fxaDeviceId has been stored in the scratchpad (currently in [1]) we would get a client record uploaded with the no fxaDeviceId. 

Pretty much all syncEverything() calls seem to be guarded by profile.hasSyncableAccount(). I don't quite understand the implementation of hasSyncableAccount() (stateCache.value especially) well enough to know if I'm on the right track. Perhaps :rnewman might have a perspective on this.

[1]: https://github.com/mozilla-mobile/firefox-ios/blob/master/Client/Helpers/FxALoginHelper.swift#L294
[2]: https://github.com/mozilla-mobile/firefox-ios/blob/master/Providers/Profile.swift#L1173
[3]: https://github.com/mozilla-mobile/firefox-ios/blob/master/Providers/Profile.swift#L849
Flags: needinfo?(rnewman)
Theory was that the fxaDeviceId was not being set before the first syncEverything. 

I found that the Refresh button selector was being called before the first advance was being called. Fixing this incidentally fixes Bug 1382561.

However, this doesn't fix this problem. 

Next, making the fxaDeviceId set properly in the SyncStateMachine. 

Also: when the fxaDeviceId changes, reset the client collection, to upload our client record again.

This is definitely paying down technical debt, but doesn't fix the problem.
> we would get a client record uploaded with the no fxaDeviceId

Are there circumstances where we might *want* to upload a client record without an fxaDeviceId, or should we error out in this case?  ISTM that refusing to upload such a record would either fix this bug, or eliminate that as a cause of this bug.
> Are there circumstances where we might *want* to upload a client record without an fxaDeviceId, or should we error out in this case?
My feeling is that there are no circumstances when not having an fxaDeviceId is beneficial.

Defer to :rnewman to be authoritative on this.
This is the work in progress PR against v9.x.
With 5 tabs open:

2017-09-19 14:24:37.093 [Debug] [SQLiteRemoteClientsAndTabs.swift:266] getTabsForClientWithGUID > Looking for tabs for client with guid: nil
2017-09-19 14:24:41.668 [Debug] [SQLiteRemoteClientsAndTabs.swift:269] getTabsForClientWithGUID > Found 0 tabs for client with guid: nil
2017-09-19 14:25:00.538 [Debug] [TabsSynchronizer.swift:68] uploadOurTabs(_:toServer:) > Uploading our tabs: 0.

I'm still suspicious of getTabsForClientWithGUID(nil).
Looking at the database, I see no tabs in the tabs table with the client_guid IS NULL or with the client_guid as the client id the device thinks it is.

The tabs table doesn't even have the tabs that the device has open.

Then, syncing again, 30 minutes later: 

2017-09-19 14:55:54.925 [Debug] [SQLiteRemoteClientsAndTabs.swift:269] getTabsForClientWithGUID > Found 5 tabs for client with guid: nil
2017-09-19 14:56:26.731 [Debug] [TabsSynchronizer.swift:68] uploadOurTabs(_:toServer:) > Uploading our tabs: 5.

Need infoing :justindarc. How are tabs not in the database?
Flags: needinfo?(jdarcangelo)
Discussed on Slack, but re-iterating here for preservation. I would start off by setting a breakpoint here:

https://github.com/mozilla-mobile/firefox-ios/blob/master/Storage/SQL/SQLiteRemoteClientsAndTabs.swift#L112-L117
Flags: needinfo?(jdarcangelo)
(In reply to James Hugman [:jhugman] [@jhugman] from comment #32)

> My feeling is that there are no circumstances when not having an fxaDeviceId
> is beneficial.
> 
> Defer to :rnewman to be authoritative on this.

Two perspectives:

- I'm not sure if self-hosted users will have device IDs. If we know they will -- that every FxA registration under the sun allocates a device ID -- then ignore this.

- From a Sync-centric perspective, it's better for a client that exists and is writing to have a client record than not, especially if a missing field will later be filled in.

If we know that every FxA registration pass will yield a device ID, then let's start making those fields non-optional.
Flags: needinfo?(rnewman)
(In reply to James Hugman [:jhugman] [@jhugman] from comment #35)
> Looking at the database, I see no tabs in the tabs table with the
> client_guid IS NULL or with the client_guid as the client id the device
> thinks it is.

N.B., we should never see our own client_guid in that table.

> The tabs table doesn't even have the tabs that the device has open.

Which means they weren't flushed to the DB, or they were deleted after they were flushed. Justin's pointer is the right starting point.

N.B., we flush delayed:

    func tabManagerWillStoreTabs(_ tabs: [Tab]) {
        // It is possible that not all tabs have loaded yet, so we filter out tabs with a nil URL.
        let storedTabs: [RemoteTab] = tabs.flatMap( Tab.toTab )

        // Don't insert into the DB immediately. We tend to contend with more important
        // work like querying for top sites.
        let queue = DispatchQueue.global(qos: DispatchQoS.background.qosClass)
        queue.asyncAfter(deadline: DispatchTime.now() + Double(Int64(ProfileRemoteTabsSyncDelay * Double(NSEC_PER_MSEC))) / Double(NSEC_PER_SEC)) {
            self.profile?.storeTabs(storedTabs)
        }
    }

ProfileRemoteTabsSyncDelay = 0.1.

It's possible that's too short -- we flush before we've finished restoring tabs. Or it's possible there's an arithmetic error in that code, where we convert between seconds, nanoseconds, milliseconds, integers, and doubles.
Attachment #8910030 - Flags: review?(jdarcangelo) → review+
Merged into master.
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Uplifted to v9.x as 741b4a63a.
Whiteboard: [MobileCore][needsuplift] → [MobileCore]
Verifying as fix on 9.1(6241). Tested with new accounts and with accounts that previous failed to display synced tabs from iOS to desktop and everything works as expected.
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.