Table split left players without action buttons

[ctm]

Fix the bug that caused gerdog to have to log out and log back in again.

gerdog: table split works - yay. but had to do a couple of refreshes in the lobby window to get the action buttons back

[ctm]

I have not been able to reproduce this. I'll send gerdog email asking for more info, but I'm removing the easy label for now.

[ctm]

Gerdog replied quickly, but even taking his extended description into account, I don't yet have an idea of what caused his problem.

After the table split I could see the action, but I couldn't act because there were no action buttons to click. Also I had the chat in a separate window and when I tried to type something I couldn't.

I then closed the table and chat window, went back to the lobby, tried to type in the lobby chat and couldn't and then refreshed the lobby window - NOT relogged in - and the table came back still without action buttons.

I closed the table window again, went back to the lobby window. I don't remember if I refreshed the window or just closed the window and logged in at this point. Either way, the table came up with all of the controls showing.

I've pored through the logs and can see where gerdog logs out and logs back in again:

select id, received_at at time zone 'mst', message from public_lobby_messages where id >= 229119 order by received_at;
...
 229124 | 2023-11-20 18:10:59.327082 | {"TablesAdded": [4901, [5486]]}
 229125 | 2023-11-20 18:10:59.343713 | {"PlayerRemoved": [5485, 14]}
 229126 | 2023-11-20 18:10:59.348052 | {"PlayersAdded": [5486, [14]]}
 229127 | 2023-11-20 18:10:59.364849 | {"PlayerRemoved": [5485, 11]}
 229128 | 2023-11-20 18:10:59.368711 | {"PlayersAdded": [5486, [11]]}
 229129 | 2023-11-20 18:10:59.401958 | {"PlayersAdded": [5486, [9]]}
 229130 | 2023-11-20 18:11:37.482651 | {"PlayerLoggedOut": 11}
 229131 | 2023-11-20 18:11:38.810428 | {"PlayerLoggedIn": 11}
 229132 | 2023-11-20 18:12:21.472959 | {"PlayerLoggedOut": 11}
 229133 | 2023-11-20 18:12:22.649881 | {"PlayerLoggedIn": 11}
 229134 | 2023-11-20 18:15:18.049982 | {"ChatMessage": [11, "table split works - yay. but had to do a couple of refreshes in the lobby window to get the action buttons back"]}

I do, however, see a mysterious fold from before that (don't be misled by the table_id being 5485; that is not the active table, just the table_id that was used when the table session id was created and the table session id is not recreated after a move):

select table_requests.id, received_at, request, table_id from table_requests join table_sessions on table_session_id = table_sessions.id where event_id = 4901 and player_id = 11 order by received_at asc;
...
 4195339 | 2023-11-21 01:11:01.573084+00 | {"Identify": [0, [9]]}                                                             |     5485
 4195341 | 2023-11-21 01:11:04.892086+00 | {"SetAction": ["Fold", 151]}                                                |     5485

and I see the fold acknowledged:

select private_table_messages.id, received_at at time zone 'mst', message, table_id from private_table_messages join tables on table_id = tables.id where event_id = 4901 and player_id = 11 order by received_at asc;
...
 12348333 | 2023-11-20 18:11:01.35907  | {"Cards": [{"cards": [{"KnownDown": {"Natural": {"rank": 4, "suit": "Spade"}}}, {"KnownDown": {"Natural": {"rank": 11, "suit": "Diamond"}}}, {"Up": {"Natural": {"rank": 9, "suit": "Spade"}}}]}, 0]}                                                                                                                                                                                                                           |     5486
 12348335 | 2023-11-20 18:11:04.892145 | {"ActionSet": "Fold"}                                                                                                                                                                                                                                                                                                                                                                                                           |     5486
 12348337 | 2023-11-20 18:11:07.702871 | "AdvancedActionCleared"     

Perhaps an errant click clicked the fold button in some weird race condition before the button could be read or registered and after that there were no UI controls because it was no longer gerdog's turn? That seems like a huge stretch and wouldn't explain why he couldn't chat in the lobby.

This one is probably going to be very hard to track down. It'll probably have to happen to another person before I can even guess how to instrument the code to figure out what's going on.

Ugh!

[ctm]

I forgot to test this with detached chat. I don't see how that could matter, but it's certainly something I should test.

[ctm]

I have reproduced this locally. I don't know all the details yet, but I should be able to fix it today.

[ctm]

This is a bug related to the beginning of re-entry code that is in master. Specifically, this line can kill the lobby:

                status.entries_left -= 1;

inside LateRegistrationStatus::i_am_playing. The issue is that i_am_playing is called more than once, because it used to be idempotent, so all that needed be done was to have it called at the right time and if it was called again, no problem. However, when I added entries_left, that was no longer the case and by then I either had never known or forgotten i_am_playing's previous idempotency.

The solution is to either make i_am_playing idempotent again or to only call it in the right place. I don't think either will be particularly hard to do, but I lean toward the latter, at least until I review the relevant code.

FWIW, supporting re-entries (#1241) is the next feature for me to add, so it makes sense for whatever fix I add to take that into account.

[ctm]

Currently, i_am_playing gets called when the lobby receives a PlayersAdded message. The problem is, that message is sent both at the start of a tournament but also when a player is moved from table to table. Back when i_am_playing was idempotent, the extra call didn't matter.

The best solution is to send a new, short, message each time the entries_left field in EntryStatus changes and either make i_am_playing be called when that message is processed, or keep the call to i_am_playing where it is, but move the update of entries_left out of i_am_playing.

[ctm]

Nope. That'll teach me to "think out loud". The solution is to use currently_playing to gate the decrement (and to also add a test to make sure entries_left is positive:

diff --git a/lib/commands/src/types.rs b/lib/commands/src/types.rs
index 86bc0038..3e0fb887 100644
--- a/lib/commands/src/types.rs
+++ b/lib/commands/src/types.rs
@@ -1858,12 +1858,17 @@ impl LateRegistrationStatus {
     pub fn i_am_playing(&mut self) {
         use LateRegistrationStatus::*;
         match self {
-            NoLateRegistration => {}
-            LateRegistrationOver => log::warn!("I am playing, but late registration is over"),
+            NoLateRegistration | LateRegistrationOver => {}
             LateRegistrationUnavailable(status) | LateRegistrationAvailable(status) => {
-                status.entries += 1;
-                status.entries_left -= 1;
-                status.currently_playing = true;
+                if !status.currently_playing {
+                    status.entries += 1;
+                    if status.entries_left > 0 {
+                        status.entries_left -= 1;
+                    } else {
+                        log::error!("no entries left and yet we're playing");
+                    }
+                    status.currently_playing = true;
+                }
             }
         }
     }

Deploying now.