Fixing a bug when stopping a disconnected connection

[marwendoukh]

Problem Description

I faced an issue when the connection gets a stop request when it is in the disconnected state.
This could happen when switching the tab very quickly or getting the app in background and opening it quickly.
The connection will then not be able to restart.

Steps to reproduce

1. Start a connection

2. Stop the connection

3. Then call stop() again

4. Try to start the connection again : the connection could not be started, we get :

Reconnectable connection not in the disconnected state. Ignoring start request

Expected behaviour

The connection should be able to start again

Debugging informations

When calling stop() (ReconnectableConnection class) for the second time, it will change the state directly to stopping (without checking the current state).
Then it will call underlyingConnection.stop(stopError: stopError)
In the stop function (HttpConnection class), it will check if the connection is in the stopped state and will print a log message without continuing the rest of the function , that is why we do not get any callback after that and the connection will remain in the stopping state forever.

Suggested solution

Checking the current state of the connection before executing the stop process

Related issues

This Pull Request might could be related to #204 and #86

[moozzyk]

Can you provide logs for the original issue?

[moozzyk]

Can you add a test?

[marwendoukh]

Here is a sample code to reproduce the Problem:

self.connection.start()
DispatchQueue.main.asyncAfter(deadline: .now() + 2, execute: {
  self.connection.stop()
})
DispatchQueue.main.asyncAfter(deadline: .now() + 4, execute: {
   self.connection.stop()
 })
DispatchQueue.main.asyncAfter(deadline: .now() + 6, execute: {
    self.connection.start()
 })

here is the log:

2023-07-19T12:21:42.586Z debug: HttpConnection init
2023-07-19T12:21:42.588Z debug: HubConnection init
2023-07-19T12:21:42.588Z info: Starting hub connection
2023-07-19T12:21:42.588Z info: Starting reconnectable connection
2023-07-19T12:21:42.589Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2023-07-19T12:21:42.590Z debug: Changing state to: 'starting' succeeded
2023-07-19T12:21:42.590Z debug: Starting or reconnecting
2023-07-19T12:21:42.590Z debug: HttpConnection init
2023-07-19T12:21:42.590Z debug: HttpConnection deinit
2023-07-19T12:21:42.590Z info: Starting connection
2023-07-19T12:21:42.590Z debug: Attempting to change state from: 'initial' to: 'connecting'
2023-07-19T12:21:42.590Z debug: Changing state to: 'connecting' succeeded
2023-07-19T12:21:42.961Z debug: Negotiate completed with OK status code
2023-07-19T12:21:42.961Z debug: Negotiate response: {"negotiateVersion":1,"connectionId":"X","connectionToken":"X","availableTransports":[{"transport":"WebSockets","transferFormats":["Text","Binary"]},{"transport":"ServerSentEvents","transferFormats":["Text"]},{"transport":"LongPolling","transferFormats":["Text","Binary"]}]}
2023-07-19T12:21:42.962Z debug: Negotiation response received
2023-07-19T12:21:42.962Z info: Selected WebSockets transport
2023-07-19T12:21:42.962Z info: Starting WebSocket transport
2023-07-19T12:21:43.010Z debug: (ws) no auth challenge handler registered - falling back to default handling
2023-07-19T12:21:43.181Z info: urlSession didOpenWithProtocol invoked. WebSocket open
2023-07-19T12:21:43.181Z info: Transport started
2023-07-19T12:21:43.181Z debug: Attempting to change state from: 'connecting' to: 'connected'
2023-07-19T12:21:43.181Z debug: Changing state to: 'connected' succeeded
2023-07-19T12:21:43.181Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2023-07-19T12:21:43.181Z debug: Invoking connectionDidOpen
2023-07-19T12:21:43.181Z debug: Connection opened successfully
2023-07-19T12:21:43.181Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2023-07-19T12:21:43.181Z debug: Changing state to: 'running' succeeded
2023-07-19T12:21:43.181Z info: Hub connection started
2023-07-19T12:21:43.181Z debug: Sending handshake request: {"protocol": "json", "version": 1}�
2023-07-19T12:21:43.181Z info: Received send request
2023-07-19T12:21:43.181Z debug: Sending data
2023-07-19T12:21:43.273Z debug: Received data from transport
2023-07-19T12:21:43.274Z debug: Data received
2023-07-19T12:21:43.274Z debug: Processing handshake response: {}�
2023-07-19T12:21:43.274Z debug: Resetting keep alive
"connectionDidOpen"
2023-07-19T12:21:43.274Z debug: Payload contains 0 message(s)
2023-07-19T12:21:44.692Z info: Stopping hub connection
2023-07-19T12:21:44.692Z info: Received connection stop request
2023-07-19T12:21:44.692Z debug: Attempting to change state from: '(nil)' to: 'stopping'
2023-07-19T12:21:44.692Z debug: Changing state to: 'stopping' succeeded
2023-07-19T12:21:44.692Z info: Stopping connection
2023-07-19T12:21:44.692Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2023-07-19T12:21:44.693Z debug: Changing state to: 'stopped' succeeded
2023-07-19T12:21:44.696Z debug: urlSession didCloseWith invoked
2023-07-19T12:21:44.696Z info: WebSocket close. Code: 1000, reason:
2023-07-19T12:21:44.696Z debug: Marking transport as closed.
2023-07-19T12:21:44.696Z info: Transport closed
2023-07-19T12:21:44.696Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2023-07-19T12:21:44.696Z debug: urlSession didCompleteWithError invoked
2023-07-19T12:21:44.696Z debug: Changing state to: 'stopped' succeeded
2023-07-19T12:21:44.696Z debug: Previous state stopped
2023-07-19T12:21:44.696Z debug: error is nil - ignoring error
2023-07-19T12:21:44.696Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2023-07-19T12:21:44.696Z debug: Connection closed
2023-07-19T12:21:44.696Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2023-07-19T12:21:44.696Z debug: Changing state to: 'reconnecting' failed
2023-07-19T12:21:44.696Z debug: Assuming clean stop - stopping connection
2023-07-19T12:21:44.697Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2023-07-19T12:21:44.700Z debug: Changing state to: 'disconnected' succeeded
2023-07-19T12:21:44.700Z info: HubConnection closing with error: nil
2023-07-19T12:21:44.700Z info: Terminating 0 pending hub methods
"connectionDidClose"
2023-07-19T12:21:46.783Z info: Stopping hub connection
2023-07-19T12:21:46.783Z info: Received connection stop request
2023-07-19T12:21:46.783Z debug: Attempting to change state from: '(nil)' to: 'stopping'
2023-07-19T12:21:46.783Z debug: Changing state to: 'stopping' succeeded
2023-07-19T12:21:46.783Z info: Stopping connection
2023-07-19T12:21:46.783Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2023-07-19T12:21:46.783Z debug: Changing state to: 'stopped' succeeded
2023-07-19T12:21:46.783Z info: Connection already stopped
2023-07-19T12:21:48.883Z info: Starting hub connection
2023-07-19T12:21:48.883Z info: Starting reconnectable connection
2023-07-19T12:21:48.883Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2023-07-19T12:21:48.883Z debug: Changing state to: 'starting' failed
2023-07-19T12:21:48.883Z warning: Reconnectable connection not in the disconnected state. Ignoring start request

[moozzyk]

Thanks for providing the repro and the logs!

[marwendoukh]

@moozzyk I updated the code and added the Unit Test for this case

[moozzyk]

Thanks for the PR! LGTM!