Incorrect extra chips displayed

[ctm]

Find and fix the UI bug that can make it look like someone was awarded more chips than that player was actually awarded.

Yesterday's evening tournament had a table hang (#1271) but also had a UI glitch that made it look like ADB DaVoice got more chips than he did. @ts4z:

ts4z: the poker bug gods have awared ADB DaVoice a bonus 586k in chips

…

Chip count bug may be cosmetic. After the break, our table refreshed with the right players and reasonable chip counts. It was, however, still frozen.

This was on table 5563, I believe.

FWIW, mb2's client has an "action tracker" that keeps track of the current round's action independently of the server. In theory, they should always agree, but the server sends out chip counts with some of its messages and those chip counts override anything the action tracker has. So, most likely there is a way that the action tracker can get confused that normally nobody sees (or it would have been reported long ago) because a Status message overwrites the error before it's displayed, but due to the pause, the error didn't get overwritten quickly enough. Obviously, I should fix the error even if I fix the pause.

I am not labeling this easy, because it may be hard to reproduce. OTOH, all the messages that were sent top ts4z's client were logged, with timestamps, so if I can't eyeball the problem, I can finally write a tool that simply replays all messages through the client and see for myself. IOW, this should be very reproducible, although it could be a while before I bite the bullet and write that tool.

[ts4z]

fwiw I don't think I was the only one that saw the increased chip count. DaVoice noticed it before I did (I saw he had a big stack, but didn't figure out what exactly it was).

DaVoice busted Grizz for 586,600 in chips in the pot; and his stack was exactly 586,600 too large during the freeze.

During this time, jpmassar also disappeared from our table.

After the break, his chip count was corrected, and when the game finally unpaused (final table?) everything was OK. jpmassar also reapparead (at least his stack did, JP wasn't really playing at that point).

[ctm]

There are a bunch of entries in public_table_messages where player_id is NOT NULL. I think those are only logged when messages are played back due to a window being closed. There are other logs that I can look at that should be able to tell me when people have closed their windows and my guess is that both @ts4z and ADB DaVoice did so at least once when the table was hung and that the problem they each saw was a bug associated with playback.

[ctm]

Ugh. I just closed the window from this evening's tournament, and I saw my "gg" message three times, which makes me think that for some reason the Chat message was replayed twice after my initial message. I wish I hadn't closed it, because there's a tiny chance that I could have found useful info in the JavaScript console. I'll check the logs tomorrow.

[ctm]

Nope. Turns out, the last three chat messages were all "gg" by me:

mb2=> select id, received_at at time zone 'america/denver', message, player_id, hand_id  from public_table_messages where table_id = 5569 and variant = 44 order by received_at;
    id    |          timezone          |                  message                   | player_id | hand_id 
----------+----------------------------+--------------------------------------------+-----------+---------
...
 10298544 | 2024-01-06 18:54:26.133932 | {"Chat": [10, "gg"]}                       |           |  387293
 10298755 | 2024-01-06 19:05:23.249029 | {"Chat": [10, "gg"]}                       |           |  387298
 10298863 | 2024-01-06 19:08:16.434324 | {"Chat": [10, "gg"]}                       |           |  387302
(32 rows)

[ctm]

FWIW, I definitely have a doubled chat line on my lobby right now.

Although my "Thanks!" chat appears twice, It was only logged through public_lobby_messages once.

mb2=> select id, received_at at time zone 'america/denver', substr(message::text, 0, 30) from public_lobby_messages where variant = 8 order by id desc limit 5;
   id   |          timezone          |            substr             
--------+----------------------------+-------------------------------
 235085 | 2024-01-16 08:40:55.248513 | {"ChatMessage": [10, "Thanks!
 235084 | 2024-01-16 08:40:53.694652 | {"ChatMessage": [10, "I've al
 235083 | 2024-01-16 08:40:33.141421 | {"ChatMessage": [10, "In case
 235038 | 2024-01-15 20:28:55.80488  | {"ChatMessage": [10, "Deploye
 235029 | 2024-01-15 20:27:20.273323 | {"ChatMessage": [10, "I'm dep
(5 rows)

I have not refreshed the page, but it's been idle long enough that I can easily imagine the websocket closing and being reopened. I think we log that in the database, too, although it's been so long that I've played with that code that I could be misremembering. If not, I can add that, because my guess is that's what's going on, only because I can't think of anything else.

[ctm]

Sure enough:

mb2=> select id, created_at at time zone 'america/denver', player_id from lobby_reconnect_requests order by id desc limit 5;
  id   |          timezone          | player_id 
-------+----------------------------+-----------
 29817 | 2024-01-16 15:59:01.225398 |        10
 29816 | 2024-01-16 07:30:31.261941 |        10
 29815 | 2024-01-15 21:12:06.867762 |        14
 29814 | 2024-01-15 20:28:21.405253 |        17
 29813 | 2024-01-15 20:28:19.357156 |        10
(5 rows)

I'll poke around the reconnect code and see what it does. FWIW, I can easily imagine that the reconnect code got invoked during the abnormal hang (which has since been fixed) where the UI made it look like there were extra chips.

[ctm]

Yup, the lobby reconnect code sends a ReplayChats message and then we do some de-duplication which apparently has an off by one error. I'll log that as a bug, but I suspect that something very similar happens to the tables, the EndOfHand message was replayed inappropriately (or processed inappropriately) during a websocket reconnect during the hang.