Closed Kuffs2205 closed 1 year ago
acupofjose
commented
1 year ago Interesting! I’m in the process of refactoring most of this library (see #28) and I’m hoping to clarify what you’re asking here in these changes. The current reconnection/error listener setup needs some love that is addressed in these changes.
acupofjose
commented
1 year ago If you're up to give it a try... would you attempt this on realtime-csharp@6.0.1?
Kuffs2205
commented
1 year ago Sorry, I didn't see this message until just now.
I was coming to tell you of the result after trying the update today.
The log is a little short right now but an issue seen so far is that at 14:33:32 Presence seems to erroneously leave the channel on NasVM10 despite still being connected. Joining the channel on RAGE confirms that the channel is still active but NasVM10 is not in the list of joined computers. I also see a Channel Join at 14:33:31 without a Channel Leave preceding it. For clarification, everything after 13:06 happened with no user interaction at all. Just the test app running in a VM.
I'm leaving for the day but I'll reset and try again and see what the logs show tomorrow.
Question: Do I need to refresh my "Track" at any point? i.e If I don't track again within a specific timeframe, do I automatically leave the channel even if still connected to it?
25 May 2023 13:06:00 Channel_StateChanged: Joining
25 May 2023 13:06:00 Channel_StateChanged: Joined
25 May 2023 13:06:00 Channel 11111111-1111-1111-1111-111111111111 Connected
25 May 2023 13:06:00 Presence Sync:
25 May 2023 13:06:00 Presence Sync: Daz Kuffs on NASVM10
25 May 2023 13:06:00 Presence Join: Daz Kuffs on NASVM10
25 May 2023 14:33:31 Channel_StateChanged: Joining
25 May 2023 14:33:31 Channel_StateChanged: Joined
25 May 2023 14:33:31 Presence Sync: Daz Kuffs on NASVM10
25 May 2023 14:33:32 Presence Sync:
25 May 2023 14:33:32 Presence Leave: Daz Kuffs on NASVM10
25 May 2023 15:35:34 Presence Sync: Daz Kuffs on RAGE
25 May 2023 15:35:34 Presence Join: Daz Kuffs on RAGESo I left it overnight.
This is the entire log:
25 May 2023 15:42:26 Channel_StateChanged: Joining
25 May 2023 15:42:26 Channel_StateChanged: Joined
25 May 2023 15:42:26 Channel 11111111-1111-1111-1111-111111111111 Connected
25 May 2023 15:42:26 Presence Sync:
25 May 2023 15:42:26 Presence Sync: Daz Kuffs on NASVM10
25 May 2023 15:42:26 Presence Join: Daz Kuffs on NASVM10
- Left it to its own devices here-
25 May 2023 17:31:32 Channel_StateChanged: Joining
25 May 2023 17:31:32 Channel_StateChanged: Joined
25 May 2023 17:31:32 Presence Sync: Daz Kuffs on NASVM10
25 May 2023 17:31:32 Presence Sync:
25 May 2023 17:31:32 Presence Leave: Daz Kuffs on NASVM10When I returned at around 8:15AM, I saw that I had again erroneously left the channel after just under 2 hours.
I tried connecting to the channel from my desktop computer but my presence was not detected on NasVM10 so I believe the connection was broken there.
Interesting point. I seem to get Channel_StateChanged: Joined without ever getting Channel_StateChanged: Leave
Do I maybe have to retrack after a Join event?
acupofjose
commented
1 year ago Hm. That may be it? After joining a channel, a presence is only registered if Track is called. So yes, why not try adding a call to Track when you receive a Joined state change! (If that works, I suppose we need to keep track of the last sent track event arguments and resend on reconnect internally.)
Also, if you could add two debug handlers for me:
client.AddDebugHandler((_, message, _) => Debug.WriteLine(message));
client.Socket!.AddErrorHandler((_, ex) => Debug.WriteLine(ex.Message));Apologies, I've been trying to figure out how to handle testing against network errors and rejoins, but I can't figure out a way to simulate failures in a reproducible way for the testing suite. I wonder why the it's ~1:45:00 minutes that the disconnect happens. Is that timeframe pretty consistent too?
Kuffs2205
commented
1 year ago I'll add the retrack and also log it.
I've added the extra handlers and configured them to log to my event file.
After I read your last message, I checked in on the VM and saw the following:
``` 26 May 2023 08:38:58 Channel 11111111-1111-1111-1111-111111111111 Disconnected 26 May 2023 08:39:07 Channel_StateChanged: Joining 26 May 2023 08:39:07 Channel_StateChanged: Joined 26 May 2023 08:39:07 Channel 11111111-1111-1111-1111-111111111111 Connected 26 May 2023 08:39:07 Presence Sync: 26 May 2023 08:39:07 Presence Sync: Daz Kuffs on NASVM10 26 May 2023 08:39:07 Presence Join: Daz Kuffs on NASVM10 26 May 2023 10:08:28 Channel_StateChanged: Joining 26 May 2023 10:08:29 Channel_StateChanged: Joined 26 May 2023 10:08:29 Presence Sync: Daz Kuffs on NASVM10 ```
No leave event this time BUT connecting to the channel from a different computer (at around 14:00) showed that the connection was broken as no presence was received at the VM. Maybe the channel was shut down on the server side as it detected there was nobody joined. The client just didn't realise it.
Looking at the 3 logs so far. 1: Presence Join @ 13:06 Channel Rejoin @ 14:33 = 87 Minutes Apart 2: Presence Join @ 15:42 Channel Rejoin @ 17:31 = 109 Minutes Apart 3: Presence Join @ 08:39 Channel Rejoin @ 10:08 = 89 Minutes Apart
I would say this so far is pretty consistent at around 100 minutes with about a 10 min deviation.
I understand that some things are really hard to test when they depend on certain hard to reproduce events. In this case, it is fine for 90 minutes then "something" happens. No unit test is ever going to work for that. Hopefully the debug logs will point you in the right direction. I'm trimming the message just for clarity. The log is quite unreadable when it shows the entire thing with all the line feeds.
So far I have got the following:
``` 26 May 2023 14:03:40 Channel_StateChanged: Joining 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Push [topic: realtime:111111111111111111111... Exception: 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:03:40 Channel_StateChanged: Joined 26 May 2023 14:03:40 Sending Track Event 26 May 2023 14:03:40 Channel 11111111-1111-1111-1111-111111111111 Connected 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Push [topic: realtime:111111111111111111111... Exception: 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Message Received: {"event":"presence_state"... Exception: 26 May 2023 14:03:40 Presence Sync: 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:03:40 Realtime Client Debug: Message:Socket Message Received: {"event":"presence_diff",... Exception: 26 May 2023 14:03:40 Presence Sync: Daz Kuffs on NASVM10 26 May 2023 14:03:40 Presence Join: Daz Kuffs on NASVM10 26 May 2023 14:03:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:03:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:04:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:04:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:04:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:04:35 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:04:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:04:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:05:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:05:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:05:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:05:35 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:05:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:05:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:06:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:06:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:06:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:06:35 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:06:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:06:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:07:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:07:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:07:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:07:36 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:07:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:07:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:08:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:08:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:08:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:08:35 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:08:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:08:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:09:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:09:15 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:09:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:09:35 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:09:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:09:55 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:10:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:10:16 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:10:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:10:36 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:10:55 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:10:56 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:11:15 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 14:11:16 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 14:11:35 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: ```
It looks like the final log could be quite large.
Kuffs2205
commented
1 year ago It seems like the Rejoin is triggered by a server disconnection. No exceptions thrown. Only messages.
The 100 minute time doesn't seem relevant any more as this time it stayed connected for around 4 hours.
``` 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Disconnection: ByServer Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Closed at 26/05/2023 18:08:41 Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Disconnection: Lost Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Closed at 26/05/2023 18:08:41 Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Reconnection: Lost Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket State Change: Reconnect Exception: 26 May 2023 18:08:41 Channel_StateChanged: Joining 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Push [topic: realtime:111111111111111111111... Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Connected to: wss://xavzzdpfjcvkvysesbhz.su... Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket State Change: Open Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Push [topic: phoenix, event: heartbeat, ref... Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Message Received: {"event":"phx_reply","pay... Exception: 26 May 2023 18:08:41 Channel_StateChanged: Joined 26 May 2023 18:08:41 Realtime Client Debug: Message:Socket Message Received: {"event":"presence_state"... Exception: 26 May 2023 18:08:41 Presence Sync: Daz Kuffs on NASVM10 26 May 2023 18:08:42 Realtime Client Debug: Message:Socket Message Received: {"event":"presence_diff",... Exception: 26 May 2023 18:08:42 Presence Sync: 26 May 2023 18:08:42 Presence Leave: Daz Kuffs on NASVM10 ```
I did ask it to retrack after a rejoin but it didn't. I can only assume it was prevented by this line in my code.
Sub Track()
If Channel Is Nothing OrElse Not Channel.IsSubscribed Then Return
LoggingService.GetInstance.Post($"Sending Track Event", eLogType.Realtime)
......
End SubI am assuming the channel is not re-subscribed after the rejoin? At the very least, it doesn't seem to be subscribed in time.
I just tried removing the IsSubscribed requirement and saw this:
``` 27 May 2023 09:44:13 Channel_StateChanged: Joined 27 May 2023 09:44:13 Tracking: Channel Subscribed:False 27 May 2023 09:44:13 Sending Track Event 27 May 2023 09:44:13 Realtime Client Debug Message: Socket Push [topic: realtime:11111111111111111111111111111111, event: presence, ref: dca818fb-5e6a-4541-8997-b490a9f04bcb]: { "event": "track", "payload": { "LastSeen": "2023-05-27T08:44:13.7096456Z", "Email": "redacted@gmail.com",... 27 May 2023 09:44:13 Tracking: Channel Subscribed:True 27 May 2023 09:44:13 Sending Track Event 27 May 2023 09:44:13 Realtime Client Debug Message: Socket Push [topic: realtime:11111111111111111111111111111111, event: presence, ref: e3c0f1ae-0b6d-44ce-83d6-390becaa7f57]: { "event": "track", "payload": { "LastSeen": "2023-05-27T08:44:13.710232Z", "Email": "redacted@gmail.com",... ```
It seems to suggest that just after joining, the channel is still unsubscribed for a short time. Maybe the events are triggering slightly out of order as I don't see how I could join a channel that is not yet subscribed.
I've left this running for now. We'll see how it goes after it has seen a disconnect.
acupofjose
commented
1 year ago Thanks for looking into this with so much detail!! Super helpful to have this context. The fact it’s coming from a server disconnect makes me think there’s something wrong in the reconnection logic with setting states and subscriptions back up. But. I’m out of pocket for a few days, I’ll have to get back to you early next week!
Kuffs2205
commented
1 year ago No problem. I'm not rushing to complete this. I'll just post when i have new info and you can look at it when you are free.
On Sat, 27 May 2023, 13:59 Joseph Schultz, @.***> wrote:
Thanks for looking into this with so much detail!! Super helpful to have this context. The fact it’s coming from a server disconnect makes me think there’s something wrong in the reconnection logic with setting states and subscriptions back up. But. I’m out of pocket for a few days, I’ll have to get back to you early next week!
— Reply to this email directly, view it on GitHub https://github.com/supabase-community/realtime-csharp/issues/29#issuecomment-1565402146, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAI7TFNNHJMCZDJSWEKVFTTXIH3BFANCNFSM6AAAAAAYHUZXUY . You are receiving this because you authored the thread.Message ID: @.***>
Kuffs2205
commented
1 year ago Some more disconnect data with an exception this time. I did forget about it so it ran for 2 days.
I'm sending the Track even though it says I'm not subscribed. It appears to work as I see an outgoing message right after.
However despite apparently rejoining the channel at 17:24:28 , 15 seconds later a Leave event is received and I'm gone. I assume the track didn't actually work as i was at that point not subscribed (apparently). It definitely seems like a small flaw in the reconnection logic.
Even though the heartbeats continue for the entire time which suggests the connection is open, joining the channel from another computer shows that presence data is not received which I assume is because I'm not in the channel.
```
27 May 2023 17:24:14 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"7a389cdf-d9f6-4eee-a355-786148b0916a","topic":"phoenix"}
27 May 2023 17:24:28 Realtime Client Debug Message: Socket Disconnection: Lost
27 May 2023 17:24:28 Realtime Client Debug Exception: The remote party closed the WebSocket connection without completing the close handshake. at System.Net.WebSockets.ManagedWebSocket.ThrowEOFUnexpected()
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource
Nothing much of interest happens after that. It is just a constant stream of:
28 May 2023 01:32:59 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: c2c16f0a-9095-4426-a5a6-ff32ec0766d1]: {}
28 May 2023 01:32:59 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"c2c16f0a-9095-4426-a5a6-ff32ec0766d1","topic":"phoenix"}
28 May 2023 01:33:19 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: bd7f4995-762b-474d-aa9e-e525be1062ed]: {}
28 May 2023 01:33:19 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"bd7f4995-762b-474d-aa9e-e525be1062ed","topic":"phoenix"}
28 May 2023 01:33:39 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 1f6500a4-7b6a-48a5-96d1-19688e68da00]: {}I do see a couple of anomalies which just appears to be reconnections after errors but I've included them here so you can see the type of errors encountered:
28 May 2023 01:34:39 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 488baf33-24a7-4018-a10f-b0efa4e9ce9d]: {}
28 May 2023 01:34:44 Realtime Client Debug Message: Socket Disconnection: NoMessageReceived
28 May 2023 01:34:44 Realtime Client Debug Message: Socket Closed at 28/05/2023 01:34:44
28 May 2023 01:34:45 Realtime Client Debug Message: Socket Reconnection: NoMessageReceived
28 May 2023 01:34:45 Realtime Client Debug Message: Socket State Change: Reconnect
28 May 2023 01:34:45 Realtime Client Debug Message: Socket Connected to: wss://xavzzdpfjcvkvysesbhz.supabase.co/realtime/v1/websocket?apikey=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6Inhhdnp6ZHBmamN2a3Z5c2VzYmh6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE2NzI4MTgwMjksImV4cCI6MTk4ODM5NDAy...
28 May 2023 01:34:45 Realtime Client Debug Message: Socket State Change: Open
28 May 2023 01:34:45 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 494abf3d-cce1-4d7a-9313-fd05e9f8e632]: {}
28 May 2023 01:34:45 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":28 May 2023 11:37:38 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: f798212c-005f-41d2-9e60-94b1463873b8]: {}
28 May 2023 11:37:38 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"f798212c-005f-41d2-9e60-94b1463873b8","topic":"phoenix"}
28 May 2023 11:37:45 Realtime Client Debug Message: Socket Disconnection: Lost
28 May 2023 11:37:45 Realtime Client Debug Exception: The remote party closed the WebSocket connection without completing the close handshake. at System.Net.WebSockets.ManagedWebSocket.ThrowEOFUnexpected()
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
at Websocket.Client.WebsocketClient.Listen(WebSocket client, CancellationToken token)
28 May 2023 11:37:45 Realtime Client Debug Message: Next reconnection attempt will occur at: 28/05/2023 11:38:30
28 May 2023 11:37:45 Realtime Client Debug Message: Socket Reconnection: Lost
28 May 2023 11:37:45 Realtime Client Debug Message: Socket State Change: Reconnect
28 May 2023 11:37:45 Realtime Client Debug Message: Socket Connected to: wss://xavzzdpfjcvkvysesbhz.supabase.co/realtime/v1/websocket?apikey=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6Inhhdnp6ZHBmamN2a3Z5c2VzYmh6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE2NzI4MTgwMjksImV4cCI6MTk4ODM5NDAy...
28 May 2023 11:37:45 Realtime Client Debug Message: Socket State Change: Open
28 May 2023 11:37:45 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 9ebab991-cce4-4577-8534-2801d1618c4b]: {}
28 May 2023 11:37:45 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"9ebab991-cce4-4577-8534-2801d1618c4b","topic":"phoenix"}
28 May 2023 11:38:05 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 92e48ef3-97aa-41fd-80fa-229dd21856f7]: 28 May 2023 17:23:13 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: d03a90f1-9ef2-458c-bedc-a382ac250cc6]: {}
28 May 2023 17:23:13 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"d03a90f1-9ef2-458c-bedc-a382ac250cc6","topic":"phoenix"}
28 May 2023 17:23:33 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: a5489736-dfba-4b20-95eb-624d1efe29ae]: {}
28 May 2023 17:23:33 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"a5489736-dfba-4b20-95eb-624d1efe29ae","topic":"phoenix"}
28 May 2023 17:23:45 Realtime Client Debug Message: Socket Disconnection: Lost
28 May 2023 17:23:45 Realtime Client Debug Exception: The remote party closed the WebSocket connection without completing the close handshake. at System.Net.WebSockets.ManagedWebSocket.ThrowEOFUnexpected()
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
at Websocket.Client.WebsocketClient.Listen(WebSocket client, CancellationToken token)
28 May 2023 17:23:45 Realtime Client Debug Message: Next reconnection attempt will occur at: 28/05/2023 17:24:30
28 May 2023 17:23:45 Realtime Client Debug Message: Socket Reconnection: Lost
28 May 2023 17:23:45 Realtime Client Debug Message: Socket State Change: Reconnect
28 May 2023 17:23:45 Realtime Client Debug Message: Socket Connected to: wss://xavzzdpfjcvkvysesbhz.supabase.co/realtime/v1/websocket?apikey=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6Inhhdnp6ZHBmamN2a3Z5c2VzYmh6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE2NzI4MTgwMjksImV4cCI6MTk4ODM5NDAy...
28 May 2023 17:23:45 Realtime Client Debug Message: Socket State Change: Open
28 May 2023 17:23:45 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: 8f18ecf9-ad5d-4074-b085-cfe6d26e766e]: {}
28 May 2023 17:23:45 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"8f18ecf9-ad5d-4074-b085-cfe6d26e766e","topic":"phoenix"}
28 May 2023 17:24:05 Realtime Client Debug Message: Socket Push [topic: phoenix, event: heartbeat, ref: b37c4a2e-aa0d-461d-82f9-65de81715e37]: {}
28 May 2023 17:24:05 Realtime Client Debug Message: Socket Disconnection: Lost
28 May 2023 17:24:05 Realtime Client Debug Exception: The remote party closed the WebSocket connection without completing the close handshake. at System.Net.WebSockets.ManagedWebSocket.ThrowEOFUnexpected()
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TResult](Memory`1 payloadBuffer, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
at Websocket.Client.WebsocketClient.Listen(WebSocket client, CancellationToken token)
28 May 2023 17:24:05 Realtime Client Debug Message: Next reconnection attempt will occur at: 28/05/2023 17:24:50
28 May 2023 17:24:06 Realtime Client Debug Message: Socket Reconnection: Lost
28 May 2023 17:24:06 Realtime Client Debug Message: Socket State Change: Reconnect
28 May 2023 17:24:06 Realtime Client Debug Message: Socket Connected to: wss://xavzzdpfjcvkvysesbhz.supabase.co/realtime/v1/websocket?apikey=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJzdXBhYmFzZSIsInJlZiI6Inhhdnp6ZHBmamN2a3Z5c2VzYmh6Iiwicm9sZSI6ImFub24iLCJpYXQiOjE2NzI4MTgwMjksImV4cCI6MTk4ODM5NDAy...
28 May 2023 17:24:06 Realtime Client Debug Message: Socket State Change: OpenMay not be relevant to this issue so possibly needs its own thread but just in case:
I noticed that sending a Track Event manually whilst already joined to the channel causes both a Join and Leave eventto be raised. However, the Leave event is raised after the join making it appear as though I left when I didn't.
29 May 2023 12:08:29 Sending Track Event
29 May 2023 12:08:29 Realtime Client Debug Message: Socket Push [topic: realtime:11111111111111111111111111111111, event: presence, ref: 5d6df879-afa3-4961-8eea-c8f548630ad9]: { "event": "track", "payload": { "LastSeen": "2023-05-29T11:08:29.1576795Z", "Email": "xxx@gmail.com", "Name": "Daz Kuffs", "ComputerName": "RAGE", "UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a", "ConnectID": "00000000-0000-0000-0000-000000000000", "SharedInstances": [ { "InstanceID": "409f44f0-0542-49bc-bec5-47de2b59be48", "InstanceName": "Ruffster", "ComputerName": "RAGE", "RemoteComputerID": "1a796a13-bd00-4a35-835e-648682a2601b", "UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a" } ] }}
29 May 2023 12:08:29 Realtime Client Debug Message: Socket Message Received: {"event":"phx_reply","payload":{"response":{},"status":"ok"},"ref":"5d6df879-afa3-4961-8eea-c8f548630ad9","topic":"realtime:11111111111111111111111111111111"}
29 May 2023 12:08:29 Realtime Client Debug Message: Socket Message Received: {"event":"presence_diff","payload":{"joins":{"145bacf8-fe11-11ed-9abb-6a2047d90b67":{"metas":[{"phx_ref":"F2OYoo6yrtA9v9zm","phx_ref_prev":"F2OYnFmge_Q9v3RI","ComputerName":"RAGE","ConnectID":"00000000-0000-0000-0000-000000000000","Email":"kuffs2205@gmail.com","LastSeen":"2023-05-29T11:08:29.1576795Z","Name":"Daz Kuffs","SharedInstances":[{"ComputerName":"RAGE","InstanceID":"409f44f0-0542-49bc-bec5-47de2b59be48","InstanceName":"Ruffster","RemoteComputerID":"1a796a13-bd00-4a35-835e-648682a2601b","UserID":"7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"}],"UserID":"7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"}]}},"leaves":{"145bacf8-fe11-11ed-9abb-6a2047d90b67":{"metas":[{"phx_ref":"F2OYnFmge_Q9v3RI","ComputerName":"RAGE","ConnectID":"00000000-0000-0000-0000-000000000000","Email":"xxx@gmail.com","LastSeen":"2023-05-29T11:08:02.5031865Z","Name":"Daz Kuffs","SharedInstances":[{"ComputerName":"RAGE","InstanceID":"409f44f0-0542-49bc-bec5-47de2b59be48","InstanceName":"Ruffster","RemoteComputerID":"1a796a13-bd00-4a35-835e-648682a2601b","UserID":"7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"}],"UserID":"7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"}]}}},"ref":null,"topic":"realtime:11111111111111111111111111111111"}
29 May 2023 12:08:29 Presence Sync: Daz Kuffs on RAGE
29 May 2023 12:08:29 Presence Join: Daz Kuffs on RAGE
29 May 2023 12:08:29 Presence Leave: Daz Kuffs on RAGEI notice that the Json for the Join Event apparently (with my limited knowledge) contains a reference to the Leave event in the : phx_ref_prev field.
Maybe some internal magic needs to check for this and not raise events when they cancel each other out. Personally, I feel that this should only have raised a Sync event and neither a Join or Leave.
Here is the Json for easier viewing.
{
"event": "presence_diff",
"payload":
{
"joins":
{
"145bacf8-fe11-11ed-9abb-6a2047d90b67":
{
"metas":
[
{
"ComputerName": "RAGE",
"ConnectID": "00000000-0000-0000-0000-000000000000",
"Email": "xxx@gmail.com",
"LastSeen": "2023-05-29T11:08:29.1576795Z",
"Name": "Daz Kuffs",
"phx_ref": "F2OYoo6yrtA9v9zm",
"phx_ref_prev": "F2OYnFmge_Q9v3RI", ' MATCH '
"SharedInstances":
[
{
"ComputerName": "RAGE",
"InstanceID": "409f44f0-0542-49bc-bec5-47de2b59be48",
"InstanceName": "Ruffster",
"RemoteComputerID": "1a796a13-bd00-4a35-835e-648682a2601b",
"UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"
}
],
"UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"
}
]
}
},
"leaves":
{
"145bacf8-fe11-11ed-9abb-6a2047d90b67":
{
"metas":
[
{
"ComputerName": "RAGE",
"ConnectID": "00000000-0000-0000-0000-000000000000",
"Email": "xxx@gmail.com",
"LastSeen": "2023-05-29T11:08:02.5031865Z",
"Name": "Daz Kuffs",
"phx_ref": "F2OYnFmge_Q9v3RI", ' MATCH '
"SharedInstances":
[
{
"ComputerName": "RAGE",
"InstanceID": "409f44f0-0542-49bc-bec5-47de2b59be48",
"InstanceName": "Ruffster",
"RemoteComputerID": "1a796a13-bd00-4a35-835e-648682a2601b",
"UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"
}
],
"UserID": "7aaab6a9-fe93-47e9-a3d0-eb717389cf9a"
}
]
}
}
},
"ref": null,
"topic": "realtime:11111111111111111111111111111111"
}
chasers
commented
1 year ago Hiya ... question, is this happening locally or only when you connect to Realtime hosted?
chasers
commented
1 year ago Also ... can you try this lib: https://github.com/Mazyod/PhoenixSharp#phoenixjs
And see if it's happening with that?
Realtime is just some custom payloads on top of Phoenix. And if there is a bug in the server side socket code you should see errors in https://app.supabase.com/project/_/logs/realtime-logs (show last 24 hours of logs).
payload protocol is here: https://supabase.com/docs/guides/realtime/protocol
But I've been looking into this issue for someone and don't see any backend Channel errors for their project.
They also say that they won't get disconnected while database records are coming through.
Maybe setup a "ping" table to listen to and have pg_cron insert something there every 5 minutes and see what happens.
chasers
commented
1 year ago btw not trying to knock this lib or anything just trying to figure out if it's a backend issue we need to fix.
nuno84
commented
1 year ago Hello all, It seems I am experiencing the same behavior. I have the following single file C# console application (.net 7.0) project all pasted below. It sends a broadcast count every second. I have a Flutter app to check the 'output'. After a couple of hours it keeps printing in the loop (I don't see any other message) and even if I restart the Flutter app (so it is not an issue on the receiving end) it is not showing activity on the receiving end anymore. The last time it stopped below 3000 seconds. Any ideas? I can push both projects into a public github repo if it is useful. Thank you
using Newtonsoft.Json;
using Postgrest.Responses;
using Supabase.Realtime.Models;
using System.Diagnostics;
using Websocket.Client.Logging;
using static Supabase.Realtime.Interfaces.IRealtimeChannel;
using static Supabase.Realtime.Interfaces.IRealtimePresence;
namespace SupabaseRealtimeTestApp
{
internal class Program
{
class CounterBroadcast : BaseBroadcast
{
[JsonProperty("counter")]
public int Counter { get; set; }
}
class UserPresence : BasePresence { }
static async Task Main(string[] args)
{
Console.WriteLine("Hello, World!");
try
{
var url = SUPABASE_PROJ_URL;
var key = ANON_KEY;
var options = new Supabase.SupabaseOptions
{
AutoConnectRealtime = true,
AutoRefreshToken = true
};
var supabase = new Supabase.Client(url, key, options);
await supabase.InitializeAsync();
// Broadcast setup
var broadcastChannel = supabase.Realtime.Channel("CHANNEL_KEY");
var broadcast = broadcastChannel.Register<CounterBroadcast>();
broadcast.AddBroadcastEventHandler((sender, baseBroadcast) =>
{
var response = broadcast.Current();
Console.WriteLine($"Broadcast received");
});
broadcastChannel.AddStateChangedHandler((sender, state) => Console.WriteLine($"Broadcast channel State changed: {state}"));
broadcastChannel.AddErrorHandler((_, ex) => Console.WriteLine($"Broadcast channel Error handler changed: {ex.Message}"));
await broadcastChannel.Subscribe();
// Presence setup
var presenceChannel = supabase.Realtime.Channel("presence_channel");
var presence = presenceChannel.Register<UserPresence>("MICKEY_MOUSE");
presenceChannel.AddStateChangedHandler((sender, state) => Console.WriteLine($"Presence channel State changed: {state}"));
presence.AddPresenceEventHandler(EventType.Join, (sender, type) =>
{
Console.WriteLine($"JOIN");
var state = presence.CurrentState;
});
presence.AddPresenceEventHandler(EventType.Sync, (sender, type) =>
{
Console.WriteLine($"The Event Type: {type}");
var state = presence.CurrentState;
});
presenceChannel.AddErrorHandler((_, ex) => Console.WriteLine($"Presence channel Error handler changed: {ex.Message}"));
await presenceChannel.Subscribe();
//Send alive signal
Console.WriteLine("Alive set");
presence.Track(new UserPresence { });
int counter = 1;
while (true)
{
broadcast.Send("counter", new CounterBroadcast { Counter = counter++ });
Console.WriteLine($"Sent broadcast: {counter}");
await Task.Delay(TimeSpan.FromMilliseconds(1000));
}
}
catch (Exception ex)
{
Console.WriteLine($"Exception thrown: {ex.Message}");
Environment.Exit(1);
}
}
}
}I've been doing some testing.
I did a Flutter app to also send the same broadcast message to the same channel every second.
I ran both C# and Flutter broadcast emitters at the same time.
For the last 4h or so, the C# app failed about 3 times while the Flutter app kept sending without issues.
I also tried to set broadcastSelf: true on the C# app and after the failure happens it didn't receive any of those 2 broadcast messages (C# + Flutter).
It suggests to me that it is a C# lib issue.
Any idea on how to tackle it?
I will keep the apps running and write a follow-up if I get any new insight.
Thanks
nuno84
commented
1 year ago Update on this: I added some more event handlers on the broadcast channel and this break in the pattern happens:
..... [CHANNEL_KEY] Sent broadcast: 395 Broadcast channel AddMessageReceivedHandler: broadcast Received: 394 Broadcast channel AddMessageReceivedHandler: broadcast Received: 9856 [CHANNEL_KEY] Sent broadcast: 396 Broadcast channel AddMessageReceivedHandler: broadcast Received: 395 [CHANNEL_KEY] Sent broadcast: 397 [CHANNEL_KEY] Sent broadcast: 398 Broadcast channel AddMessageReceivedHandler: phx_reply [CHANNEL_KEY] Sent broadcast: 399 Broadcast channel AddMessageReceivedHandler: phx_reply [CHANNEL_KEY] Sent broadcast: 400 Broadcast channel AddMessageReceivedHandler: phx_reply [CHANNEL_KEY] Sent broadcast: 401 Broadcast channel AddMessageReceivedHandler: phx_reply [CHANNEL_KEY] Sent broadcast: 402 Broadcast channel AddMessageReceivedHandler: phx_reply [CHANNEL_KEY] Sent broadcast: 403
So he was printing a broadcast event and suddently started printing a phx_reply instead. I stopped the debugging on that point and inspected the reply:
{"event":"phx_reply","payload":{"response":{"reason":"unmatched topic"},"status":"error"},"ref":"9be2825b-9969-42f7-a0f3-b78f64eddf63","topic":"realtime:CHANNEL_KEY"}
I think the error is now spotted. In the meanwhile the Flutter broadcast emitter keeps sending it without any issue.
Thank you
acupofjose
commented
1 year ago @nuno84 thanks for your investigation! An unmatched topic.... hm. Maybe that's an edgecase that requires resubscribing to the broadcast channel? This is a new error for me to see! I'm planning on looking into this today.
nuno84
commented
1 year ago Hi @acupofjose, I have been trying to provoque it, but it doesn't seem easy to do. Sometime it takes 10 min, sometimes it takes > 2 hours to happen. For some reason it gets a 'LOST' on HandleSocketReconnectionHappened callback and it sets the IsSubscribed to false. If I try to remove the internet cable, it recovers afterwards, so yes, that seems an edgecase. By the way are you (or someone else) using this lib in production? I am looking into creating a windows service, but the connection reliability is key since there will be no user interaction to restart the process. That is why this error is bugging me. If I can help you to solve this issue, please tell me how. I am glad to help. Thank you once again.
nuno84
commented
1 year ago I git cloned the supabase_realtime lib and added a couple breakpoints to try to get more insight. I made a print-screen on the error entry point, maybe it can help. It then stops broadcasting the event and never recovers. Thank you
nuno84
commented
1 year ago BTW, some details:
Exception message: "The remote party closed the WebSocket connection without completing the close handshake."
Stacktrace:
at System.Net.WebSockets.ManagedWebSocket.ThrowEOFUnexpected()
at System.Net.WebSockets.ManagedWebSocket.1.StateMachineBox1.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
at System.Net.WebSockets.ManagedWebSocket.1.MoveNext() at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder1.StateMachineBox1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token) at System.Threading.Tasks.ValueTask1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
at Websocket.Client.WebsocketClient.
acupofjose
commented
1 year ago @nuno84 could you try your test case using #33?
nuno84
commented
1 year ago Hi @acupofjose, The changes you made make sense to me. I am already putting it into test today, lets wait and see. I will provide feedback soon. BTW, about the production subject, do you think it is mature/reliable enough to put it to use in a no-user-interface service running 24/7? Thank you
acupofjose
commented
1 year ago @nuno84, I'm not presently using the realtime functionality for anything publicly in production. Everything I have used it for has been for personal projects. For what I've been using it for (basic messaging, realtime updates) it's worked just fine for me. All of the websocket connectivity is coming from the Websocket.Client library which I think is mature enough to be trustworthy. But, ultimately that's a choice up to you! Hope that helps.
nuno84
commented
1 year ago I spent most of the day testing it and it didn't fail. I think you can release an update. I hope I will keep working with lib and and if something else comes up, will keep you updated. Thank you once again for your help.
Is there a specific process to keep the Realtime Client connected? I seem to be having trouble doing so. I'm unsure if I am supposed to respond to the events to handle errors and reconnect manually or if the client is supposed to do that itself.
For example, I connect to a channel. Presence works fine to start. I then leave the application running whilst logging the RealtimeClient and Presence event handlers as they are called.
After a few hours I start getting events being logged. It seems relatively normal as there are Open, Close & Reconnect events which I would expect.
Should the Error event not say what the error was?
After some time, there are only Close events. When I return to the application in the morning, Presence is no longer working. I assume the connection is broken.
What makes me think that there is library issue is that there are a disproportionate number of Close events. I would expect each Close to have a matching Open.
Here are the logs.