Firefox-ios: FXIOS-423 ⁃ [Sync Tests] Sync process does not seem to work using Stage server

[isabelrios]

Steps to reproduce

1-Log in with a stage account
2-Go to Settings and wait until you see the Sync Now label, tap on it again
3-Go to Bookmarks

Expected behavior

The bookmark appears

Actual behavior

The bookmark is not synced. Upon tapping on Sync Now briefly shows Syncing
Please see video attached:
https://youtu.be/odZCxvVxJ4g

Note: This is not reproducible manually. Only when using stage server when running the automated tests

All sync integration tests are failing due to that and PR #6508 is blocked due to this.

┆Issue is synchronized with this Jira Task

[isabelrios]

Hi @rfk, are you aware of any change on stage server that may be causing this? thanks!

[rfk]

No recent changes that come to mind. Are you able to get any logs from the device when running the failing test? If you send me a zip of the logs I'm happy to comb through and look for any clues.

[isabelrios]

@rfk Thanks for you quick response :) here you have some logs:

2020-05-08 17:29:10.049 [Debug] [SentryIntegration.swift:185] printMessage(message:extra:) > Sentry: Failed to register for APNS 2020-05-08 17:29:10.245 [Error] [StorageClient.swift:406] getFailureInfo(_:_:) > Response: 0. Got error Error Domain=NSURLErrorDomain Code=-1202 "The certificate for this server is invalid. You might be connecting to a server that is pretending to be “sync-4-us-east-1.stage.mozaws.net” which could put your confidential information at risk." UserInfo={NSURLErrorFailingURLPeerTrustErrorKey=<SecTrustRef: 0x600002b65830>, NSLocalizedRecoverySuggestion=Would you like to connect to the server anyway?, _kCFStreamErrorDomainKey=3, _kCFStreamErrorCodeKey=-9814, NSErrorPeerCertificateChainKey=( "<cert(0x7faf1e9b1400) s: *.stage.mozaws.net i: DigiCert SHA2 Secure Server CA>", "<cert(0x7faf1e96a400) s: DigiCert SHA2 Secure Server CA i: DigiCert Global Root CA>" ), NSUnderlyingError=0x60000156f5d0 {Error Domain=kCFErrorDomainCFNetwork Code=-1202 "(null)" UserInfo={_kCFStreamPropertySSLClientCertificateState=0, kCFStreamPropertySSLPeerTrust=<SecTrustRef: 0x600002b65830>, _kCFNetworkCFStreamSSLErrorOriginalValue=-9814, _kCFStreamErrorDomainKey=3, _kCFStreamErrorCodeKey=-9814, kCFStreamPropertySSLPeerCertificates=( "<cert(0x7faf1e9b1400) s: *.stage.mozaws.net i: DigiCert SHA2 Secure Server CA>", "<cert(0x7faf1e96a400) s: DigiCert SHA2 Secure Server CA i: DigiCert Global Root CA>" )}}, NSLocalizedDescription=The certificate for this server is invalid. You might be connecting to a server that is pretending to be “sync-4-us-east-1.stage.mozaws.net” which could put your confidential information at risk., NSErrorFailingURLKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, NSErrorFailingURLStringKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, NSErrorClientCertificateStateKey=0}. 2020-05-08 17:29:10.245 [Error] [StorageClient.swift:415] getFailureInfo(_:_:) > Filling generic RequestError. 2020-05-08 17:29:10.245 [Info] [Profile.swift:639] endSyncing(_:) > Ending all queued syncs. 2020-05-08 17:29:10.245 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid. 2020-05-08 17:29:10.246 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs.

Hope that helps, if not I will try to get better ones with more info if possible

[rfk]

Oh, wow. I'm getting a similar error when I try to access https://sync-4-us-east-1.stage.mozaws.net directly in the browser. Looks like it may be an Ops issue with the certificates on that host, I'll escalate into an Ops bug.

(Edit: filed as https://bugzilla.mozilla.org/show_bug.cgi?id=1637171)

[isabelrios]

I don't get that error anymore @rfk, I think that issue is solved for us from that part. If I go to that link I see:
"It Works! SyncStorage is successfully running on this host."

But, tests does not work yet. There may be also something on iOS side @garvankeeley. The error after trying to sync manually using sim and stage is this:
2020-05-18 18:03:55.284 [Info] [Profile.swift:1121] syncWith(synchronizers:statsSession:why:) > Syncing ["clients", "tabs", "bookmarks", "history", "logins"] 2020-05-18 18:03:55.288 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid. 2020-05-18 18:03:55.313 [Debug] [SyncStateMachine.swift:153] toReady(_:) > Got token from auth state. 2020-05-18 18:03:55.313 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs. 2020-05-18 18:03:55.313 [Info] [SyncStateMachine.swift:159] toReady(_:) > No persisted Sync state. Starting over. 2020-05-18 18:03:55.314 [Info] [SyncStateMachine.swift:194] toReady(_:) > Advancing to InitialWithLiveToken. 2020-05-18 18:03:55.314 [Info] [SyncStateMachine.swift:339] init(scratchpad:token:) > Inited initialWithLiveToken 2020-05-18 18:03:55.314 [Info] [SyncStateMachine.swift:122] advanceFromState(_:) > advanceFromState: InitialWithLiveToken 2020-05-18 18:03:55.315 [Info] [Profile.swift:644] endSyncing(_:) > Ending all queued syncs. 2020-05-18 18:03:55.315 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid. 2020-05-18 18:03:55.315 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs. failed to register. Error Domain=NSCocoaErrorDomain Code=3010 "remote notifications are not supported in the simulator" UserInfo={NSLocalizedDescription=remote notifications are not supported in the simulator} 2020-05-18 18:03:55.343 [Debug] [SentryIntegration.swift:185] printMessage(message:extra:) > Sentry: Failed to register for APNS

Does it ring any bell? Thanks!

[garvankeeley]

I don't see anything that looks like an error there. remote notifications are not supported in the simulator error is correct.
No scratchpad found in prefs. failed to register I don't know if that is a problem, or is it a normal initial state

[isabelrios]

Latest logs:
1-Login with account
2-Once it is shown in Settings, I clicked on Sync Now button to force the sync

2020-06-25 18:49:34.831 [Debug] [Profile.swift:869] beginTimedSyncs() > Already running sync timer.
2020-06-25 18:49:34.832 [Info] [Profile.swift:1121] syncWith(synchronizers:statsSession:why:) > Syncing ["clients", "tabs", "bookmarks", "history", "logins"]
2020-06-25 18:49:34.870 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid.
2020-06-25 18:49:34.898 [Debug] [SyncStateMachine.swift:153] toReady(_:) > Got token from auth state.
2020-06-25 18:49:34.898 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs.
2020-06-25 18:49:34.898 [Info] [SyncStateMachine.swift:159] toReady(_:) > No persisted Sync state. Starting over.
2020-06-25 18:49:34.898 [Info] [SyncStateMachine.swift:194] toReady(_:) > Advancing to InitialWithLiveToken.
2020-06-25 18:49:34.898 [Info] [SyncStateMachine.swift:339] init(scratchpad:token:) > Inited initialWithLiveToken
2020-06-25 18:49:34.898 [Info] [SyncStateMachine.swift:122] advanceFromState(_:) > advanceFromState: InitialWithLiveToken
failed to register. Error Domain=NSCocoaErrorDomain Code=3010 "remote notifications are not supported in the simulator" UserInfo={NSLocalizedDescription=remote notifications are not supported in the simulator}
2020-06-25 18:49:34.901 [Debug] [SentryIntegration.swift:186] printMessage(message:extra:) > Sentry: Failed to register for APNS 
2020-06-25 18:49:34.903 [Error] [StorageClient.swift:406] getFailureInfo(_:_:) > Response: 0. Got error Error Domain=NSURLErrorDomain Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSUnderlyingError=0x600002ee0bd0 {Error Domain=kCFErrorDomainCFNetwork Code=-1003 "(null)" UserInfo={_kCFStreamErrorCodeKey=8, _kCFStreamErrorDomainKey=12}}, NSErrorFailingURLStringKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, NSErrorFailingURLKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, _kCFStreamErrorDomainKey=12, _kCFStreamErrorCodeKey=8, NSLocalizedDescription=A server with the specified hostname could not be found.}.
2020-06-25 18:49:34.903 [Error] [StorageClient.swift:415] getFailureInfo(_:_:) > Filling generic RequestError.
2020-06-25 18:49:34.904 [Info] [Profile.swift:644] endSyncing(_:) > Ending all queued syncs.
2020-06-25 18:49:34.904 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid.
2020-06-25 18:49:34.904 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs.
failed to register. Error Domain=NSCocoaErrorDomain Code=3010 "remote notifications are not supported in the simulator" UserInfo={NSLocalizedDescription=remote notifications are not supported in the simulator}
2020-06-25 18:49:34.938 [Debug] [SentryIntegration.swift:186] printMessage(message:extra:) > Sentry: Failed to register for APNS 
2020-06-25 18:49:45.167 [Info] [Profile.swift:1121] syncWith(synchronizers:statsSession:why:) > Syncing ["clients", "tabs", "bookmarks", "history", "logins"]
2020-06-25 18:49:45.172 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid.
2020-06-25 18:49:45.204 [Debug] [SyncStateMachine.swift:153] toReady(_:) > Got token from auth state.
2020-06-25 18:49:45.204 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs.
2020-06-25 18:49:45.204 [Info] [SyncStateMachine.swift:159] toReady(_:) > No persisted Sync state. Starting over.
2020-06-25 18:49:45.204 [Info] [SyncStateMachine.swift:194] toReady(_:) > Advancing to InitialWithLiveToken.
2020-06-25 18:49:45.204 [Info] [SyncStateMachine.swift:339] init(scratchpad:token:) > Inited initialWithLiveToken
2020-06-25 18:49:45.204 [Info] [SyncStateMachine.swift:122] advanceFromState(_:) > advanceFromState: InitialWithLiveToken
failed to register. Error Domain=NSCocoaErrorDomain Code=3010 "remote notifications are not supported in the simulator" UserInfo={NSLocalizedDescription=remote notifications are not supported in the simulator}
2020-06-25 18:49:45.207 [Debug] [SentryIntegration.swift:186] printMessage(message:extra:) > Sentry: Failed to register for APNS 
2020-06-25 18:49:45.208 [Error] [StorageClient.swift:406] getFailureInfo(_:_:) > Response: 0. Got error Error Domain=NSURLErrorDomain Code=-1003 "A server with the specified hostname could not be found." UserInfo={NSUnderlyingError=0x600002d2b5d0 {Error Domain=kCFErrorDomainCFNetwork Code=-1003 "(null)" UserInfo={_kCFStreamErrorCodeKey=8, _kCFStreamErrorDomainKey=12}}, NSErrorFailingURLStringKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, NSErrorFailingURLKey=https://sync-4-us-east-1.stage.mozaws.net/1.5/4969246/info/collections, _kCFStreamErrorDomainKey=12, _kCFStreamErrorCodeKey=8, NSLocalizedDescription=A server with the specified hostname could not be found.}.
2020-06-25 18:49:45.209 [Error] [StorageClient.swift:415] getFailureInfo(_:_:) > Filling generic RequestError.
2020-06-25 18:49:45.209 [Info] [Profile.swift:644] endSyncing(_:) > Ending all queued syncs.
2020-06-25 18:49:45.209 [Info] [SyncAuthState.swift:137] token(_:canBeExpired:) > Returning cached token, which should be valid.
2020-06-25 18:49:45.209 [Debug] [State.swift:549] restoreFromPrefs(_:syncKeyBundle:) > No scratchpad found in prefs.

[garvankeeley]

"A server with the specified hostname could not be found." @eoger @rfk
We use the constant supplied by app-services https://github.com/mozilla-mobile/firefox-ios/blob/7e7aebb8166428b3b3635f59f63964ba7bc6aeee/RustFxA/RustFirefoxAccounts.swift#L119

[rfk]

Thanks for the bump, I bet one of the stage sync storage nodes has gone down or changed configuration somehow. I'll follow up with ops and report back here.

[rfk]

Ref https://bugzilla.mozilla.org/show_bug.cgi?id=1648581 for followup, but if you don't want to follow in bugzilla, I will reflect important updates back here.

[rfk]

From the video at the top of this bug, it looks like this test may be signing in using a fixed email address of "[email protected]", as defined here. I suspect that this user is assigned to a now-dead storage node in stage.

It's not good that the stage servers allow your account to continue to exist in this state, but there is a way to work around it: manually delete and re-create this account via https://accounts.stage.mozaws.net/ and then try running the tests again. This should cause the new user account to be allocated to a new and functioning storage node.

(This assumes that you don't have any valuable data synced to that account, but given that the entire storage node seems to be dead, any such data is probably gone already...)

[isabelrios]

Thanks @rfk, you are right, that's a fixed account I use to degub the tests. I did what you suggested and that account is working fine. But, the strange things continue...for the tests we create a new account each time, like: email='[email protected]', password='qfTcMcii'

With this account, I see this screen, the sync does not work yet.. :( this error is reported:

JSON error: missing fieldlocaleat line 1 column 239) 2020-06-26 18:04:25.252 [Debug] [Profile.swift:869] beginTimedSyncs() > Already running sync timer. failed to register. Error Domain=NSCocoaErrorDomain Code=3010 "remote notifications are not supported in the simulator" UserInfo={NSLocalizedDescription=remote notifications are not supported in the simulator} 2020-06-26 18:04:25.263 [Debug] [SentryIntegration.swift:186] printMessage(message:extra:) > Sentry: Failed to register for APNS
@garvankeeley any new idea looking at these logs?

I'm sorry for keeping you guys busy with this, looks like one error after another, I don't really know how to get to the bottom of this, but my feeling is that there is something going on. Also because we have had these tests working for long time pretty stable but after all the big changes that have happened behind the scenes, they are completely broken :(
Thanks in advance for your help with this!

[eoger]

It seems to me we're failing to deserialize the Profile::locale field, indeed while going on the fxa server I've noticed this field can be null. I'll make a patch here.

[isabelrios]

Thanks @eoger that has fixed the issue on iOS side and now the testing accounts created work fine \o/ thanks for your help!