amplify-swift icon indicating copy to clipboard operation
amplify-swift copied to clipboard

Published 20 hours ago • verified publisher icon aws-amplify

DataStore does not restart after toggle airplane mode off and on

Open dpilch opened this issue 2 years ago • 2 comments

Describe the bug

The issue was originally reported in Discord. Customer states that this issue started appearing on iOS 15.6.

When using DataStore and airplane mode is switched to off and then back on DataStore will stop but not restart.

Appears to be related to https://github.com/aws-amplify/amplify-ios/pull/1901.

Steps To Reproduce

  1. Create basic app with DataStore and the default Todo schema
  2. In main app setup DataStore and verbose logging.
import SwiftUI
import Amplify
import AWSDataStorePlugin
import AWSAPIPlugin

class AppDelegate: NSObject, UIApplicationDelegate {
    func application(_ application: UIApplication, didFinishLaunchingWithOptions launchOptions: [UIApplication.LaunchOptionsKey : Any]? = nil) -> Bool {
        do {
            Amplify.Logging.logLevel = .verbose
            let apiPlugin = AWSAPIPlugin(modelRegistration: AmplifyModels());
            try Amplify.add(plugin: apiPlugin)
            let dataStorePlugin = AWSDataStorePlugin(modelRegistration: AmplifyModels())
            try Amplify.add(plugin: dataStorePlugin)
            try Amplify.configure()
            print("Amplify configured with DataStore plugin")
            Amplify.DataStore.start { result in print("DataStore started") }
        } catch {
            print("An error occurred setting up Amplify: \(error)")
        }
        
        return true
    }
}
@main
struct MyIosAppApp: App {
    @UIApplicationDelegateAdaptor(AppDelegate.self) var appDelegate

        var body: some Scene {
            WindowGroup {
                ContentView()
            }
        }
}
  1. Run app on physical device.
  2. Toggle airplane mode off then on. (Customer states this must be done when app is not in foreground, however I was able to reproduce the issue while the app is in foreground.
  3. Observe logs
  4. Create Todo on another client and observe that websocketDidReceiveMessage message is not present in logs

Expected behavior

DataStore should restart and reconnect.

Amplify Framework Version

1.28.0

Amplify Categories

DataStore

Dependency manager

Swift PM

Swift version

5.6.1

CLI version

9.2.1

Xcode version

13.4.1

Relevant log output

Log Messages 
2022-08-16 11:55:15.213919-0600 MyIosApp[592:18786] [tcp] nw_proto_tcp_route_init [C2.1.1:3] no mtu received
2022-08-16 11:55:15.215668-0600 MyIosApp[592:18786] [tcp] nw_proto_tcp_route_init [C1.1:2] no mtu received
2022-08-16 11:55:15.215695-0600 MyIosApp[592:18783] [StarscreamAdapter] viabilityChanged: false
2022-08-16 11:55:15.217068-0600 MyIosApp[592:18786] Connection 2: encountered error(1:53)
2022-08-16 11:55:15.346682-0600 MyIosApp[592:18783] [RealtimeConnectionProvider] Status: connected. Connectivity status: unsatisfied
2022-08-16 11:55:15.347913-0600 MyIosApp[592:18783] [RealtimeConnectionProvider] Connetion is stale. Pending reconnect on connectivity.
2022-08-16 11:55:18.353104-0600 MyIosApp[592:18718] [StarscreamAdapter] viabilityChanged: true
2022-08-16 11:55:18.356449-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] Status: connected. Connectivity status: satisfied
2022-08-16 11:55:18.357459-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] Connetion is stale. Disconnecting to begin reconnect.
2022-08-16 11:55:18.358073-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] Realtime connection is stale, disconnecting.
2022-08-16 11:55:18.358816-0600 MyIosApp[592:18786] [StarscreamAdapter] socket.disconnect
2022-08-16 11:55:18.361757-0600 MyIosApp[592:18786] ConnectionProviderError.connection
2022-08-16 11:55:18.446792-0600 MyIosApp[592:18786] ConnectionProviderError.connection
2022-08-16 11:55:18.447926-0600 MyIosApp[592:18786] ConnectionProviderError.connection
2022-08-16 11:55:18.448746-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] all subscriptions removed, disconnecting websocket connection.
2022-08-16 11:55:18.448835-0600 MyIosApp[592:18786] [StarscreamAdapter] socket.disconnect
2022-08-16 11:55:18.475772-0600 MyIosApp[592:18783] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] APIError: Subscription item event failed with error
Caused by:
connection
2022-08-16 11:55:18.475934-0600 MyIosApp[592:18783] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] [A320B3AA-3721-41AF-801F-51EDCBFF4AE3] - Failed
2022-08-16 11:55:18.476294-0600 MyIosApp[592:18783] [IncomingAsyncSubscriptionEventPublisher] API Subscription failed for model `Todo` with error: Subscription item event failed with error
2022-08-16 11:55:18.474199-0600 MyIosApp[592:18786] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] APIError: Subscription item event failed with error
Caused by:
connection
2022-08-16 11:55:18.478065-0600 MyIosApp[592:18908] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] APIError: Subscription item event failed with error
Caused by:
connection
2022-08-16 11:55:18.478550-0600 MyIosApp[592:18908] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] [1B36602E-CEFC-4358-9B31-C88B038DD075] - Failed
2022-08-16 11:55:18.478718-0600 MyIosApp[592:18786] [RetryableGraphQLSubscriptionOperation<MutationSync<AnyModel>>] [0D30E9EB-247F-4933-B94E-A108A57693FD] - Failed
2022-08-16 11:55:18.478721-0600 MyIosApp[592:18908] [IncomingAsyncSubscriptionEventPublisher] API Subscription failed for model `Todo` with error: Subscription item event failed with error
2022-08-16 11:55:18.478857-0600 MyIosApp[592:18786] [IncomingAsyncSubscriptionEventPublisher] API Subscription failed for model `Todo` with error: Subscription item event failed with error
2022-08-16 11:55:18.484004-0600 MyIosApp[592:18908] [IncomingAsyncSubscriptionEventToAnyModelMapper] Received completion: failure(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.497599-0600 MyIosApp[592:18908] [AWSModelReconciliationQueue] receiveCompletion: error: DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection
2022-08-16 11:55:18.501979-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: errored(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.506432-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(syncEngineActive, errored(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)) -> cleaningUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.508205-0600 MyIosApp[592:18908] [RemoteSyncEngine] New state: cleaningUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.509144-0600 MyIosApp[592:18908] [RemoteSyncEngine] respond(to:): cleaningUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.509979-0600 MyIosApp[592:18908] [AppSyncSubscriptionConnection] Unsubscribe 11465369-92AD-4B9D-9135-83DC3AE2FB92
2022-08-16 11:55:18.510977-0600 MyIosApp[592:18908] [AppSyncSubscriptionConnection] Unsubscribe 490F1325-9CFA-4BF6-AFA7-5C0BD46D2C2E
2022-08-16 11:55:18.514943-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] all subscriptions removed, disconnecting websocket connection.
2022-08-16 11:55:18.515079-0600 MyIosApp[592:18786] [StarscreamAdapter] socket.write - {"id":"11465369-92AD-4B9D-9135-83DC3AE2FB92","type":"stop"}
2022-08-16 11:55:18.515145-0600 MyIosApp[592:18786] [StarscreamAdapter] socket.disconnect
2022-08-16 11:55:18.516053-0600 MyIosApp[592:18908] [AppSyncSubscriptionConnection] Unsubscribe F9F4E6A6-1BAB-49AD-8280-7C2687060581
2022-08-16 11:55:18.516825-0600 MyIosApp[592:18908] [OutgoingMutationQueue] stopSyncingToCloud(_:)
2022-08-16 11:55:18.516961-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: receivedStop((Function))
2022-08-16 11:55:18.517419-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(requestingEvent, receivedStop((Function))) -> stopping((Function))
2022-08-16 11:55:18.517600-0600 MyIosApp[592:18908] [OutgoingMutationQueue] New state: stopping((Function))
2022-08-16 11:55:18.517948-0600 MyIosApp[592:18908] [RealtimeConnectionProvider] all subscriptions removed, disconnecting websocket connection.
2022-08-16 11:55:18.518089-0600 MyIosApp[592:18908] [RealtimeConnectionProvider] all subscriptions removed, disconnecting websocket connection.
2022-08-16 11:55:18.518375-0600 MyIosApp[592:18908] [StarscreamAdapter] socket.write - {"id":"490F1325-9CFA-4BF6-AFA7-5C0BD46D2C2E","type":"stop"}
2022-08-16 11:55:18.518414-0600 MyIosApp[592:18908] [StarscreamAdapter] socket.disconnect
2022-08-16 11:55:18.518471-0600 MyIosApp[592:18908] [StarscreamAdapter] socket.write - {"id":"F9F4E6A6-1BAB-49AD-8280-7C2687060581","type":"stop"}
2022-08-16 11:55:18.518515-0600 MyIosApp[592:18908] [StarscreamAdapter] socket.disconnect
2022-08-16 11:55:18.518973-0600 MyIosApp[592:18908] [OutgoingMutationQueue] respond(to:): stopping((Function))
2022-08-16 11:55:18.519048-0600 MyIosApp[592:18908] [OutgoingMutationQueue] doStop(completion:)
2022-08-16 11:55:18.519244-0600 MyIosApp[592:18908] [OutgoingMutationQueue] doStopWithoutNotifyingStateMachine(completion:)
2022-08-16 11:55:18.519523-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: doneStopping
2022-08-16 11:55:18.519717-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(stopping((Function)), doneStopping) -> stopped
2022-08-16 11:55:18.519897-0600 MyIosApp[592:18908] [OutgoingMutationQueue] New state: stopped
2022-08-16 11:55:18.520831-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: cleanedUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.521249-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(cleaningUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection), cleanedUp(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)) -> schedulingRestart(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.522119-0600 MyIosApp[592:18908] [RemoteSyncEngine] New state: schedulingRestart(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.522764-0600 MyIosApp[592:18908] [OutgoingMutationQueue] respond(to:): stopped
2022-08-16 11:55:18.523508-0600 MyIosApp[592:18908] [RemoteSyncEngine] respond(to:): schedulingRestart(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection)
2022-08-16 11:55:18.525283-0600 MyIosApp[592:18908] [AWSDataStorePlugin] StorageEngine completed with error: DataStoreError: Subscription item event failed with error
Caused by:
DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection
2022-08-16 11:55:18.526743-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: finished
2022-08-16 11:55:18.527300-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(schedulingRestart(DataStoreError: Subscription item event failed with error
Caused by:
APIError: Subscription item event failed with error
Caused by:
connection), finished) -> cleaningUpForTermination
2022-08-16 11:55:18.527720-0600 MyIosApp[592:18908] [RemoteSyncEngine] New state: cleaningUpForTermination
2022-08-16 11:55:18.527949-0600 MyIosApp[592:18908] [AWSDataStorePlugin] Stopping DataStore successful.
2022-08-16 11:55:18.528839-0600 MyIosApp[592:18908] [RemoteSyncEngine] respond(to:): cleaningUpForTermination
2022-08-16 11:55:18.529012-0600 MyIosApp[592:18908] [OutgoingMutationQueue] stopSyncingToCloud(_:)
2022-08-16 11:55:18.529748-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: receivedStop((Function))
2022-08-16 11:55:18.530118-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(stopped, receivedStop((Function))) -> stopping((Function))
2022-08-16 11:55:18.530708-0600 MyIosApp[592:18908] [OutgoingMutationQueue] New state: stopping((Function))
2022-08-16 11:55:18.531032-0600 MyIosApp[592:18908] [OutgoingMutationQueue] respond(to:): stopping((Function))
2022-08-16 11:55:18.531563-0600 MyIosApp[592:18908] [OutgoingMutationQueue] doStop(completion:)
2022-08-16 11:55:18.531817-0600 MyIosApp[592:18908] [OutgoingMutationQueue] doStopWithoutNotifyingStateMachine(completion:)
2022-08-16 11:55:18.531976-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: doneStopping
2022-08-16 11:55:18.532620-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(stopping((Function)), doneStopping) -> stopped
2022-08-16 11:55:18.533157-0600 MyIosApp[592:18908] [OutgoingMutationQueue] New state: stopped
2022-08-16 11:55:18.533422-0600 MyIosApp[592:18908] [StateMachine<State, Action>] Notifying: cleanedUpForTermination
2022-08-16 11:55:18.533939-0600 MyIosApp[592:18908] [StateMachine<State, Action>] resolve(cleaningUpForTermination, cleanedUpForTermination) -> terminate
2022-08-16 11:55:18.534815-0600 MyIosApp[592:18908] [RemoteSyncEngine] New state: terminate
2022-08-16 11:55:18.535087-0600 MyIosApp[592:18908] [OutgoingMutationQueue] respond(to:): stopped
2022-08-16 11:55:18.535338-0600 MyIosApp[592:18908] [RemoteSyncEngine] respond(to:): terminate
2022-08-16 11:55:19.154950-0600 MyIosApp[592:18786] [RealtimeConnectionProvider] Status: notConnected. Connectivity status: satisfied
2022-08-16 11:55:32.597647-0600 MyIosApp[592:18908] [RealtimeConnectionProvider] Status: notConnected. Connectivity status: satisfied
2022-08-16 11:55:33.234874-0600 MyIosApp[592:18908] [RealtimeConnectionProvider] Status: notConnected. Connectivity status: satisfied

Is this a regression?

Yes

Regression additional context

I haven't tested but customer states that this is new behavior in iOS 15.6.

Device

iPhone 11

iOS Version

15.6

Specific to simulators

No response

Additional context

No response

dpilch avatar Aug 16 '22 17:08 dpilch

From https://github.com/aws-amplify/amplify-ios/pull/1901

The fix here is for DataStorePlugin to stop the storage engine (in turn stops the sync engine and dereferences storage engine) when it receives a terminating event from the storage engine. This way, the non-retryable errors are not immediately retried. When a DataStore operation is performed at a later time, such as a save or a query, it will check if storage engine is there, if not it will create the storage engine and start the sync process. This avoids immediately/continuous retry when it encounters non-retrable errors, and allows the app to recover (for example, sync process goes through steps such as delta sync to get the latest data), without having the end-user or developer intervene by restarting the app or making calls to stop/clear/start on app lifecycle events like foregrounding.

So it appears that stopping DataStore is intentional to fix the issue in https://github.com/aws-amplify/amplify-ios/pull/1901. However, it is creating a different issue with subscriptions because it is waiting for an explicit DataStore operation (save/query/delete) to be called before restarting.

I don't think there is a workaround for this other than to explicitly call DataStore start after connectivity is restored to the device. The problem is that I don't think there is an appropriate trigger to listen to.

dpilch avatar Aug 16 '22 21:08 dpilch

what we'd like to verify is that, turning airplane mode on will stop the sync process successfully. As @dpilch mentioned, DataStore is not reacting to network events to restart the sync process. The expectation, and what we'd like to verify, is that turning off airplane mode, then calling DataStore.start explicitly or performing a DataStore operation will put DataStore into a sync active state.

lawmicha avatar Sep 26 '22 20:09 lawmicha

We were able to verify that toggling the wifi off and then back on causes DataStore's sync process to stop. Toggling the wifi off first doesn't do anything, but when the wifi is toggled back on, the error is then sent to DataStore

APIError: Subscription item event failed with error
Caused by: connection

DataStore then moves to a stopped state, it will not receive subscription events even though the network has already recovered. Calling DataStore.start does recover the system. The next steps for this is, how can we improve the time it takes for DataStore to recover? Can the sync process handle .connection problems or listen to Network Framework network status changes?

lawmicha avatar Oct 24 '22 21:10 lawmicha

I'm going to mark this as a feature request to improve the network reachability client in iOS as a way to recovery faster if it is able to detect network issues.

lawmicha avatar Oct 31 '22 19:10 lawmicha

This has been identified as a feature request. If this feature is important to you, we strongly encourage you to give a 👍 reaction on the request. This helps us prioritize new features most important to you. Thank you!

github-actions[bot] avatar Oct 31 '22 19:10 github-actions[bot]

Pending release on

  • main PR https://github.com/aws-amplify/amplify-swift/pull/2571
  • v1 PR https://github.com/aws-amplify/amplify-swift/pull/2581

lawmicha avatar Nov 17 '22 14:11 lawmicha

Both of the above PR are released, closing the ticket. Feel free to reopen the ticket or create a new one if you are still facing any issue.

royjit avatar Mar 09 '23 22:03 royjit