1537749 - Deleting FxA account on desktop leaves app in state that appears connected

Status: NEW

(Firefox for iOS :: Firefox Accounts, defect, P2)

Description

[Simon Basca [:SimonB]]

Build: 3145a8
Device: iPhone 7
iOS: 12.1

Preconditions:

• Log in to FxA on iOS and desktop

Steps to reproduce:

1. On Desktop, go to Account management page
2. Delete the account
3. On iOS, perform a sync

Actual results:

• Before step 3) the app is left in a state where it still appears connected to a valid account. After syncing the app goes into a state where it looks like there was a password change (prompting the user to enter their password for the deleted account).

Note;

• After restarting the app and logging in to a different FxA on iOS you will see a manifestation of Bug 1529625.

Comment 1

[:garvan]

When in this state, I tap 'sync now', expected the account to become disconnected at that time. But the sync message doesn't tell the client the account is deleted:

2019-04-01 12:57:50.531 [Info] [SyncAuthState.swift:122] token(_:canBeExpired:) > Returning cached token, which should be valid.
2019-04-01 12:57:50.533 [Debug] [SyncStateMachine.swift:146] toReady > Got token from auth state.
2019-04-01 12:57:50.548 [Debug] [State.swift:458] unpickleV1FromPrefs(_:syncKeyBundle:) > Read keys from Keychain with label XMv9r01hjoTX.
2019-04-01 12:57:50.550 [Info] [SyncStateMachine.swift:186] toReady > Advancing to InitialWithLiveToken.
2019-04-01 12:57:50.551 [Info] [SyncStateMachine.swift:327] init(scratchpad:token:) > Inited initialWithLiveToken
2019-04-01 12:57:50.552 [Info] [SyncStateMachine.swift:120] advanceFromState > advanceFromState: InitialWithLiveToken
2019-04-01 12:57:50.856 [Debug] [StorageClient.swift:382] failFromResponse > Status code: 200.
2019-04-01 12:57:50.859 [Info] [SyncStateMachine.swift:327] init(scratchpad:token:) > Inited initialWithLiveTokenAndInfo
2019-04-01 12:57:50.861 [Info] [SyncStateMachine.swift:120] advanceFromState > advanceFromState: InitialWithLiveTokenAndInfo
2019-04-01 12:57:50.862 [Debug] [SyncStateMachine.swift:768] advance() > Cached meta/global fetched at 1554135083200, newer than server modified 1554134216160. Using cached meta/global.
2019-04-01 12:57:50.863 [Info] [SyncStateMachine.swift:311] init(client:scratchpad:token:) > Inited hasMetaGlobal
2019-04-01 12:57:50.865 [Info] [SyncStateMachine.swift:120] advanceFromState > advanceFromState: HasMetaGlobal
2019-04-01 12:57:50.866 [Debug] [SyncStateMachine.swift:857] advance() > Cached keys fetched at 1554135083300, newer than server modified 1554134216270. Using cached keys.
2019-04-01 12:57:50.867 [Info] [SyncStateMachine.swift:311] init(client:scratchpad:token:) > Inited hasFreshCryptoKeys
2019-04-01 12:57:50.868 [Info] [SyncStateMachine.swift:120] advanceFromState > advanceFromState: HasFreshCryptoKeys
2019-04-01 12:57:50.869 [Info] [SyncStateMachine.swift:311] init(client:scratchpad:token:) > Inited ready
2019-04-01 12:57:50.870 [Info] [SyncStateMachine.swift:120] advanceFromState > advanceFromState: Ready
2019-04-01 12:57:50.871 [Debug] [Profile.swift:1098] takeActionsOnEngineStateChanges > No collections need reset. Moving on.
2019-04-01 12:57:50.873 [Debug] [Profile.swift:1236] syncWith(synchronizers:account:statsSession:why:) > Syncing clients…
2019-04-01 12:57:50.874 [Debug] [Profile.swift:1036] syncClientsWithDelegate(_:prefs:ready:why:) > Syncing clients to storage.
2019-04-01 12:57:50.874 [Info] [Synchronizer.swift:203] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.clients...'
2019-04-01 12:57:50.875 [Debug] [ClientsSynchronizer.swift:395] synchronizeLocalClients(_:withServer:info:notifier:) > Synchronizing clients.
2019-04-01 12:57:50.876 [Debug] [StorageClient.swift:791] getSince(_:sort:limit:offset:) > Issuing GET with newer = 0, offset = nil, sort = nil.
2019-04-01 12:57:51.180 [Debug] [StorageClient.swift:382] failFromResponse > Status code: 200.
2019-04-01 12:57:51.186 [Debug] [ClientsSynchronizer.swift:330] applyStorageResponse(_:toLocalClients:withServer:notifier:) > Applying clients response.
2019-04-01 12:57:51.187 [Debug] [ClientsSynchronizer.swift:337] applyStorageResponse(_:toLocalClients:withServer:notifier:) > Got 2 client records.
2019-04-01 12:57:51.188 [Debug] [ClientsSynchronizer.swift:351] applyStorageResponse(_:toLocalClients:withServer:notifier:) > Skipping our own unmodified record.
2019-04-01 12:57:51.191 [Debug] [ClientsSynchronizer.swift:222] processCommandsFromRecord(_:withServer:) > Processing commands from downloaded record.
2019-04-01 12:57:51.192 [Debug] [ClientsSynchronizer.swift:306] maybeUploadOurRecord(_:ifUnmodifiedSince:toServer:) > Should we upload our client record? Caller = false, expired = false.
2019-04-01 12:57:51.194 [Debug] [ClientsSynchronizer.swift:380] applyStorageResponse(_:toLocalClients:withServer:notifier:) > Running 0 commands.
2019-04-01 12:57:51.195 [Debug] [Profile.swift:1046] syncClientsWithDelegate(_:prefs:ready:why:) > Updating FxA devices list.
2019-04-01 12:57:51.495 [Debug] [Profile.swift:1236] syncWith(synchronizers:account:statsSession:why:) > Syncing tabs…
2019-04-01 12:57:51.497 [Info] [Synchronizer.swift:203] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.tabs...'
2019-04-01 12:57:51.499 [Debug] [StorageClient.swift:791] getSince(_:sort:limit:offset:) > Issuing GET with newer = 1554135179980, offset = nil, sort = nil.
2019-04-01 12:57:51.572 [Debug] [StorageClient.swift:382] failFromResponse > Status code: 200.
2019-04-01 12:57:51.577 [Debug] [TabsSynchronizer.swift:119] afterWipe() > Got 1 tab records.
2019-04-01 12:57:51.579 [Debug] [TabsSynchronizer.swift:128] afterWipe() > Filtered 1 records down to 0.
2019-04-01 12:57:51.584 [Debug] [SQLiteRemoteClientsAndTabs.swift:237] getTabsForClientWithGUID > Looking for tabs for client with guid: nil
2019-04-01 12:57:51.586 [Debug] [SQLiteRemoteClientsAndTabs.swift:240] getTabsForClientWithGUID > Found 1 tabs for client with guid: nil
2019-04-01 12:57:51.587 [Debug] [Profile.swift:1236] syncWith(synchronizers:account:statsSession:why:) > Syncing logins…
2019-04-01 12:57:51.588 [Debug] [Profile.swift:1070] syncLoginsWithDelegate(_:prefs:ready:why:) > Syncing logins to storage.
2019-04-01 12:57:51.923 [Debug] [Profile.swift:1236] syncWith(synchronizers:account:statsSession:why:) > Syncing bookmarks…
2019-04-01 12:57:51.925 [Debug] [Profile.swift:1088] mirrorBookmarksWithDelegate(_:prefs:ready:why:) > Synchronizing server bookmarks to storage.
2019-04-01 12:57:51.926 [Info] [Synchronizer.swift:203] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.bookmarks...'
2019-04-01 12:57:51.928 [Debug] [Profile.swift:1367] greenLight() > Checking green light. Backgrounded: false.
2019-04-01 12:57:51.930 [Info] [Downloader.swift:45] init(collectionClient:basePrefs:collection:) > Downloader configured with prefs 'profile.sync.synchronizer.bookmarks..downloader.bookmarks..'.
2019-04-01 12:57:51.931 [Debug] [BookmarksDownloader.swift:127] go(info:greenLight:) > Downloading up to 100 records.
2019-04-01 12:57:51.933 [Debug] [Downloader.swift:127] go(_:limit:) > Modified: 1554134382820; last 1554134382820.
2019-04-01 12:57:51.934 [Debug] [Downloader.swift:129] go(_:limit:) > No more data to batch-download.
2019-04-01 12:57:51.935 [Info] [BookmarksDownloader.swift:151] go(info:greenLight:) > No new data. No need to continue batching.
2019-04-01 12:57:51.936 [Debug] [BookmarksSynchronizer.swift:202] synchronizeBookmarksToStorage(_:usingBuffer:withServer:info:greenLight:remoteClientsAndTabs:) > Validating completed buffer download.
2019-04-01 12:57:51.943 [Info] [BookmarksSynchronizer.swift:262] synchronizeBookmarksToStorage(_:usingBuffer:withServer:info:greenLight:remoteClientsAndTabs:) > Bookmark mirroring took 13913µs. Result was Completed
2019-04-01 12:57:51.943 [Debug] [Profile.swift:1236] syncWith(synchronizers:account:statsSession:why:) > Syncing history…
2019-04-01 12:57:51.945 [Debug] [Profile.swift:1060] syncHistoryWithDelegate(_:prefs:ready:why:) > Syncing history to storage.
2019-04-01 12:57:51.946 [Info] [Synchronizer.swift:203] init(scratchpad:delegate:basePrefs:why:collection:) > Synchronizer configured with prefs 'profile.sync.synchronizer.history...'
2019-04-01 12:57:51.947 [Debug] [Profile.swift:1367] greenLight() > Checking green light. Backgrounded: false.
2019-04-01 12:57:51.948 [Info] [Downloader.swift:45] init(collectionClient:basePrefs:collection:) > Downloader configured with prefs 'profile.sync.synchronizer.history..downloader.history..'.
2019-04-01 12:57:51.949 [Debug] [HistorySynchronizer.swift:260] synchronizeLocalHistory(_:withServer:info:greenLight:) > Advancing downloader lastModified to synchronizer lastFetched 1554137774090.
2019-04-01 12:57:51.952 [Debug] [Downloader.swift:127] go(_:limit:) > Modified: 1554137774090; last 1554137774090.
2019-04-01 12:57:51.953 [Debug] [Downloader.swift:129] go(_:limit:) > No more data to batch-download.
2019-04-01 12:57:51.953 [Info] [HistorySynchronizer.swift:231] onBatchResult > No new data. No need to continue batching.
2019-04-01 12:57:51.954 [Info] [HistorySynchronizer.swift:163] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Uploading 0 deleted places.
2019-04-01 12:57:51.955 [Debug] [IndependentRecordSynchronizer.swift:104] uploadRecords(_:lastTimestamp:storageClient:onUpload:) > No modified records to upload.
2019-04-01 12:57:51.957 [Info] [SQLiteHistory.swift:1125] attachVisitsTo(places:visitLimit:) > Attaching 0 places to 0 most recent visits
2019-04-01 12:57:51.957 [Info] [HistorySynchronizer.swift:174] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Uploading 0 modified places.
2019-04-01 12:57:51.958 [Info] [HistorySynchronizer.swift:125] uploadModifiedPlaces(_:lastTimestamp:fromStorage:withServer:) > Preparing upload…
2019-04-01 12:57:51.958 [Debug] [HistorySynchronizer.swift:188] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Done syncing. Work was done? false
2019-04-01 12:57:51.959 [Debug] [HistorySynchronizer.swift:190] uploadOutgoingFromStorage(_:lastTimestamp:withServer:) > Done.
2019-04-01 12:57:51.960 [Info] [Profile.swift:728] endSyncing > Ending all queued syncs.
Sync status for clients: completed(Sync.SyncEngineStatsSession)
Sync status for tabs: completed(Sync.SyncEngineStatsSession)
Sync status for logins: notStarted(Sync.SyncNotStartedReason.unknown)
Sync status for bookmarks: completed(Sync.SyncEngineStatsSession)
Sync status for history: completed(Sync.SyncEngineStatsSession)
Resolved sync display state: good
2019-04-01 12:57:51.961 [Info] [SyncAuthState.swift:122] token(_:canBeExpired:) > Returning cached token, which should be valid.
2019-04-01 12:57:51.971 [Debug] [State.swift:458] unpickleV1FromPrefs(_:syncKeyBundle:) > Read keys from Keychain with label XMv9r01hjoTX.
2019-04-01 12:57:51.979 [Debug] [SyncTelemetry.swift:52] send(ping:docType:) > Ping URL: https://incoming.telemetry.mozilla.org/submit/telemetry/3ABE6DDD-8201-4149-9CA2-C733E4D34B18/sync/Fennec/14.0/developer/1
2019-04-01 12:57:51.980 [Debug] [SyncTelemetry.swift:53] send(ping:docType:) > Ping payload: {"os":{"name":"iOS","version":"12.2","locale":"en_CA"},"events":[],"why":"schedule","syncs":[{"why":"syncNow","didLogin":false,"took":1086,"engines":[{"name":"clients","incoming":{"succeeded":1,"failed":0,"applied":1,"newFailed":0,"reconciled":0},"took":319},{"name":"tabs","took":88},{"name":"logins","status":"sync.not_started.reason.unknown"},{"name":"bookmarks","took":4},{"name":"history","took":7}],"devices":[{"version":"66.0.1","id":"2c339e09b9fb4ab853cd2c03fefc385eae4bd72130f20dc4c2432d6d0ea5c297","os":"Darwin"},{"version":"14.0","id":"af1e5dc6fd9c234238a488eb1799d0e123a6b5024c62874919a23441fefdd316","os":"iOS"}],"when":1554137870873}],"deviceID":"e35cfba4a8db148583fc862423b7852c46ed381720f4a91e21967696cc0210b3","uid":"58d0bea1c0d1d98635e225c38286f1e4","version":1}
2019-04-01 12:57:52.278 [Debug] [SyncTelemetry.swift:82] send(ping:docType:) > Ping response: 200.

Comment 2

[:garvan]

1. problem: account_destroyed push notification is never sent to iOS
   (need a handler here https://github.com/mozilla-mobile/firefox-ios/blob/19e64bfc73c862dad77a32c6f1b591ac9ef99b54/Account/FxAPushMessageHandler.swift#L265-L286)

2. problem post-sync: app acts like there was a password change