pont icon indicating copy to clipboard operation
pont copied to clipboard

Reconnecting player wasn't able to rejoin

Open relsqui opened this issue 1 year ago • 4 comments

This morning we had a player lose connection partway through a game, and when they re-entered the room they showed up as a new player with the same name as the previous one. I see the server code does attempt to handle this situation, so I'm not sure why it didn't work here. We never saw any kind of disconnect message for the first instance of the other player, so it's possible they were seen as still active even though they weren't. Sorry I don't have more detail, happy to help try to repro if I can.

(Also, thanks for making this! I wasn't familiar with the game before and it's fun.)

relsqui avatar Feb 19 '25 00:02 relsqui

Can you tell me a player or room name, and I can see if there's anything odd in the logs?

mkeeter avatar Feb 19 '25 00:02 mkeeter

The player was "Jon" and I don't fully remember the room name but it had I think "hasty" and "mount" in it? Something that made me think of inexpertly using Docker. :P Would have been around 8:55am PST.

relsqui avatar Feb 19 '25 01:02 relsqui

Okay, here's the relevant section of the logs (redacting other player names):

[2025-02-18T16:34:51Z INFO  pont_server] [127.0.0.1:39590] Incoming TCP connection
[2025-02-18T16:34:51Z INFO  pont_server] [127.0.0.1:39590] WebSocket connection established
[2025-02-18T16:35:04Z INFO  pont_server] [127.0.0.1:39592] Incoming TCP connection
[2025-02-18T16:35:04Z INFO  pont_server] [127.0.0.1:39592] WebSocket connection established
[2025-02-18T16:35:05Z INFO  pont_server] [127.0.0.1:39590] Creating room 'data hasty mount' for player Jon
[2025-02-18T16:35:07Z INFO  pont_server] [127.0.0.1:39594] Incoming TCP connection
[2025-02-18T16:35:07Z INFO  pont_server] [127.0.0.1:39594] WebSocket connection established
[2025-02-18T16:35:08Z INFO  pont_server] [127.0.0.1:39596] Incoming TCP connection
[2025-02-18T16:35:08Z INFO  pont_server] [127.0.0.1:39596] WebSocket connection established
[2025-02-18T16:35:16Z INFO  pont_server] [127.0.0.1:39598] Incoming TCP connection
[2025-02-18T16:35:16Z INFO  pont_server] [127.0.0.1:39598] WebSocket connection established
[2025-02-18T16:35:28Z INFO  pont_server] [127.0.0.1:39592] Player [] sent JoinRoom(data hasty mount)
[2025-02-18T16:35:28Z INFO  pont_server] [127.0.0.1:39594] Player [] sent JoinRoom(data hasty mount)
[2025-02-18T16:35:37Z INFO  pont_server] [127.0.0.1:39598] Player [] sent JoinRoom(data hasty mount)
[2025-02-18T16:36:38Z INFO  pont_server] [127.0.0.1:39596] Player [] sent JoinRoom(data hasty mount)

[2025-02-18T16:56:39Z INFO  pont_server] [127.0.0.1:39604] Incoming TCP connection
[2025-02-18T16:56:39Z INFO  pont_server] [127.0.0.1:39604] WebSocket connection established
[2025-02-18T16:56:59Z INFO  pont_server] [127.0.0.1:39604] Player Jon sent JoinRoom(data hasty mount)
[2025-02-18T16:57:09Z INFO  pont_server] [data hasty mount] Removed disconnected player 'Jon'
[2025-02-18T16:57:09Z INFO  pont_server] [127.0.0.1:39604] Finished session with Jon

[2025-02-18T16:57:13Z INFO  pont_server] [127.0.0.1:39606] Incoming TCP connection
[2025-02-18T16:57:13Z INFO  pont_server] [127.0.0.1:39606] WebSocket connection established
[2025-02-18T16:57:15Z INFO  pont_server] [127.0.0.1:39606] Player Jon sent JoinRoom(data hasty mount)
[2025-02-18T16:57:59Z INFO  pont_server] [data hasty mount] Removed disconnected player 'Jon'
[2025-02-18T16:57:59Z INFO  pont_server] [127.0.0.1:39606] Finished session with Jon

[2025-02-18T16:58:22Z INFO  pont_server] [data hasty mount] Removed disconnected player '[]'
[2025-02-18T16:58:22Z INFO  pont_server] [127.0.0.1:39592] Finished session with []

[2025-02-18T16:58:22Z INFO  pont_server] [data hasty mount] Removed disconnected player '[]'
[2025-02-18T16:58:22Z INFO  pont_server] [127.0.0.1:39598] Finished session with []

[2025-02-18T17:00:26Z INFO  pont_server] [data hasty mount] Removed disconnected player '[]'
[2025-02-18T17:00:26Z INFO  pont_server] [127.0.0.1:39594] Finished session with []

[2025-02-18T17:10:17Z INFO  pont_server] [data hasty mount] Removed disconnected player 'Jon'
[2025-02-18T17:10:17Z INFO  pont_server] [127.0.0.1:39590] Finished session with Jon

[2025-02-18T19:03:57Z INFO  pont_server] [data hasty mount] Removed disconnected player '[]'
[2025-02-18T19:03:57Z INFO  pont_server] [data hasty mount] All players left, closing room.
[2025-02-18T19:03:57Z INFO  pont_server] Closing room [data hasty mount]

It looks like the original session with Jon was on socket 39590. Notice that this session doesn't end until 2025-02-18T17:10:17Z, near the end of these logs. In other words, your attempts to rejoin failed because the server thought the original session was still connected!

I'm not sure what would cause this confusion, but it's possible that websockets aren't great about detecting certain types of disconnection; Stack Overflow suggests adding regular pings to check for connection liveness...

mkeeter avatar Feb 19 '25 01:02 mkeeter

That tracks! Thanks for looking into it. 🙏

relsqui avatar Feb 19 '25 01:02 relsqui