Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix deadlock on main thread #294

Open
wants to merge 2 commits into
base: master
Choose a base branch
from

Conversation

YuryNiakhai
Copy link
Contributor

When fast to repeat start / stop actions connection from main thread - could be dead lock on main thread.
General issue decision: https://stackoverflow.com/a/46709947

@moozzyk
Copy link
Owner

moozzyk commented Feb 11, 2024

Can you point me to what is deadlocking and how to reproduce this? Could the deadlock be fixed by not using the main queue for callbacks? If so, it is possible to configure the queue in HubOptions:

public var callbackQueue: DispatchQueue = DispatchQueue.main

I am worried that while removing the wait might fix the deadlock you are seeing, it introduces other issues due to race conditions (e.g. someone is starting the connection before the stop has completed).

@YuryNiakhai
Copy link
Contributor Author

Can you point me to what is deadlocking and how to reproduce this? Could the deadlock be fixed by not using the main queue for callbacks? If so, it is possible to configure the queue in HubOptions:

public var callbackQueue: DispatchQueue = DispatchQueue.main

I am worried that while removing the wait might fix the deadlock you are seeing, it introduces other issues due to race conditions (e.g. someone is starting the connection before the stop has completed).

Changing queue in HubOptions does not decide the issue.
Here is my full log when I reproduce it:

Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
Error starting webSocket
Transport closed
Connection not to be restarted. State: starting
Stopping hub connection
Received connection stop request
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
Hub connection started
Received send request
Stopping hub connection
Received connection stop request
Stopping connection
WebSocket close. Code: 1000, reason:
Transport closed
HubConnection closing with error: nil
Terminating 0 pending hub methods
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
Hub connection started
Received send request
Stopping hub connection
Received connection stop request
Stopping connection
WebSocket close. Code: 1000, reason:
Transport closed
HubConnection closing with error: nil
Terminating 0 pending hub methods
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
Error starting webSocket.
Transport closed
Connection not to be restarted. State: starting
Stopping hub connection
Received connection stop request
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
Stopping hub connection
Received connection stop request
Stopping connection
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
WebSocket close. Code: 1000, reason:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
Hub connection started
Received send request
Stopping hub connection
Received connection stop request
Stopping connection
WebSocket close. Code: 1000, reason:
Transport closed
HubConnection closing with error: nil
Terminating 0 pending hub methods
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
Hub connection started
Received send request
Stopping hub connection
Received connection stop request
Stopping connection
WebSocket close. Code: 1000, reason:
Transport closed
HubConnection closing with error: nil
Terminating 0 pending hub methods
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
urlSession didOpenWithProtocol invoked. WebSocket open
Transport started
Hub connection started
Received send request
Stopping hub connection
Received connection stop request
Stopping connection
WebSocket close. Code: 1000, reason:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Registering client side hub method:
Starting hub connection
Starting reconnectable connection
Starting connection
Selected WebSockets transport
Starting WebSocket transport
Stopping hub connection
Received connection stop request
Stopping connection
Error starting webSocket.
Transport closed
HubConnection closing with error
Terminating 0 pending hub methods

at the and I have:
Screenshot 2024-02-12 at 12 01 55

Screenshot 2024-02-12 at 12 01 39

Looks when I manually call stop in HubConnection from main thread - all stack will be also on main thread and DispatchGroup will lock main thread if DispatchGroup waiting something. Perhaps when calling stop function in HubConnection should switch to some internal library queue logic, because when using calling DispatchGroup.leave - that do it not from main thread...

@moozzyk
Copy link
Owner

moozzyk commented Feb 12, 2024

Can you enable logging at the diagnostic level and include this log?

@YuryNiakhai
Copy link
Contributor Author

YuryNiakhai commented Feb 12, 2024

Can you enable logging at the diagnostic level and include this log?

When I start connection - I create new instance from HubConnectionBuilder and stop previous started instance (before create new instance)

2024-02-12T16:20:56.821Z debug: HttpConnection init
2024-02-12T16:20:56.823Z debug: HubConnection init
2024-02-12T16:20:56.824Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:20:56.826Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:20:56.827Z debug: Starting or reconnecting
2024-02-12T16:20:56.827Z debug: HttpConnection init
2024-02-12T16:20:56.827Z debug: HttpConnection deinit
2024-02-12T16:20:56.827Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:20:56.829Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:20:57.126Z debug: Negotiate completed with OK status code
2024-02-12T16:20:57.126Z debug: Negotiate response:
2024-02-12T16:20:57.127Z debug: Negotiation response received
2024-02-12T16:20:57.278Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:20:57.369Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:20:57.369Z debug: Marking transport as closed.
2024-02-12T16:20:57.375Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:20:57.375Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:20:57.375Z debug: Previous state connecting
2024-02-12T16:20:57.375Z debug: Leaving startDispatchGroup (transportDidClose(_:): 267)
2024-02-12T16:20:57.375Z debug: Invoking connectionDidFailToOpen
2024-02-12T16:20:57.378Z debug: Attempting to restart connection
2024-02-12T16:20:57.378Z debug: nextAttemptInterval: never, RetryContext:
2024-02-12T16:20:57.384Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:20:57.384Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:20:57.384Z debug: Opening the connection failed
2024-02-12T16:20:57.391Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:20:57.391Z debug: Changing state to: 'stopping' failed
2024-02-12T16:20:57.392Z debug: HttpConnection init
2024-02-12T16:20:57.393Z debug: HubConnection init
2024-02-12T16:20:57.394Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:20:57.394Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:20:57.394Z debug: Starting or reconnecting
2024-02-12T16:20:57.394Z debug: HttpConnection init
2024-02-12T16:20:57.394Z debug: HttpConnection deinit
2024-02-12T16:20:57.394Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:20:57.394Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:20:57.395Z debug: HubConnection deinit
2024-02-12T16:20:57.395Z debug: HttpConnection deinit
2024-02-12T16:20:57.541Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:20:57.630Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:20:57.630Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:20:57.630Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:20:57.630Z debug: Invoking connectionDidOpen
2024-02-12T16:20:57.630Z debug: Connection opened successfully
2024-02-12T16:20:57.630Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:20:57.630Z debug: Changing state to: 'running' succeeded
2024-02-12T16:20:57.630Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:20:57.631Z debug: Sending data
2024-02-12T16:20:57.695Z debug: Received data from transport
2024-02-12T16:20:57.696Z debug: Data received
2024-02-12T16:20:57.696Z debug: Processing handshake response: {} 
2024-02-12T16:20:57.696Z debug: Resetting keep alive
2024-02-12T16:20:57.696Z debug: Payload contains 0 message(s)
2024-02-12T16:20:57.927Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:20:57.927Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:20:57.927Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:20:57.927Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:20:57.930Z debug: urlSession didCloseWith invoked
2024-02-12T16:20:57.930Z debug: Marking transport as closed.
2024-02-12T16:20:57.930Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:20:57.930Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:20:57.930Z debug: Previous state stopped
2024-02-12T16:20:57.930Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:20:57.931Z debug: Connection closed
2024-02-12T16:20:57.931Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:20:57.931Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:20:57.931Z debug: Assuming clean stop - stopping connection
2024-02-12T16:20:57.931Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:20:57.931Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:20:57.931Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:20:57.931Z debug: error is nil - ignoring error
2024-02-12T16:20:58.780Z debug: HttpConnection init
2024-02-12T16:20:58.782Z debug: HubConnection init
2024-02-12T16:20:58.783Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:20:58.783Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:20:58.783Z debug: Starting or reconnecting
2024-02-12T16:20:58.783Z debug: HttpConnection init
2024-02-12T16:20:58.783Z debug: HttpConnection deinit
2024-02-12T16:20:58.784Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:20:58.784Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:20:59.389Z debug: Negotiate completed with OK status code
2024-02-12T16:20:59.389Z debug: Negotiate response:
2024-02-12T16:20:59.389Z debug: Negotiation response received
2024-02-12T16:20:59.559Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:20:59.646Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:20:59.646Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:20:59.646Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:20:59.647Z debug: Invoking connectionDidOpen
2024-02-12T16:20:59.647Z debug: Connection opened successfully
2024-02-12T16:20:59.647Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:20:59.647Z debug: Changing state to: 'running' succeeded
2024-02-12T16:20:59.647Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:20:59.647Z debug: Sending data
2024-02-12T16:20:59.710Z debug: Received data from transport
2024-02-12T16:20:59.710Z debug: Data received
2024-02-12T16:20:59.710Z debug: Processing handshake response: {} 
2024-02-12T16:20:59.710Z debug: Resetting keep alive
2024-02-12T16:20:59.710Z debug: Payload contains 0 message(s)
2024-02-12T16:20:59.847Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:20:59.847Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:20:59.847Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:20:59.847Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:20:59.851Z debug: urlSession didCloseWith invoked
2024-02-12T16:20:59.851Z debug: Marking transport as closed.
2024-02-12T16:20:59.851Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:20:59.851Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:20:59.851Z debug: Previous state stopped
2024-02-12T16:20:59.851Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:20:59.852Z debug: Connection closed
2024-02-12T16:20:59.852Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:20:59.852Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:20:59.852Z debug: Assuming clean stop - stopping connection
2024-02-12T16:20:59.852Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:20:59.852Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:20:59.852Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:20:59.853Z debug: error is nil - ignoring error
2024-02-12T16:21:00.561Z debug: HttpConnection init
2024-02-12T16:21:00.563Z debug: HubConnection init
2024-02-12T16:21:00.564Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:00.564Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:00.564Z debug: Starting or reconnecting
2024-02-12T16:21:00.564Z debug: HttpConnection init
2024-02-12T16:21:00.564Z debug: HttpConnection deinit
2024-02-12T16:21:00.564Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:00.564Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:00.864Z debug: Negotiate completed with OK status code
2024-02-12T16:21:00.865Z debug: Negotiate response:
2024-02-12T16:21:00.865Z debug: Negotiation response received
2024-02-12T16:21:01.022Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:01.111Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:01.111Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:01.111Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:01.111Z debug: Invoking connectionDidOpen
2024-02-12T16:21:01.111Z debug: Connection opened successfully
2024-02-12T16:21:01.111Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:01.111Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:01.111Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:01.111Z debug: Sending data
2024-02-12T16:21:01.181Z debug: Received data from transport
2024-02-12T16:21:01.181Z debug: Data received
2024-02-12T16:21:01.181Z debug: Processing handshake response: {} 
2024-02-12T16:21:01.181Z debug: Resetting keep alive
2024-02-12T16:21:01.181Z debug: Payload contains 0 message(s)
2024-02-12T16:21:01.329Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:01.329Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:01.329Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:01.329Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:01.335Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:01.335Z debug: Marking transport as closed.
2024-02-12T16:21:01.337Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:01.337Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:01.337Z debug: Previous state stopped
2024-02-12T16:21:01.337Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:01.338Z debug: Connection closed
2024-02-12T16:21:01.338Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:21:01.338Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:21:01.338Z debug: Assuming clean stop - stopping connection
2024-02-12T16:21:01.338Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:01.338Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:01.337Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:01.338Z debug: error is nil - ignoring error
2024-02-12T16:21:02.042Z debug: HttpConnection init
2024-02-12T16:21:02.044Z debug: HubConnection init
2024-02-12T16:21:02.044Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:02.044Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:02.044Z debug: Starting or reconnecting
2024-02-12T16:21:02.044Z debug: HttpConnection init
2024-02-12T16:21:02.045Z debug: HttpConnection deinit
2024-02-12T16:21:02.045Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:02.045Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:02.381Z debug: Negotiate completed with OK status code
2024-02-12T16:21:02.382Z debug: Negotiate response:
2024-02-12T16:21:02.382Z debug: Negotiation response received
2024-02-12T16:21:02.536Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:02.625Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:02.626Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:02.626Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:02.626Z debug: Invoking connectionDidOpen
2024-02-12T16:21:02.626Z debug: Connection opened successfully
2024-02-12T16:21:02.626Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:02.626Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:02.626Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:02.626Z debug: Sending data
2024-02-12T16:21:02.690Z debug: Received data from transport
2024-02-12T16:21:02.691Z debug: Data received
2024-02-12T16:21:02.691Z debug: Processing handshake response: {} 
2024-02-12T16:21:02.691Z debug: Resetting keep alive
2024-02-12T16:21:02.691Z debug: Payload contains 0 message(s)
2024-02-12T16:21:02.865Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:02.866Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:02.866Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:02.866Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:02.872Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:02.872Z debug: Marking transport as closed.
2024-02-12T16:21:02.875Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:02.875Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:02.875Z debug: Previous state stopped
2024-02-12T16:21:02.875Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:02.876Z debug: Connection closed
2024-02-12T16:21:02.876Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:21:02.876Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:21:02.876Z debug: Assuming clean stop - stopping connection
2024-02-12T16:21:02.876Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:02.876Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:02.873Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:02.876Z debug: error is nil - ignoring error
2024-02-12T16:21:03.591Z debug: HttpConnection init
2024-02-12T16:21:03.593Z debug: HubConnection init
2024-02-12T16:21:03.594Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:03.594Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:03.594Z debug: Starting or reconnecting
2024-02-12T16:21:03.594Z debug: HttpConnection init
2024-02-12T16:21:03.594Z debug: HttpConnection deinit
2024-02-12T16:21:03.594Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:03.594Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:03.950Z debug: Negotiate completed with OK status code
2024-02-12T16:21:03.950Z debug: Negotiate response:
2024-02-12T16:21:03.950Z debug: Negotiation response received
2024-02-12T16:21:04.114Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:04.207Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:04.207Z debug: Marking transport as closed.
2024-02-12T16:21:04.207Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:04.207Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:04.208Z debug: Previous state connecting
2024-02-12T16:21:04.208Z debug: Leaving startDispatchGroup (transportDidClose(_:): 267)
2024-02-12T16:21:04.208Z debug: Invoking connectionDidFailToOpen
2024-02-12T16:21:04.208Z debug: Attempting to restart connection
2024-02-12T16:21:04.208Z debug: nextAttemptInterval: never, RetryContext:
2024-02-12T16:21:04.209Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:04.209Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:04.209Z debug: Opening the connection failed
2024-02-12T16:21:04.209Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:04.210Z debug: Changing state to: 'stopping' failed
2024-02-12T16:21:04.210Z debug: HttpConnection init
2024-02-12T16:21:04.212Z debug: HubConnection init
2024-02-12T16:21:04.214Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:04.214Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:04.214Z debug: Starting or reconnecting
2024-02-12T16:21:04.214Z debug: HttpConnection init
2024-02-12T16:21:04.214Z debug: HttpConnection deinit
2024-02-12T16:21:04.214Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:04.214Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:04.216Z debug: HubConnection deinit
2024-02-12T16:21:04.216Z debug: HttpConnection deinit
2024-02-12T16:21:04.371Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:04.380Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:04.380Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:04.380Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:04.380Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:04.479Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:04.479Z debug: Changing state to: 'connected' failed
2024-02-12T16:21:04.479Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:04.479Z debug: Connection is being stopped while the transport is starting
2024-02-12T16:21:04.479Z debug: HubConnection deinit
2024-02-12T16:21:04.479Z debug: HttpConnection deinit
2024-02-12T16:21:04.486Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:04.486Z debug: Marking transport as closed.
2024-02-12T16:21:04.486Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:04.487Z debug: error is nil - ignoring error
2024-02-12T16:21:05.223Z debug: HttpConnection init
2024-02-12T16:21:05.225Z debug: HubConnection init
2024-02-12T16:21:05.226Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:05.226Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:05.226Z debug: Starting or reconnecting
2024-02-12T16:21:05.226Z debug: HttpConnection init
2024-02-12T16:21:05.226Z debug: HttpConnection deinit
2024-02-12T16:21:05.227Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:05.227Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:05.628Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:05.803Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:05.803Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:05.803Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:05.803Z debug: Invoking connectionDidOpen
2024-02-12T16:21:05.804Z debug: Connection opened successfully
2024-02-12T16:21:05.804Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:05.804Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:05.804Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:05.804Z debug: Sending data
2024-02-12T16:21:05.878Z debug: Received data from transport
2024-02-12T16:21:05.878Z debug: Data received
2024-02-12T16:21:05.878Z debug: Processing handshake response: {} 
2024-02-12T16:21:05.878Z debug: Resetting keep alive
2024-02-12T16:21:05.878Z debug: Payload contains 0 message(s)
2024-02-12T16:21:06.045Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:06.045Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:06.045Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:06.045Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:06.049Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:06.049Z debug: Marking transport as closed.
2024-02-12T16:21:06.051Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:06.051Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:06.051Z debug: Previous state stopped
2024-02-12T16:21:06.051Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:06.051Z debug: Connection closed
2024-02-12T16:21:06.051Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:21:06.051Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:21:06.051Z debug: Assuming clean stop - stopping connection
2024-02-12T16:21:06.051Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:06.051Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:06.050Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:06.052Z debug: error is nil - ignoring error
2024-02-12T16:21:06.666Z debug: HttpConnection init
2024-02-12T16:21:06.667Z debug: HubConnection init
2024-02-12T16:21:06.668Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:06.668Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:06.668Z debug: Starting or reconnecting
2024-02-12T16:21:06.668Z debug: HttpConnection init
2024-02-12T16:21:06.668Z debug: HttpConnection deinit
2024-02-12T16:21:06.668Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:06.668Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:07.063Z debug: Negotiate completed with OK status code
2024-02-12T16:21:07.063Z debug: Negotiate response:
2024-02-12T16:21:07.063Z debug: Negotiation response received
2024-02-12T16:21:07.223Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:07.316Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:07.316Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:07.316Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:07.316Z debug: Invoking connectionDidOpen
2024-02-12T16:21:07.316Z debug: Connection opened successfully
2024-02-12T16:21:07.316Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:07.316Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:07.317Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:07.317Z debug: Sending data
2024-02-12T16:21:07.381Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:07.381Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:07.381Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:07.381Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:07.381Z debug: HubConnection deinit
2024-02-12T16:21:07.381Z debug: HttpConnection deinit
2024-02-12T16:21:07.387Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:07.392Z debug: Marking transport as closed.
2024-02-12T16:21:07.390Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:07.392Z debug: error is nil - ignoring error
2024-02-12T16:21:08.184Z debug: HttpConnection init
2024-02-12T16:21:08.185Z debug: HubConnection init
2024-02-12T16:21:08.185Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:08.185Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:08.185Z debug: Starting or reconnecting
2024-02-12T16:21:08.185Z debug: HttpConnection init
2024-02-12T16:21:08.185Z debug: HttpConnection deinit
2024-02-12T16:21:08.186Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:08.186Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:08.585Z debug: Negotiate completed with OK status code
2024-02-12T16:21:08.585Z debug: Negotiate response:
2024-02-12T16:21:08.585Z debug: Negotiation response received
2024-02-12T16:21:08.753Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:08.846Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:08.846Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:08.846Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:08.846Z debug: Invoking connectionDidOpen
2024-02-12T16:21:08.846Z debug: Connection opened successfully
2024-02-12T16:21:08.846Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:08.847Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:08.847Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:08.847Z debug: Sending data
2024-02-12T16:21:08.916Z debug: Received data from transport
2024-02-12T16:21:08.917Z debug: Data received
2024-02-12T16:21:08.917Z debug: Processing handshake response: {} 
2024-02-12T16:21:08.917Z debug: Resetting keep alive
2024-02-12T16:21:08.917Z debug: Payload contains 0 message(s)
2024-02-12T16:21:08.966Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:08.966Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:08.966Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:08.966Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:08.976Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:08.976Z debug: Marking transport as closed.
2024-02-12T16:21:08.978Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:08.978Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:08.978Z debug: Previous state stopped
2024-02-12T16:21:08.979Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:08.979Z debug: Connection closed
2024-02-12T16:21:08.979Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:21:08.979Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:21:08.979Z debug: Assuming clean stop - stopping connection
2024-02-12T16:21:08.979Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:08.979Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:08.977Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:08.980Z debug: error is nil - ignoring error
2024-02-12T16:21:09.630Z debug: HttpConnection init
2024-02-12T16:21:09.632Z debug: HubConnection init
2024-02-12T16:21:09.633Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:09.633Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:09.633Z debug: Starting or reconnecting
2024-02-12T16:21:09.633Z debug: HttpConnection init
2024-02-12T16:21:09.633Z debug: HttpConnection deinit
2024-02-12T16:21:09.634Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:09.634Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:09.965Z debug: Negotiate completed with OK status code
2024-02-12T16:21:09.965Z debug: Negotiate response:
2024-02-12T16:21:10.123Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:10.211Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:10.211Z debug: Marking transport as closed.
2024-02-12T16:21:10.211Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:10.211Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:10.211Z debug: Previous state connecting
2024-02-12T16:21:10.211Z debug: Leaving startDispatchGroup (transportDidClose(_:): 267)
2024-02-12T16:21:10.212Z debug: Invoking connectionDidFailToOpen
2024-02-12T16:21:10.212Z debug: Attempting to restart connection
2024-02-12T16:21:10.212Z debug: nextAttemptInterval: never, RetryContext:
2024-02-12T16:21:10.213Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:10.213Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:10.213Z debug: Opening the connection failed
2024-02-12T16:21:10.213Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:10.213Z debug: Changing state to: 'stopping' failed
2024-02-12T16:21:10.214Z debug: HttpConnection init
2024-02-12T16:21:10.215Z debug: HubConnection init
2024-02-12T16:21:10.215Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:10.215Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:10.215Z debug: Starting or reconnecting
2024-02-12T16:21:10.215Z debug: HttpConnection init
2024-02-12T16:21:10.215Z debug: HttpConnection deinit
2024-02-12T16:21:10.215Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:10.216Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:10.216Z debug: HubConnection deinit
2024-02-12T16:21:10.217Z debug: HttpConnection deinit
2024-02-12T16:21:10.296Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:10.296Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:10.296Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:10.296Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:10.377Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:10.476Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:10.477Z debug: Changing state to: 'connected' failed
2024-02-12T16:21:10.477Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:10.477Z debug: HubConnection deinit
2024-02-12T16:21:10.478Z debug: Connection is being stopped while the transport is starting
2024-02-12T16:21:10.478Z debug: HttpConnection deinit
2024-02-12T16:21:10.486Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:10.486Z debug: Marking transport as closed.
2024-02-12T16:21:10.488Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:10.488Z debug: error is nil - ignoring error
2024-02-12T16:21:11.159Z debug: HttpConnection init
2024-02-12T16:21:11.160Z debug: HubConnection init
2024-02-12T16:21:11.161Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:11.161Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:11.161Z debug: Starting or reconnecting
2024-02-12T16:21:11.161Z debug: HttpConnection init
2024-02-12T16:21:11.161Z debug: HttpConnection deinit
2024-02-12T16:21:11.161Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:11.161Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:11.553Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:11.732Z debug: Attempting to change state from: 'connecting' to: 'connected'
2024-02-12T16:21:11.733Z debug: Changing state to: 'connected' succeeded
2024-02-12T16:21:11.733Z debug: Leaving startDispatchGroup (transportDidOpen(connectionId:): 240)
2024-02-12T16:21:11.733Z debug: Invoking connectionDidOpen
2024-02-12T16:21:11.733Z debug: Connection opened successfully
2024-02-12T16:21:11.733Z debug: Attempting to change state from: 'starting, reconnecting' to: 'running'
2024-02-12T16:21:11.733Z debug: Changing state to: 'running' succeeded
2024-02-12T16:21:11.733Z debug: Sending handshake request: {"protocol": "json", "version": 1} 
2024-02-12T16:21:11.733Z debug: Sending data
2024-02-12T16:21:11.809Z debug: Received data from transport
2024-02-12T16:21:11.809Z debug: Data received
2024-02-12T16:21:11.809Z debug: Processing handshake response: {} 
2024-02-12T16:21:11.809Z debug: Resetting keep alive
2024-02-12T16:21:11.809Z debug: Payload contains 0 message(s)
2024-02-12T16:21:11.929Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:11.930Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:11.930Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:11.930Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:11.935Z debug: urlSession didCloseWith invoked
2024-02-12T16:21:11.935Z debug: Marking transport as closed.
2024-02-12T16:21:11.937Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:11.937Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:11.937Z debug: Previous state stopped
2024-02-12T16:21:11.937Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:11.938Z debug: Connection closed
2024-02-12T16:21:11.938Z debug: Attempting to change state from: 'running' to: 'reconnecting'
2024-02-12T16:21:11.938Z debug: Changing state to: 'reconnecting' failed
2024-02-12T16:21:11.938Z debug: Assuming clean stop - stopping connection
2024-02-12T16:21:11.938Z debug: Attempting to change state from: '(nil)' to: 'disconnected'
2024-02-12T16:21:11.938Z debug: Changing state to: 'disconnected' succeeded
2024-02-12T16:21:11.936Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:11.938Z debug: error is nil - ignoring error
2024-02-12T16:21:12.594Z debug: HttpConnection init
2024-02-12T16:21:12.595Z debug: HubConnection init
2024-02-12T16:21:12.596Z debug: Attempting to change state from: 'disconnected' to: 'starting'
2024-02-12T16:21:12.596Z debug: Changing state to: 'starting' succeeded
2024-02-12T16:21:12.596Z debug: Starting or reconnecting
2024-02-12T16:21:12.596Z debug: HttpConnection init
2024-02-12T16:21:12.596Z debug: HttpConnection deinit
2024-02-12T16:21:12.596Z debug: Attempting to change state from: 'initial' to: 'connecting'
2024-02-12T16:21:12.596Z debug: Changing state to: 'connecting' succeeded
2024-02-12T16:21:12.703Z debug: HubConnection deinit
2024-02-12T16:21:12.703Z debug: HttpConnection deinit
2024-02-12T16:21:13.301Z debug: Negotiate completed with OK status code
2024-02-12T16:21:13.302Z debug: Negotiate response:
2024-02-12T16:21:13.302Z debug: Negotiation response received
2024-02-12T16:21:13.345Z debug: Attempting to change state from: 'starting, reconnecting, running' to: 'stopping'
2024-02-12T16:21:13.346Z debug: Changing state to: 'stopping' succeeded
2024-02-12T16:21:13.346Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:13.346Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:13.471Z debug: (ws) no auth challenge handler registered - falling back to default handling
2024-02-12T16:21:13.580Z debug: urlSession didCompleteWithError invoked
2024-02-12T16:21:13.580Z debug: Marking transport as closed.
2024-02-12T16:21:13.581Z debug: Attempting to change state from: '(nil)' to: 'stopped'
2024-02-12T16:21:13.581Z debug: Changing state to: 'stopped' succeeded
2024-02-12T16:21:13.581Z debug: Previous state stopped
2024-02-12T16:21:13.581Z debug: Invoking connectionDidClose (transportDidClose(_:): 276)
2024-02-12T16:21:15.087Z debug: HubConnection deinit
2024-02-12T16:21:15.087Z debug: HttpConnection deinit
2024-02-12T16:21:17.162Z debug: HubConnection deinit
2024-02-12T16:21:17.162Z debug: HttpConnection deinit
2024-02-12T16:21:18.223Z debug: HubConnection deinit
2024-02-12T16:21:18.223Z debug: HttpConnection deinit
2024-02-12T16:21:21.390Z debug: HubConnection deinit
2024-02-12T16:21:21.390Z debug: HttpConnection deinit
2024-02-12T16:21:24.539Z debug: HubConnection deinit
2024-02-12T16:21:24.539Z debug: HttpConnection deinit
2024-02-12T16:21:27.617Z debug: HubConnection deinit
2024-02-12T16:21:27.618Z debug: HttpConnection deinit

@moozzyk
Copy link
Owner

moozzyk commented Feb 16, 2024

Thanks for the logs. Unfortunately, they are hard to understand because it is impossible to tell which entries come from which instance. Would it be possible to somehow tag the instance when logging? Alternatively, could you provide a minimal repro for this so I can try running it on my side?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants