Declined/Accepted SyncEngines not updated properly upon new device connection

Vishwa-Mozilla commented 4 years ago

[x] AS bug: https://github.com/mozilla/application-services/issues/3205

Declined/Accepted SyncEngines not updated properly upon new connection is established until there is a state change in sync settings triggered from the Desktop.

Key Classes/Functions to look at:

WorkManagerSyncManager class contains doSync() function that handles fetching declined/accepted SyncEngines information but it is not being updated with the latest changes from the server

SyncEnginesStorage class stores the SyncEngine status to SharedPreferences

Steps to reproduce

Change Sync Settings (eg. unselect History) on Desktop, Save Settings, and click Sync Now
Connect to Firefox Account on Android
All tabs are selected because declinedEngines variable contains nothing
We can fix it by again changing sync settings on Desktop and syncing again
Click "Sync Now" on Mobile
doSync() gets triggered but this time declined/accepted SyncEngines will be identical to the Desktop

┆Issue is synchronized with this Jira Task

Vishwa-Mozilla commented 4 years ago

@grigoryk can you take a look at this?

grigoryk commented 4 years ago

Yup, I can replicate this locally.

In Firefox Desktop, disable a sync engine (e.g. "bookmarks"), sync. Now, sign-in on a fresh Fenix, sync and observe the logs:

Logs collected immediately after logging in. It looks we're syncing two times in a row, with first sync getting the declined list correctly, and second sync incorrectly gets an empty declined list.

--
06-04 14:38:00.090 10608 10649 I sync15::client: Successful request to "/1.5/80491671/storage/meta/global", incoming x-last-modified=ServerTimestamp(1591306651680)
06-04 14:38:00.090 10608 10649 D sync15::client: Got meta global with modified = 1591306651.68; last-modified = 1591306651.68
06-04 14:38:00.090 10608 10649 I sync15::state: Have info/collections and meta/global. Computing new engine states
06-04 14:38:00.090 10608 10649 D sync15::state: compute_engine_states: input EngineStateInput { local_declined: {}, remote: Some(RemoteEngineState { info_collections: {"tabs", "crypto", "forms", "meta", "clients", "prefs", "addresses", "history", "passwords", "addons"}, declined: {"bookmarks"} }), user_changes: {} }
06-04 14:38:00.090 10608 10649 D sync15::state: compute_engine_states: output EngineStateOutput { declined: {"bookmarks"}, changes_needed: EngineChangesNeeded { local_resets: {"bookmarks"}, remote_wipes: {} } }
--
--
06-04 14:38:00.271 10608 10649 I sync15::client: Successful request to "/1.5/80491671/storage/crypto/keys", incoming x-last-modified=ServerTimestamp(1546736573710)
06-04 14:38:00.271 10608 10649 D sync15::sync_multiple: Declined engines list after state machine set to: Some(["bookmarks"])
06-04 14:38:00.271 10608 10649 I sync15::sync_multiple: Resetting engine bookmarks, as it was declined remotely
06-04 14:38:00.284 10608 10649 D sql_support::conn_ext: Transaction commited after 12.46236ms
06-04 14:38:00.284 10608 10649 I sync15::sync_multiple: Synchronizing clients engine
06-04 14:38:00.284 10608 10649 I sync15::clients::engine: Syncing collection clients
--
--
06-04 14:38:09.147 10608 10649 D places::storage::history::history_sync: Updating all non-synced rows
06-04 14:38:09.157 10608 10649 D places::storage::history::history_sync: Removing local tombstones
06-04 14:38:09.161 10608 10649 D sql_support::conn_ext: Transaction commited after 14.353498ms
06-04 14:38:09.169 10608 10649 I sync15::sync: Sync finished!
06-04 14:38:09.169 10608 10649 I sync15::sync_multiple: Sync of history was successful!
06-04 14:38:09.169 10608 10649 I sync15::sync_multiple: The bookmarks engine is declined. Skipping
06-04 14:38:09.169 10608 10649 I sync15::sync_multiple: Syncing passwords engine!
06-04 14:38:09.169 10608 10649 I sync15::sync: Syncing collection passwords
06-04 14:38:09.170 10608 10649 I sync15::coll_state: Resetting passwords store
06-04 14:38:09.173 10608 10649 I logins::db: Executing reset on password store!
06-04 14:38:09.173 10608 10649 D logins::db: Updating last sync to 0
--
--
06-04 14:38:09.820 10608 10649 I SyncWorker: Successfully synced passwords
06-04 14:38:09.820 10608 10649 I SyncWorker: Successfully synced history
06-04 14:38:09.820 10608 10649 I SyncWorker: Successfully synced tabs
06-04 14:38:09.820 10608 10649 I SyncWorker: Declined engines: [mozilla.components.service.fxa.SyncEngine$Bookmarks@3d88526]
06-04 14:38:09.820 10608 10649 I SyncWorker: Accepted engines: [mozilla.components.service.fxa.SyncEngine$History@f941081, mozilla.components.service.fxa.SyncEngine$Passwords@d267567, mozilla.components.service.fxa.SyncEngine$Tabs@5cf8f14]
06-04 14:38:09.826 10608 10729 D sql_support::conn_ext: Transaction commited after 7.724598ms
06-04 14:38:09.826 10608 10729 I sync15::sync_multiple: Syncing 4 stores
06-04 14:38:09.826 10608 10729 I sync15::sync_multiple: Loading/initializing persisted state
06-04 14:38:09.826 10608 10729 E sync15::sync_multiple: Failed to parse PersistedGlobalState from JSON! Falling back to default
06-04 14:38:09.826 10608 10729 I sync15::sync_multiple: Preparing client info
--
--
06-04 14:38:09.874 10608 10729 I sync15::client: Successful request to "/1.5/80491671/info/collections", incoming x-last-modified=ServerTimestamp(1591306690030)
06-04 14:38:09.874 10608 10729 D sync15::sync_multiple: Declined engines list after state machine set to: Some([])
06-04 14:38:09.874 10608 10729 I sync15::sync_multiple: Synchronizing clients engine
06-04 14:38:09.874 10608 10729 I sync15::clients::engine: Syncing collection clients
--
--
06-04 14:38:09.980 10608 10729 I sync15::sync: Sync finished!
06-04 14:38:09.980 10608 10729 I sync15::sync_multiple: Sync of history was successful!
06-04 14:38:09.980 10608 10729 I sync15::sync_multiple: The bookmarks engine is declined. Skipping
06-04 14:38:09.980 10608 10729 I sync15::sync_multiple: Syncing passwords engine!
06-04 14:38:09.980 10608 10729 I sync15::sync: Syncing collection passwords
06-04 14:38:09.980 10608 10729 I sync15::sync: skipping incoming for passwords - not needed.
06-04 14:38:09.980 10608 10729 D logins::update_plan: UpdatePlan: deleting records...
06-04 14:38:09.980 10608 10729 D logins::update_plan: UpdatePlan: Updating existing mirror records...
--
--
06-04 14:38:10.135 10608 10729 I SyncWorker: Successfully synced passwords
06-04 14:38:10.135 10608 10729 I SyncWorker: Successfully synced tabs
06-04 14:38:10.135 10608 10729 I SyncWorker: Successfully synced history
06-04 14:38:10.135 10608 10729 I SyncWorker: Declined engines: []
06-04 14:38:10.135 10608 10729 I SyncWorker: Accepted engines: [mozilla.components.service.fxa.SyncEngine$History@f941081, mozilla.components.service.fxa.SyncEngine$Bookmarks@3d88526, mozilla.components.service.fxa.SyncEngine$Passwords@d267567, mozilla.components.service.fxa.SyncEngine$Tabs@5cf8f14]
06-04 14:38:10.137 10608 10729 W SyncTelemetry: Ignoring telemetry for engine tabs
06-04 14:38:10.140 10608 10646 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=a920c8f8-ba7b-4301-8270-daba4d36ba5b, tags={ mozilla.components.service.fxa.sync.WorkManagerSyncWorker, Debounce, Common } ]
06-04 14:38:10.214 10608 10648 I libglean_ffi: glean_core::ping: Collecting history-sync
06-04 14:38:10.241 10608 10648 D libglean_ffi: glean_core::ping: Storing ping '6cac66bc-e0f0-4bcc-85a2-fec38691c7d9' at '/data/user/0/org.mozilla.fenix.debug/glean_data/pending_pings/6cac66bc-e0f0-4bcc-85a2-fec38691c7d9'
06-04 14:38:10.241 10608 10648 I libglean_ffi: glean_core: The ping 'history-sync' was submitted and will be sent as soon as possible

Subsequent syncs get an (incorrect) empty declined list in the sync results. Note that sync manager is aware that bookmark engine is disabled, and doesn't actually sync it:

--
06-04 14:41:39.550 10608 10649 I sync15::client: Successful request to "/1.5/80491671/info/collections", incoming x-last-modified=ServerTimestamp(1591306690390)
06-04 14:41:39.550 10608 10649 D sync15::sync_multiple: Declined engines list after state machine set to: Some([])
06-04 14:41:39.550 10608 10649 I sync15::sync_multiple: Synchronizing clients engine
06-04 14:41:39.550 10608 10649 I sync15::clients::engine: Syncing collection clients
--
--
06-04 14:41:39.603 10608 10649 D places::storage::history::history_sync: Updating all non-synced rows
06-04 14:41:39.613 10608 10649 D places::storage::history::history_sync: Removing local tombstones
06-04 14:41:39.616 10608 10649 D sql_support::conn_ext: Transaction commited after 13.493195ms
06-04 14:41:39.618 10608 10649 I sync15::sync: Sync finished!
06-04 14:41:39.618 10608 10649 I sync15::sync_multiple: Sync of history was successful!
06-04 14:41:39.619 10608 10649 I sync15::sync_multiple: The bookmarks engine is declined. Skipping
06-04 14:41:39.619 10608 10649 I sync15::sync_multiple: Syncing passwords engine!
06-04 14:41:39.619 10608 10649 I sync15::sync: Syncing collection passwords
06-04 14:41:39.619 10608 10649 I sync15::sync: skipping incoming for passwords - not needed.
06-04 14:41:39.619 10608 10649 D logins::update_plan: UpdatePlan: deleting records...
06-04 14:41:39.619 10608 10649 D logins::update_plan: UpdatePlan: Updating existing mirror records...
--
--
06-04 14:41:39.785 10608 10649 I SyncWorker: Successfully synced tabs
06-04 14:41:39.785 10608 10649 I SyncWorker: Successfully synced history
06-04 14:41:39.785 10608 10649 I SyncWorker: Successfully synced passwords
06-04 14:41:39.785 10608 10649 I SyncWorker: Declined engines: []
06-04 14:41:39.785 10608 10649 I SyncWorker: Accepted engines: [mozilla.components.service.fxa.SyncEngine$History@f941081, mozilla.components.service.fxa.SyncEngine$Bookmarks@3d88526, mozilla.components.service.fxa.SyncEngine$Passwords@d267567, mozilla.components.service.fxa.SyncEngine$Tabs@5cf8f14]
06-04 14:41:39.786 10608 10649 W SyncTelemetry: Ignoring telemetry for engine tabs
06-04 14:41:39.788 10608 10643 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=481a633c-2241-4c19-ade9-04f0c2a2e7b6, tags={ Immediate, mozilla.components.service.fxa.sync.WorkManagerSyncWorker, Common } ]

Disabling another engine locally in Fenix (tabs) and syncing, I see something more problematic: we've actually enabled the 'bookmarks' sync engine without an explicit user action.

06-04 14:54:04.107 10608 10649 I sync15::client: Successful request to "/1.5/80491671/storage/meta/global", incoming x-last-modified=ServerTimestamp(1591306651680)
06-04 14:54:04.107 10608 10649 D sync15::client: Got meta global with modified = 1591306651.68; last-modified = 1591306651.68
06-04 14:54:04.107 10608 10649 I sync15::state: Have info/collections and meta/global. Computing new engine states
06-04 14:54:04.107 10608 10649 D sync15::state: compute_engine_states: input EngineStateInput { local_declined: {}, remote: Some(RemoteEngineState { info_collections: {"addons", "passwords", "forms", "addresses", "meta", "crypto", "clients", "tabs", "history", "prefs"}, declined: {"bookmarks"} }), user_changes: {"forms": true, "tabs": false, "passwords": true, "bookmarks": true, "history": true} }
06-04 14:54:04.107 10608 10649 D sync15::state: compute_engine_states: output EngineStateOutput { declined: {"tabs"}, changes_needed: EngineChangesNeeded { local_resets: {"tabs"}, remote_wipes: {"tabs"} } }
06-04 14:54:04.108 10608 10649 I sync15::state: Uploading new declined ["tabs"] to meta/global with timestamp ServerTimestamp(1591306651680)
06-04 14:54:04.108 10608 10649 D sync15::state: SyncID for engine "bookmarks" was missing
06-04 14:54:04.108 10608 10649 D sync15::state: SyncID for engine "tabs" was present, but shouldn't be
06-04 14:54:04.108 10608 10649 I sync15::state: Uploading corrected meta/global with timestamp ServerTimestamp(1591306651680)
--
--
06-04 14:54:04.301 10608 10649 I sync15::client: Successful request to "/1.5/80491671/storage/crypto/keys", incoming x-last-modified=ServerTimestamp(1546736573710)
06-04 14:54:04.301 10608 10649 D sync15::sync_multiple: Declined engines list after state machine set to: Some(["tabs"])
06-04 14:54:04.301 10608 10649 I sync15::sync_multiple: Engine "tabs" just got disabled locally, wiping server
06-04 14:54:04.301 10608 10649 D sync15::client: Wiping: "https://sync-534-us-west-2.sync.services.mozilla.com/1.5/80491671/storage/tabs"
--
--
06-04 14:54:04.446 10608 10649 I sync15::client: Successful request to "/1.5/80491671/storage/tabs", incoming x-last-modified=ServerTimestamp(0)
06-04 14:54:04.447 10608 10649 I sync15::sync_multiple: Resetting engine tabs, as it was declined remotely
06-04 14:54:04.447 10608 10649 I sync15::sync_multiple: Synchronizing clients engine
06-04 14:54:04.447 10608 10649 I sync15::clients::engine: Syncing collection clients
--
--
06-04 14:54:05.368 10608 10649 I sync15::sync: Upload success (0 records success, 0 records failed)
06-04 14:54:05.368 10608 10649 D logins::db: Updating last sync to 1591307252.16
06-04 14:54:05.372 10608 10649 D sql_support::conn_ext: Transaction commited after 3.844817ms
06-04 14:54:05.372 10608 10649 I sync15::sync: Sync finished!
06-04 14:54:05.372 10608 10649 I sync15::sync_multiple: Sync of passwords was successful!
06-04 14:54:05.372 10608 10649 I sync15::sync_multiple: The tabs engine is declined. Skipping
06-04 14:54:05.372 10608 10649 I sync15::sync_multiple: Finished syncing stores.
06-04 14:54:05.372 10608 10649 D sync15::sync_multiple: sync was successful, final status=Ok
06-04 14:54:05.372 10608 10649 I sync_manager::manager: Sync finished with status Ok
06-04 14:54:05.372 10608 10649 I sync_manager::manager: engine "passwords" status: Ok(())
06-04 14:54:05.372 10608 10649 I sync_manager::manager: engine "bookmarks" status: Ok(())
--
--
06-04 14:54:05.382 10608 10649 I SyncWorker: Successfully synced bookmarks
06-04 14:54:05.382 10608 10649 I SyncWorker: Successfully synced history
06-04 14:54:05.382 10608 10649 I SyncWorker: Successfully synced passwords
06-04 14:54:05.382 10608 10649 I SyncWorker: Declined engines: [mozilla.components.service.fxa.SyncEngine$Tabs@5cf8f14]
06-04 14:54:05.382 10608 10649 I SyncWorker: Accepted engines: [mozilla.components.service.fxa.SyncEngine$History@f941081, mozilla.components.service.fxa.SyncEngine$Bookmarks@3d88526, mozilla.components.service.fxa.SyncEngine$Passwords@d267567]
06-04 14:54:05.389 10608 10644 I WM-WorkerWrapper: Worker result SUCCESS for Work [ id=1f2c257e-c528-4f15-8a87-388fda4249fb, tags={ Immediate, mozilla.components.service.fxa.sync.WorkManagerSyncWorker, Common } ]
--

grigoryk commented 4 years ago

The reason for accidentally enabling the bookmarks engines looks straighforward and isn't a bug in itself:

in a-c, we took the incorrectly empty declined list returned during the sync at face value, and remembered it. So 'bookmarks' is now considered to be enabled
this incorrect state is then passed along to the sync manager via enabledChanges in subsequent syncs that toggle an engine state; this map is only computed in case of a first sync or in response to a user action to toggle a sync engine.

So, we've just propagated globally incorrect state that the user observed in fenix's Account Settings.

rfk commented 4 years ago

06-04 14:38:09.826 10608 10729 E sync15::sync_multiple: Failed to parse PersistedGlobalState from JSON! Falling back to default

Hrm, ^ seems like a promising lead

rfk commented 4 years ago

From a scan of the logs here:

A sync attempt hits an error parsing PersistedGlobalState, falls back to default (in which the declined list is empty).
The sync attempt proceeds, and knows (I guess from server data?) that the bookmarks engine is declined, so it doesn't sync it.
- But it also doesn't propagate this information back to the caller, so the Fenix app comes to believe there are no declined engines.
When the user edits their engine choices in Fenix, it overwrites the data on the serve with its (incorrect) view of the user's data choices.

So two things to investigate:

Why did syncmanager fail to parse the persisted global state?
Why did syncmanager not propagate the declined engine back out to the app?

liuche commented 4 years ago

Also see https://github.com/mozilla/application-services/issues/2161 - this seems to be a problem that has been happening for a while.

We need to get this fixed, because overwriting users' engine sync choices is destructive and also just bad in general.

mhammond commented 4 years ago

More diagnosis of this specific issue in https://github.com/mozilla/application-services/issues/3205, plus a PR in https://github.com/mozilla/application-services/pull/3220 (although that PR is really only a partial fix - there's still multiple syncs happening that shouldn't be)

mhammond commented 4 years ago

https://github.com/mozilla/application-services/pull/3220 landed a fix for this (although https://github.com/mozilla-mobile/android-components/issues/7335 was a contributing factor)

grigoryk commented 4 years ago

While this shouldn't be reproduce-able anymore, I'll get a fix for #7335 in place before closing this.

jonalmeida commented 2 years ago

Closing this as fixed since the upstream issue was also fixed.

mozilla-mobile / android-components

Declined/Accepted SyncEngines not updated properly upon new device connection #7233