Connection fails to reconnect

[MaxBG92]

Hey there,

I've hit a weird case where the connection fails to restart in some cases:

The way I was able to consistently reproduce it is: Start a connection Go to background Disable WiFi Reopen the app (Fails to reconnect as expected) Go to background again Enable WiFi Reopen app

I get this:

2021-10-07 16:35:48.607192+0300[3184:2277978] [hubService] Starting hub connection
2021-10-07 16:35:48.607835+0300[3184:2277978] [hubService] Starting reconnectable connection
2021-10-07 16:35:48.608513+0300[3184:2277978] [hubService] Attempting to chage state from: 'disconnected' to: 'starting'
2021-10-07 16:35:48.609287+0300[3184:2277978] [hubService] Changing state to: 'starting' failed
2021-10-07 16:35:48.609965+0300[3184:2277978] [hubService] Reconnectable connection not in the disconnected state. Ignoring start request

I debugged it and it appears the connection state at that point is stuck at .stopping but I was unable to figure out what exactly is causing the issue and how to fix it, was able to get around it by adding .stopping in the .start() of ReconnectableConnection: changeState(from:[.disconnected, .stopping], to: .starting) != nil

This is what is going on on app events:

@objc func handleNotification(notification: NSNotification) {
        if notification.name == UIApplication.didEnterBackgroundNotification {
            ds_log(.info, log: .hubService, "Application entered background. Stopping the HubService.")
            self._orgHub?.stop()
        } else if notification.name == UIApplication.willEnterForegroundNotification {
            ds_log(.info, log: .hubService, "Application entered foreground. Starting the HubService.")
            self._orgHub?.start()
        }
    }

And this is the whole log:

2021-10-07 16:35:05.217605+0300 ------[3184:2277978] [hubService] Application entered background. AuthService will timeout the active session in 10 minutes.
2021-10-07 16:35:05.217798+0300 ------[3184:2277978] [hubService] Application entered background. Stopping the HubService.
2021-10-07 16:35:05.217971+0300 ------[3184:2277978] [hubService] Stopping hub connection
2021-10-07 16:35:05.218131+0300 ------[3184:2277978] [hubService] Received connection stop request
2021-10-07 16:35:05.218312+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopping'
2021-10-07 16:35:05.218472+0300 ------[3184:2277978] [hubService] Changing state to: 'stopping' succeeded
2021-10-07 16:35:05.218622+0300 ------[3184:2277978] [hubService] Stopping connection
2021-10-07 16:35:05.218779+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2021-10-07 16:35:05.218937+0300 ------[3184:2277978] [hubService] Changing state to: 'stopped' succeeded
2021-10-07 16:35:05.221249+0300 ------[3184:2278164] [hubService] WebSocket close. Clean: true, code: 1000, reason: Normal Closure
2021-10-07 16:35:05.221485+0300 ------[3184:2278164] [hubService] Transport closed
2021-10-07 16:35:05.221664+0300 ------[3184:2278164] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2021-10-07 16:35:05.221825+0300 ------[3184:2278164] [hubService] Changing state to: 'stopped' succeeded
2021-10-07 16:35:05.221983+0300 ------[3184:2278164] [hubService] Previous state stopped
2021-10-07 16:35:05.222141+0300 ------[3184:2278164] [hubService] Invoking connectionDidClose (transportDidClose(_:): 267)
2021-10-07 16:35:05.442651+0300 ------[3184:2277978] [hubService] Connection closed
2021-10-07 16:35:05.442802+0300 ------[3184:2277978] [hubService] Attempting to chage state from: 'running' to: 'reconnecting'
2021-10-07 16:35:05.442912+0300 ------[3184:2277978] [hubService] Changing state to: 'reconnecting' failed
2021-10-07 16:35:05.443007+0300 ------[3184:2277978] [hubService] Assuming clean stop - stopping connection
2021-10-07 16:35:05.443099+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'disconnected'
2021-10-07 16:35:05.443188+0300 ------[3184:2277978] [hubService] Changing state to: 'disconnected' succeeded
2021-10-07 16:35:05.443771+0300 ------[3184:2277978] [hubService] HubConnection closing with error: nil
2021-10-07 16:35:05.443900+0300 ------[3184:2277978] [hubService] Terminating 0 pending hub methods
2021-10-07 16:35:05.444443+0300 ------[3184:2277978] [hubService] Connection did close
2021-10-07 16:35:32.497320+0300 ------[3184:2277978] [hubService] Application entered foreground. < 10 minutes elapsed. AuthService will resume the active session.
2021-10-07 16:35:32.497955+0300 ------[3184:2277978] [hubService] Application entered foreground. Starting the HubService.
2021-10-07 16:35:32.498668+0300 ------[3184:2277978] [hubService] Starting hub connection
2021-10-07 16:35:32.499413+0300 ------[3184:2277978] [hubService] Starting reconnectable connection
2021-10-07 16:35:32.500157+0300 ------[3184:2277978] [hubService] Attempting to chage state from: 'disconnected' to: 'starting'
2021-10-07 16:35:32.500900+0300 ------[3184:2277978] [hubService] Changing state to: 'starting' succeeded
2021-10-07 16:35:32.501637+0300 ------[3184:2277978] [hubService] Starting or reconnecting
.502647+0300 ------[3184:2277978] [hubService] HttpConnection init
2021-10-07 16:35:32.503493+0300 ------[3184:2277978] [hubService] HttpConnection deinit
2021-10-07 16:35:32.504477+0300 ------[3184:2277978] [hubService] Starting connection
2021-10-07 16:35:32.505160+0300 ------[3184:2277978] [hubService] Attempting to chage state from: 'initial' to: 'connecting'
2021-10-07 16:35:32.505829+0300 ------[3184:2277978] [hubService] Changing state to: 'connecting' succeeded
2021-10-07 16:35:32.506573+0300 ------[3184:2277978] [hubService] Selected WebSockets transport
2021-10-07 16:35:32.507316+0300 ------[3184:2277978] [hubService] Starting WebSocket transport
2021-10-07 16:35:32.546773+0300 ------[3184:2278164] [hubService] WebSocket error. Error: Network(The operation couldn’t be completed. Network is down)
2021-10-07 16:35:32.546995+0300 ------[3184:2278164] [hubService] Transport closed
2021-10-07 16:35:32.547122+0300 ------[3184:2278164] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2021-10-07 16:35:32.547221+0300 ------[3184:2278164] [hubService] Changing state to: 'stopped' succeeded
2021-10-07 16:35:32.547372+0300 ------[3184:2278164] [hubService] Previous state connecting
2021-10-07 16:35:32.547500+0300 ------[3184:2278164] [hubService] Leaving startDispatchGroup (transportDidClose(_:): 258)
2021-10-07 16:35:32.547596+0300 ------[3184:2278164] [hubService] Invoking connectionDidFailToOpen
2021-10-07 16:35:32.547808+0300 ------[3184:2278164] [hubService] WebSocket close. Clean: false, code: 0, reason:
2021-10-07 16:35:32.547899+0300 ------[3184:2278164] [hubService] Transport already marked as closed due to an error - ignoring close
2021-10-07 16:35:32.548751+0300 ------[3184:2277978] [hubService] Attempting to restart connection
2021-10-07 16:35:32.550926+0300 ------[3184:2277978] [hubService] nextAttemptInterval: seconds(10), RetryContext: RetryContext(failedAttemptsCount: 0, reconnectStartTime: 2021-10-07 13:35:32 +0000, error: Network(The operation couldn’t be completed. Network is down))
2021-10-07 16:35:32.551104+0300 ------[3184:2277978] [hubService] Scheduling reconnect attempt at: seconds(10)
2021-10-07 16:35:32.551739+0300 ------[3184:2277978] [hubService] Connection will reconnect due to error: Network(The operation couldn’t be completed. Network is down)
2021-10-07 16:35:38.659189+0300 ------[3184:2277978] [hubService] Application entered background. AuthService will timeout the active session in 10 minutes.
2021-10-07 16:35:38.659887+0300 ------[3184:2277978] [hubService] Application entered background. Stopping the HubService.
2021-10-07 16:35:38.660621+0300 ------[3184:2277978] [hubService] Stopping hub connection
2021-10-07 16:35:38.661109+0300 ------[3184:2277978] [hubService] Received connection stop request
2021-10-07 16:35:38.661408+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopping'
2021-10-07 16:35:38.662085+0300 ------[3184:2277978] [hubService] Changing state to: 'stopping' succeeded
2021-10-07 16:35:38.662407+0300 ------[3184:2277978] [hubService] Stopping connection
2021-10-07 16:35:38.662680+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2021-10-07 16:35:38.662959+0300 ------[3184:2277978] [hubService] Changing state to: 'stopped' succeeded
2021-10-07 16:35:38.663204+0300 ------[3184:2277978] [hubService] Connection already stopped
2021-10-07 16:35:48.605871+0300 ------[3184:2277978] [hubService] Application entered foreground. < 10 minutes elapsed. AuthService will resume the active session.
2021-10-07 16:35:48.606515+0300 ------[3184:2277978] [hubService] Application entered foreground. Starting the HubService.
2021-10-07 16:35:48.607192+0300 ------[3184:2277978] [hubService] Starting hub connection
2021-10-07 16:35:48.607835+0300 ------[3184:2277978] [hubService] Starting reconnectable connection
2021-10-07 16:35:48.608513+0300 ------[3184:2277978] [hubService] Attempting to chage state from: 'disconnected' to: 'starting'
2021-10-07 16:35:48.609287+0300 ------[3184:2277978] [hubService] Changing state to: 'starting' failed
2021-10-07 16:35:48.609965+0300 ------[3184:2277978] [hubService] Reconnectable connection not in the disconnected state. Ignoring start request
2021-10-07 16:35:48.646768+0300 ------[3184:2277978] [hubService] Starting or reconnecting
2021-10-07 16:35:48.646909+0300 ------[3184:2277978] [hubService] Aborting start/reconnect due to connection state: stopping
2021-10-07 16:36:15.183454+0300 ------[3184:2277978] [hubService] Application entered background. AuthService will timeout the active session in 10 minutes.
2021-10-07 16:36:15.184134+0300 ------[3184:2277978] [hubService] Application entered background. Stopping the HubService.
2021-10-07 16:36:15.184816+0300 ------[3184:2277978] [hubService] Stopping hub connection
2021-10-07 16:36:15.185496+0300 ------[3184:2277978] [hubService] Received connection stop request
2021-10-07 16:36:15.186512+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopping'
2021-10-07 16:36:15.187223+0300 ------[3184:2277978] [hubService] Changing state to: 'stopping' succeeded
2021-10-07 16:36:15.187854+0300 ------[3184:2277978] [hubService] Stopping connection
2021-10-07 16:36:15.188283+0300 ------[3184:2277978] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2021-10-07 16:36:15.188461+0300 ------[3184:2277978] [hubService] Changing state to: 'stopped' succeeded
2021-10-07 16:36:15.188586+0300 ------[3184:2277978] [hubService] Connection already stopped

[moozzyk]

Thanks for reporting this. I will try to see if I can reproduce this. Did you see this issue on a phone or in simulator?

Because iOS in general does not allow to keep the connection open when an applications in in the background applications I would recommend stopping the connection when the application is backgrounded rather than relying on reconnect. (Also see: #180)

[MaxBG92]

Both on device and simulator. And yes, I do stop it when going to background, but when trying to start it back up it fails saying: "Reconnectable connection not in the disconnected state. Ignoring start request" Since it is stuck on .stopping state

[moozzyk]

Thanks for confirming!

[moozzyk]

I think this is what is happening. After stop is invoked the ReconnectableConnection relies on the connectionDidClose callback to transition from the stopping state to the stopped state. However because the underlying connection was already stopped when the .stop was called the callback is not invoked leaving the ReconnectableConnection in the stopping state. This in turn prevent from starting the connection.

[MaxBG92]

That makes sense. Can I do anything on my end to prevent it from happening?

[moozzyk]

The workaround could be to create a new connection instance when the application is brought to foreground instead of restarting existing instance.