Closed renato-kristic closed 1 year ago
Hmmm, something is wrong with ping mechanism in 0.6.3.
I removed signalr.KeepAliveInterval(15*time.Second)
and signalr.TimeoutInterval(30*time.Second)
from constructor and default values are now used for my server and client.
If there is only one client everything is fine, I cannot see any timeout interval elapsed (30s)
messages in log.
But if there are two clients ping mechanism starts behaving strange.
If both clients are not sending any messages (only ping messages are exchanging) everything is fine. But when one client is sending messages other client will disconnect every 30s.
For example: Client1 -> Sending message every 2 seconds. Client2 -> Not sending anything, just listening. Client2 will be disconnected and will try to connect again.
Client2 log:
level=debug ts=2023-10-03T07:11:31.76561318Z protocol=JSON ts=2023-10-03T07:11:31.765614282Z caller=jsonhubprotocol.go:76 event=read message="{\"type\":7,\"error\":\"timeout interval elapsed (30s)\",\"allowReconnect\":true}"
level=debug ts=2023-10-03T07:11:31.765838136Z class=Client connection="QwWocpbJqbh16ZWETdzfhA==" hub=test_client.Client ts=2023-10-03T07:11:31.765838427Z caller=loop.go:96 message="signalr.closeMessage{Type:7, Error:\"timeout interval elapsed (30s)\", AllowReconnect:true}"
level=debug ts=2023-10-03T07:11:31.765872922Z protocol=JSON ts=2023-10-03T07:11:31.765873233Z caller=jsonhubprotocol.go:211 event=write message="{\"type\":7,\"error\":\"timeout interval elapsed (30s)\",\"allowReconnect\":false}\u001e"
level=debug ts=2023-10-03T07:11:31.765917526Z class=Client connection="QwWocpbJqbh16ZWETdzfhA==" hub=test_client.Client ts=2023-10-03T07:11:31.765917847Z caller=loop.go:139 event="message loop ended"
level=info ts=2023-10-03T07:11:31.765962732Z connect="timeout interval elapsed (30s)"
level=debug ts=2023-10-03T07:11:32.48676235Z caller=client.go:318 state=1
level=debug ts=2023-10-03T07:11:32.487957522Z class=Client connection="BcARsZdZzjSzPJV4fbuUpA==" hub=test_client.Client ts=2023-10-03T07:11:32.487958243Z caller=client.go:586 event="handshake sent" msg="{\"protocol\":\"json\",\"version\":1}\u001e"
level=debug ts=2023-10-03T07:11:32.488239947Z class=Client connection="BcARsZdZzjSzPJV4fbuUpA==" hub=test_client.Client ts=2023-10-03T07:11:32.488240528Z caller=client.go:616 event="handshake received" msg="signalr.handshakeResponse{Error:\"\"}"
level=debug ts=2023-10-03T07:11:32.488323906Z caller=client.go:318 state=2
If I start third client (Python client 0.9.5) it will behave correctly and will not disconnect.
Any idea what is wrong with ping mechanism?
I tried to find a source of this problem and found out the following:
Server resets timeoutTicker
every time new message arrives (I can see this happening every few seconds as there is flow of messages):
https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/loop.go#L80
But no matter if timeoutTicker
is reset just few seconds ago, this will be executed:
https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/loop.go#L113
But it should not execute.... right?
I found solution for this problem: https://github.com/philippseith/signalr/pull/180
If Client1 is sending messages and Client2 is just listening for messages, Client2 will not send ping after keepAliveInterval
.
By using NewTicker created outside of the loop that takes care of firing at keepAliveInterval
it solved this problem.
Hello,
I agree I had the same issue and apply the same fix.
I tried to find a source of this problem and found out the following: Server resets
timeoutTicker
every time new message arrives (I can see this happening every few seconds as there is flow of messages):https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/loop.go#L80
But no matter if
timeoutTicker
is reset just few seconds ago, this will be executed:https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/loop.go#L113
But it should not execute.... right?
It seems to me that these are different timeoutTicker instances. Both server and client are using them.
I found solution for this problem: #180
If Client1 is sending messages and Client2 is just listening for messages, Client2 will not send ping after
keepAliveInterval
. By using NewTicker created outside of the loop that takes care of firing atkeepAliveInterval
it solved this problem.
This "solves" the problem, yes. But only because the select case for keepAliveTicker is executing even the timeoutTicker has elapsed.
IMHO, the real problem is that the client does not reset its own timeout when it sends a Ping. You may have noticed that it is not the server which is closing the connection. It is the client! This roots in my sloppy reading of the spec: https://github.com/dotnet/aspnetcore/blob/main/src/SignalR/docs/specs/HubProtocol.md#ping-aka-keep-alive says: "Most implementations will want to reset a timeout used to determine if the other party is present." This is currently not done in this implementation. See #181
It seems to me that these are different timeoutTicker instances. Both server and client are using them. This "solves" the problem, yes. But only because the select case for keepAliveTicker is executing even the timeoutTicker has elapsed. IMHO, the real problem is that the client does not reset its own timeout when it sends a Ping. You may have noticed that it is not the server which is closing the connection. It is the client! From what I can see in logs, it is the server that breaks
pingLoop
astimeoutTicker
elapses.
Yes, these are different timeoutTicker instances. There is a new instance for every new client connected. During a test I was not aware of it. This is what was happening:
Client1 - Sends message every 2s Client2 - Just listens for messages
Client2 successfully receives messages that Client1 is sending but Client2 will not send pings if Client1 is emitting messages.
Server stops receiving ping messages from Client2 and timeoutTicker
instance for this client never gets reset.
When timeoutTicker
elapses it will break pingLoop
and client will be disconnected.
The main source of this problem is that Client2 stops sending ping messages. But if I implement timer as described in https://github.com/philippseith/signalr/pull/180 everything starts behaving normally. Client2 will continue sending pings event if Client1 is emitting messages. For me this looks like good flow of messages.
This roots in my sloppy reading of the spec: https://github.com/dotnet/aspnetcore/blob/main/src/SignalR/docs/specs/HubProtocol.md#ping-aka-keep-alive says: "Most implementations will want to reset a timeout used to determine if the other party is present." This is currently not done in this implementation. See https://github.com/philippseith/signalr/pull/181
I tried implementing server and clients using your fix and I can confirm that it works too. Client2 will not get disconnected if Client1 is sending messages.
I can see that server sends ping every 5s and resets timeout timer successfully:
https://github.com/philippseith/signalr/blob/729f03be0de1dfc1bb80e17f3c06be2dfffacba2/loop.go#L115
Client stops sending pings but client will not be disconnected by server as server resets timeoutTicker
when sending ping to the client.
For me this approach is acceptable. I hope there are no cons for using this ping mechanism.
Fixed by #181
I'm using the latest release (0.6.3) for my client and server. I defined the following values for both, server and client:
With these parameters I can see that client disconnects/reconnects every 30 seconds.
This is client log:
This is server log:
The only solution I found is to set
KeepAliveInterval=5s
on the server. If I try to set it to 4s or 6s it will still cause client to disconnect.Any idea what is causing these issues?
btw, in comments I see this https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/options.go#L39 But in
newPartyBase
method I see this hardcoded: https://github.com/philippseith/signalr/blob/e607000614fa7d709688494ec3918d0a5428fec1/party.go#L62 Could this cause any issues?