invocationDidComplete not being called after network is disconnected

[MaxBG92]

Hello

Having trouble with invocations after the networks is disconnected. My expectation is that invocationDidComplete should be called with an error but it never does.

2022-03-30 17:23:20.328232+0300 ****[3808:1426624] [hubService] Connecting to hub server.
2022-03-30 17:23:20.329727+0300 ****[3808:1426624] [hubService] HttpConnection init
2022-03-30 17:23:20.330049+0300 ****[3808:1426624] [hubService] HubConnection init
2022-03-30 17:23:20.336749+0300 ****[3808:1426624] [hubService] Registering client side hub method: 'ErrorMessage'
2022-03-30 17:23:20.338246+0300 ****[3808:1426624] [hubService] Registering client side hub method: 'OrganizationJoined'
2022-03-30 17:23:20.338397+0300 ****[3808:1426624] [hubService] Connecting to hub.
2022-03-30 17:23:20.338521+0300 ****[3808:1426624] [hubService] Starting hub connection
2022-03-30 17:23:20.338632+0300 ****[3808:1426624] [hubService] Starting reconnectable connection
2022-03-30 17:23:20.340279+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'disconnected' to: 'starting'
2022-03-30 17:23:20.340425+0300 ****[3808:1426624] [hubService] Changing state to: 'starting' succeeded
2022-03-30 17:23:20.340538+0300 ****[3808:1426624] [hubService] Starting or reconnecting
2022-03-30 17:23:20.340648+0300 ****[3808:1426624] [hubService] HttpConnection init
2022-03-30 17:23:20.340762+0300 ****[3808:1426624] [hubService] HttpConnection deinit
2022-03-30 17:23:20.340882+0300 ****[3808:1426624] [hubService] Starting connection
2022-03-30 17:23:20.342365+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'initial' to: 'connecting'
2022-03-30 17:23:20.342504+0300 ****[3808:1426624] [hubService] Changing state to: 'connecting' succeeded
2022-03-30 17:23:20.342781+0300 ****[3808:1426624] [hubService] Selected WebSockets transport
2022-03-30 17:23:20.342958+0300 ****[3808:1426624] [hubService] Starting WebSocket transport
2022-03-30 17:23:20.916259+0300 ****[3808:1426882] [hubService] WebSocket open
2022-03-30 17:23:20.916357+0300 ****[3808:1426882] [hubService] Transport started
2022-03-30 17:23:20.916419+0300 ****[3808:1426882] [hubService] Attempting to chage state from: 'connecting' to: 'connected'
2022-03-30 17:23:20.916472+0300 ****[3808:1426882] [hubService] Changing state to: 'connected' succeeded
2022-03-30 17:23:20.916511+0300 ****[3808:1426882] [hubService] Leaving startDispatchGroup (transportDidOpen(connectionId:): 236)
2022-03-30 17:23:20.916549+0300 ****[3808:1426882] [hubService] Invoking connectionDidOpen
2022-03-30 17:23:20.971776+0300 ****[3808:1426624] [hubService] Connection opened successfully
2022-03-30 17:23:20.971857+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'starting, reconnecting' to: 'running'
2022-03-30 17:23:20.971914+0300 ****[3808:1426624] [hubService] Changing state to: 'running' succeeded
2022-03-30 17:23:20.971964+0300 ****[3808:1426624] [hubService] Hub connection started
2022-03-30 17:23:20.972013+0300 ****[3808:1426624] [hubService] Sending handshake request: {"protocol": "json", "version": 1}\^^
2022-03-30 17:23:20.972056+0300 ****[3808:1426624] [hubService] Received send request
2022-03-30 17:23:20.972092+0300 ****[3808:1426624] [hubService] Sending data
2022-03-30 17:23:21.090804+0300 ****[3808:1426876] [hubService] Received data from transport
2022-03-30 17:23:21.102523+0300 ****[3808:1426876] [hubService] Received data from transport
2022-03-30 17:23:21.133913+0300 ****[3808:1426624] [hubService] Data received
2022-03-30 17:23:21.133972+0300 ****[3808:1426624] [hubService] Processing handshake response: {}\^^
2022-03-30 17:23:21.134087+0300 ****[3808:1426624] [hubService] Connection did open.
2022-03-30 17:23:21.134135+0300 ****[3808:1426624] [hubService] Not scheduling sending keep alive - keep alive disabled

---- NETWORK DISCONNECTED ----


2022-03-30 17:26:16.021993+0300 ****[3808:1426624] [hubService] Invoking server side hub method: 'GetOrgsMobileSymbols'
2022-03-30 17:26:16.022231+0300 ****[3808:1426624] [hubService] Invoking server side hub method 'GetOrgsMobileSymbols' with 1 argument(s)
2022-03-30 17:26:16.022455+0300 ****[3808:1426624] [hubService] Creating invocation message for method: 'GetOrgsMobileSymbols', invocationId: 559
2022-03-30 17:26:16.022931+0300 ****[3808:1426624] [hubService] Received send request
2022-03-30 17:26:16.023170+0300 ****[3808:1426624] [hubService] Sending data
2022-03-30 17:26:16.028298+0300 ****[3808:1426624] [hubService] stopRoutingLocalSystems for mission completed.
2022-03-30 17:26:16.029639+0300 ****[3808:1426624] [hubService] Leaving mission: Test
2022-03-30 17:26:16.030629+0300 ****[3808:1426624] [hubService] Invoking server side hub method: 'LeaveMission'
2022-03-30 17:26:16.030850+0300 ****[3808:1426624] [hubService] Invoking server side hub method 'LeaveMission' with 1 argument(s)
2022-03-30 17:26:16.031063+0300 ****[3808:1426624] [hubService] Creating invocation message for method: 'LeaveMission', invocationId: 560
2022-03-30 17:26:16.031607+0300 ****[3808:1426624] [hubService] Received send request
2022-03-30 17:26:16.031841+0300 ****[3808:1426624] [hubService] Sending data
2022-03-30 17:26:39.311798+0300 ****[3808:1426915] [hubService] Marking transport as closed.
2022-03-30 17:26:39.314305+0300 ****[3808:1426991] [hubService] WebSocket error. Error: The operation couldn’t be completed. (kNWErrorDomainPOSIX error 60 - Operation timed out). Websocket status: 3
2022-03-30 17:26:39.315543+0300 ****[3808:1426915] [hubService] Error starting webSocket. Error: The operation couldn’t be completed. (kNWErrorDomainPOSIX error 60 - Operation timed out), HttpStatusCode: 101, WebSocket closeCode: 0
2022-03-30 17:26:39.317335+0300 ****[3808:1426991] [hubService] Marking transport as closed.
2022-03-30 17:26:39.318828+0300 ****[3808:1426915] [hubService] Transport closed
2022-03-30 17:26:39.320312+0300 ****[3808:1426991] [hubService] Transport already marked as closed - ignoring error. (handleError)
2022-03-30 17:26:39.322411+0300 ****[3808:1426915] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2022-03-30 17:26:39.323705+0300 ****[3808:1426915] [hubService] Changing state to: 'stopped' succeeded
2022-03-30 17:26:39.324744+0300 ****[3808:1426915] [hubService] Previous state connected
2022-03-30 17:26:39.325815+0300 ****[3808:1426915] [hubService] Invoking connectionDidClose (transportDidClose(_:): 272)
2022-03-30 17:26:39.326718+0300 ****[3808:1426624] [hubService] Connection closed
2022-03-30 17:26:39.327413+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'running' to: 'reconnecting'
2022-03-30 17:26:39.328090+0300 ****[3808:1426624] [hubService] Changing state to: 'reconnecting' succeeded
2022-03-30 17:26:39.328743+0300 ****[3808:1426624] [hubService] Initiating connection restart
2022-03-30 17:26:39.329380+0300 ****[3808:1426624] [hubService] Attempting to restart connection
2022-03-30 17:26:39.334216+0300 ****[3808:1426624] [hubService] nextAttemptInterval: seconds(10), RetryContext: RetryContext(failedAttemptsCount: 0, reconnectStartTime: 2022-03-30 14:26:39 +0000, error: The operation couldn’t be completed. (kNWErrorDomainPOSIX error 60 - Operation timed out))
2022-03-30 17:26:39.334891+0300 ****[3808:1426624] [hubService] Scheduling reconnect attempt at: seconds(10)
2022-03-30 17:26:39.335801+0300 ****[3808:1426624] [hubService] Connection will reconnect due to error: The operation couldn’t be completed. (kNWErrorDomainPOSIX error 60 - Operation timed out)
2022-03-30 17:26:49.345771+0300 ****[3808:1426624] [hubService] Starting or reconnecting
2022-03-30 17:26:49.346052+0300 ****[3808:1426624] [hubService] HttpConnection init
2022-03-30 17:26:49.346276+0300 ****[3808:1426624] [hubService] HttpConnection deinit
2022-03-30 17:26:49.346678+0300 ****[3808:1426624] [hubService] Starting connection
2022-03-30 17:26:49.346907+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'initial' to: 'connecting'
2022-03-30 17:26:49.347135+0300 ****[3808:1426624] [hubService] Changing state to: 'connecting' succeeded
2022-03-30 17:26:49.347368+0300 ****[3808:1426624] [hubService] Selected WebSockets transport
2022-03-30 17:26:49.347584+0300 ****[3808:1426624] [hubService] Starting WebSocket transport
2022-03-30 17:26:49.362703+0300 ****[3808:1427012] [hubService] Marking transport as closed.
2022-03-30 17:26:49.362968+0300 ****[3808:1427012] [hubService] Error starting webSocket. Error: The Internet connection appears to be offline., HttpStatusCode: -1, WebSocket closeCode: 0
2022-03-30 17:26:49.363180+0300 ****[3808:1427012] [hubService] Transport closed
2022-03-30 17:26:49.363399+0300 ****[3808:1427012] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2022-03-30 17:26:49.363628+0300 ****[3808:1427012] [hubService] Changing state to: 'stopped' succeeded
2022-03-30 17:26:49.363841+0300 ****[3808:1427012] [hubService] Previous state connecting
2022-03-30 17:26:49.364068+0300 ****[3808:1427012] [hubService] Leaving startDispatchGroup (transportDidClose(_:): 263)
2022-03-30 17:26:49.364275+0300 ****[3808:1427012] [hubService] Invoking connectionDidFailToOpen
2022-03-30 17:26:49.364584+0300 ****[3808:1426624] [hubService] Attempting to restart connection
2022-03-30 17:26:49.364880+0300 ****[3808:1426624] [hubService] nextAttemptInterval: seconds(10), RetryContext: RetryContext(failedAttemptsCount: 1, reconnectStartTime: 2022-03-30 14:26:39 +0000, error: The Internet connection appears to be offline.)
2022-03-30 17:26:49.365119+0300 ****[3808:1426624] [hubService] Scheduling reconnect attempt at: seconds(10)
2022-03-30 17:26:59.377146+0300 ****[3808:1426624] [hubService] Starting or reconnecting
2022-03-30 17:26:59.380310+0300 ****[3808:1426624] [hubService] HttpConnection init
2022-03-30 17:26:59.383226+0300 ****[3808:1426624] [hubService] HttpConnection deinit
2022-03-30 17:26:59.386037+0300 ****[3808:1426624] [hubService] Starting connection
2022-03-30 17:26:59.388410+0300 ****[3808:1426624] [hubService] Attempting to chage state from: 'initial' to: 'connecting'
2022-03-30 17:26:59.390612+0300 ****[3808:1426624] [hubService] Changing state to: 'connecting' succeeded
2022-03-30 17:26:59.392656+0300 ****[3808:1426624] [hubService] Selected WebSockets transport
2022-03-30 17:26:59.394391+0300 ****[3808:1426624] [hubService] Starting WebSocket transport
2022-03-30 17:26:59.408455+0300 ****[3808:1427051] [hubService] Marking transport as closed.
2022-03-30 17:26:59.408741+0300 ****[3808:1427051] [hubService] Error starting webSocket. Error: The Internet connection appears to be offline., HttpStatusCode: -1, WebSocket closeCode: 0
2022-03-30 17:26:59.408987+0300 ****[3808:1427051] [hubService] Transport closed
2022-03-30 17:26:59.409241+0300 ****[3808:1427051] [hubService] Attempting to chage state from: '(nil)' to: 'stopped'
2022-03-30 17:26:59.409488+0300 ****[3808:1427051] [hubService] Changing state to: 'stopped' succeeded
2022-03-30 17:26:59.409729+0300 ****[3808:1427051] [hubService] Previous state connecting
2022-03-30 17:26:59.409971+0300 ****[3808:1427051] [hubService] Leaving startDispatchGroup (transportDidClose(_:): 263)
2022-03-30 17:26:59.410208+0300 ****[3808:1427051] [hubService] Invoking connectionDidFailToOpen
2022-03-30 17:26:59.410528+0300 ****[3808:1426624] [hubService] Attempting to restart connection
2022-03-30 17:26:59.410850+0300 ****[3808:1426624] [hubService] nextAttemptInterval: seconds(10), RetryContext: RetryContext(failedAttemptsCount: 2, reconnectStartTime: 2022-03-30 14:26:39 +0000, error: The Internet connection appears to be offline.)
2022-03-30 17:26:59.411104+0300 ****[3808:1426624] [hubService] Scheduling reconnect attempt at: seconds(10)

[moozzyk]

Are you saying the completionHandler is not invoked at all or it does but the error is nil?

[MaxBG92]

Not at all. Let me know if you need any specifics other than the logs

[moozzyk]

Thanks for confirming. This might be a tough one - the completion handler is passed to the webSocket task verbatim and if the task does not call the completion handler I have no control over it. I will need to dig a little bit to see if I can reproduce and if there is some configuration I might have missed. One more question - how do you disable network? Do you disconnect from WiFi in settings in the simulator?

[MaxBG92]

On iPad, I disable wifi. On sim you would need to disconnect the laptop from wifi

[moozzyk]

Note to self:
Currently when closing the transport the sessions is invalidated with finishTasksAndInvalidate:

SignalR-Client-Swift/Sources/SignalRClient/WebsocketsTransport.swift

Line 144 in 02e7a15

urlSession?.finishTasksAndInvalidate()

invalidateAndCancel might be a better choice as it cancel outstanding tasks:
https://developer.apple.com/documentation/foundation/nsurlsession/1411538-invalidateandcancel

Possibly, send is waiting for some kind of time out but because the transport is being closed the WebSocket is going out of scope and callback never happens?

@MaxBG92: would you be able to test if using invalidateAndCancel instead of finishTasksAndInvalidate on the line I pointed to above fixes the problem?

[MaxBG92]

Hello, sorry for the delay. Tried it but getting the same result

[moozzyk]

Thanks for confirming!

[moozzyk]

This thread could be useful: https://developer.apple.com/forums/thread/678384

[moozzyk]

Added additional logging in 06772b8. My hypothesis is that maybe the callback was invoked but the error was nil and the handler just exited here:

SignalR-Client-Swift/Sources/SignalRClient/WebsocketsTransport.swift

Lines 96 to 100 in 06772b8

	guard error != nil else {
	logger.log(logLevel: .debug, message: "error is nil - ignoring error")
	// As per docs: "Error may be nil, which implies that no error occurred and this task is complete."
	return
	}

leaving no trace whatsoever. If this is confirmed, the client should close the transport regardless of whether the error is present.