DataStore does not restart after toggle airplane mode off and on #2152

dpilch · 2022-08-16T17:57:33Z

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 #1901.

Steps To Reproduce

Create basic app with DataStore and the default Todo schema
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()
            }
        }
}

Run app on physical device.
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.
Observe logs
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

The text was updated successfully, but these errors were encountered:

dpilch · 2022-08-16T21:15:48Z

From #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 #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.

lawmicha · 2022-09-26T20:02:25Z

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 · 2022-10-24T21:05:54Z

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 · 2022-10-31T19:12:44Z

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.

github-actions · 2022-10-31T19:13:24Z

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!

lawmicha · 2022-11-17T14:33:43Z

Pending release on

royjit · 2023-03-09T22:48:35Z

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.

dpilch added bug Something isn't working datastore Issues related to the DataStore category regression Something that was working before stopped working after an upgrade. High priority issue. labels Aug 16, 2022

ameter mentioned this issue Aug 17, 2022

Error happened when I return back from offline mode and turn on the wifi, Also a crash happened if I restarted the data store again #2167

Closed

chrisbonifacio added p3 and removed p3 labels Sep 9, 2022

lawmicha assigned manaswi223 Sep 13, 2022

atierian mentioned this issue Sep 20, 2022

When I launch the app while the wifi is turned OFF, and turn ON the wifi, an unauthorized log message displayed #2323

Closed

lawmicha added p2 and removed p1 labels Oct 24, 2022

lawmicha unassigned manaswi223 Oct 31, 2022

lawmicha added feature-request Request a new feature improvement Code quality, testing, etc. and removed regression Something that was working before stopped working after an upgrade. High priority issue. p2 bug Something isn't working labels Oct 31, 2022

lawmicha mentioned this issue Nov 15, 2022

fix(datastore): retry on subscription connection error #2571

Merged

14 tasks

lawmicha self-assigned this Nov 17, 2022

lawmicha added the pending-release Code has been merged but pending release Code has been merged but pending release label Nov 17, 2022

albemala mentioned this issue Jan 12, 2023

DataStore doesn't load when starting the app in offline mode #2668

Closed

royjit closed this as completed Mar 9, 2023

github-actions bot removed the pending-release Code has been merged but pending release Code has been merged but pending release label Mar 9, 2023

ethan021021 mentioned this issue Apr 4, 2023

DataStore blocking main thread after toggling airplane mode on/off #2849

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DataStore does not restart after toggle airplane mode off and on #2152

DataStore does not restart after toggle airplane mode off and on #2152

dpilch commented Aug 16, 2022 •

edited

Loading

dpilch commented Aug 16, 2022

lawmicha commented Sep 26, 2022

lawmicha commented Oct 24, 2022

lawmicha commented Oct 31, 2022

github-actions bot commented Oct 31, 2022

lawmicha commented Nov 17, 2022

royjit commented Mar 9, 2023

DataStore does not restart after toggle airplane mode off and on #2152

DataStore does not restart after toggle airplane mode off and on #2152

Comments

dpilch commented Aug 16, 2022 • edited Loading

Describe the bug

Steps To Reproduce

Expected behavior

Amplify Framework Version

Amplify Categories

Dependency manager

Swift version

CLI version

Xcode version

Relevant log output

Is this a regression?

Regression additional context

Device

iOS Version

Specific to simulators

Additional context

dpilch commented Aug 16, 2022

lawmicha commented Sep 26, 2022

lawmicha commented Oct 24, 2022

lawmicha commented Oct 31, 2022

github-actions bot commented Oct 31, 2022

lawmicha commented Nov 17, 2022

royjit commented Mar 9, 2023

dpilch commented Aug 16, 2022 •

edited

Loading