Closing table window loses level end in upper left

[ctm]

Fix so that when a player closes a table window, the new window has the level info in the upper left.

I closed my table window several times so far in this evening's game and at one point I noticed that the level info wasn't in the upper left. There's a chance that it never was, because I was looking at the chat box most of the time.

I tried again during break and the break info reappeared, but I think that's special-cased. After we were off the break, I tried again and it disappeared, so it probably always disappears. This may be a regression due to the work I did on preserving chat (#1414), but more likely it's been there "forever".

[ctm]

I've added the regression code because I can see where Table::replay sends an OnLevel message. I'm adding some dbg!() invocations and will soon know why it's either not being hit or not being processed somewhere in the chain of message processing.

[ctm]

Turns out, I can't reproduce it locally. I did, however, find a different bug (#1417). !Whee

[ctm]

I spent a bit of time looking into this today, including forcing a table split to see if that was related. I also stared at the code and couldn't see anything wrong. When it was happening, I should have switched chat mode to show the maximum number of messages and that would have given me more info, but I incorrectly assumed that it was going to be trivial to reproduce.

I'll try to reproduce this in all the evening tournaments I play in. I'll simply close my table window a bunch and see if it happens again. If it does, I'll switch chat mode and also open the JavaScript console (although I think I did that yesterday, when I saw this bug in the wild).

I haven't yet dug through the database to see if I can find anything abnormal and I'll do so "now", but mb2 deliberately chooses not to log replay messages. OTOH, I'll easily be able to see when I was closing the Table windows and that, combined with looking at the hands involved might give me a glimpse.

[ctm]

I could not reproduce this yesterday and nobody has reported it. I didn't slog through the database, but I'm going to work on some chat issues (#1418 and #1419) instead of rummaging around in the db. If this issue is still with us (and I have no reason to believe it's been fixed), I'll probably get more details and either reopen this issue or create a new one. OTOH, I'll be doing some refactoring or replay messages and there's a chance that will fix this, too, although I doubt it.

[ctm]

So, I got curious and started poking around in the db, after all, and I found something surprising which may help. First, I looked for all my sit_requests so I could see when I was closing the table window:

mb2=> select * from table_sessions where event_id = 5273 and player_id = 10;
         id         | event_id | table_id |          created_at           | player_id 
--------------------+----------+----------+-------------------------------+-----------
 185007351117258982 |     5273 |     5847 | 2024-05-16 00:05:00.694239+00 |        10
(1 row)

mb2=> select id, received_at at time zone 'america/denver', event_id, player_id, table_id from sit_requests where table_session_id = 185007351117258982 order by received_at;
  id   |          timezone          | event_id | player_id | table_id 
-------+----------------------------+----------+-----------+----------
 56317 | 2024-05-15 18:05:04.450837 |     5273 |        10 |         
 56320 | 2024-05-15 18:05:47.604845 |     5273 |        10 |         
 56321 | 2024-05-15 18:09:03.837105 |     5273 |        10 |         
 56322 | 2024-05-15 18:14:34.713125 |     5273 |        10 |         
 56325 | 2024-05-15 18:51:09.875639 |     5273 |        10 |         
 56326 | 2024-05-15 18:52:41.465518 |     5273 |        10 |         
 56331 | 2024-05-15 18:58:30.879508 |     5273 |        10 |         
 56334 | 2024-05-15 19:01:08.090715 |     5273 |        10 |         
 56337 | 2024-05-15 19:34:24.248691 |     5273 |        10 |         
(9 rows)

56325 is an example of when I saw the problem, because it was shortly before the break. I then checked to see which tables were used by this tournament:

mb2=> select id from tables where event_id = 5273 order by id;
  id  
------
 5847
 5848
 5849
(3 rows)

Then, because I'm lazy and didn't want to screw up the conversion, I looked up all my sit requests in UTC:

mb2=> select id, received_at, event_id, player_id, table_id from sit_requests where table_session_id = 185007351117258982 order by received_at;
  id   |          received_at          | event_id | player_id | table_id 
-------+-------------------------------+----------+-----------+----------
...
 56325 | 2024-05-16 00:51:09.875639+00 |     5273 |        10 |         
...
(9 rows)

Then I looked to see what private table messages were sent to me within two minutes after that reconnect:

mb2=> select id, received_at at time zone 'america/denver', hand_id, table_id, substr(message::text, 0, 160) from private_table_messages where received_at >= '2024-05-16 00:51:09.875639+00' and received_at < '2024-05-16 00:52:09.875639+00' and player_id = 10 and table_id in (5847, 5848, 5849) order by received_at;
    id    |          timezone          | hand_id | table_id |                                                                             substr                                                                              
----------+----------------------------+---------+----------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------
 13094465 | 2024-05-15 18:51:09.88819  |  405250 |     5849 | {"Preference": {"sound": 59, "seating": {"seats": [null, null, null, null, null, null, null, null, null], "auto_center": "OnlyWhenAutoSeated"}, "deck_color": "
 13094466 | 2024-05-15 18:51:09.893036 |         |     5847 | {"Identities": [[11, "gerdog"], [10, "deadhead"], [6, "smalltalkdan"], [37, "ts4z"], [3, "Chuck"], [9, "Grizz"]]}
 13094467 | 2024-05-15 18:51:10.015824 |         |     5849 | {"Cards": [{"cards": [{"KnownDown": {"Natural": {"rank": 13, "suit": "Diamond"}}}, {"KnownDown": {"Natural": {"rank": 3, "suit": "Spade"}}}, {"KnownDown": {"Na
 13094468 | 2024-05-15 18:51:10.032482 |         |     5849 | "AdvancedActionCleared"
 13094469 | 2024-05-15 18:51:10.046643 |         |     5849 | "AdvancedActionCleared"
 13094470 | 2024-05-15 18:51:10.075028 |         |     5849 | {"Cards": [{"cards": [{"KnownDown": {"Natural": {"rank": 13, "suit": "Diamond"}}}, {"KnownDown": {"Natural": {"rank": 3, "suit": "Spade"}}}, {"KnownDown": {"Na
 13094471 | 2024-05-15 18:51:10.079911 |         |     5849 | "AdvancedActionCleared"
 13094472 | 2024-05-15 18:51:10.096434 |         |     5849 | "AdvancedActionCleared"
 13094473 | 2024-05-15 18:51:10.114723 |         |     5849 | "AdvancedActionCleared"
 13094474 | 2024-05-15 18:51:10.137089 |         |     5849 | "AdvancedActionCleared"
 13094475 | 2024-05-15 18:51:10.146255 |         |     5849 | {"Preference": {"sound": 59, "seating": {"seats": [null, null, null, null, null, null, null, null, null], "auto_center": "OnlyWhenAutoSeated"}, "deck_color": "
 13094507 | 2024-05-15 18:51:12.081208 |  405251 |     5849 | {"Cards": [{"cards": [{"KnownDown": {"Natural": {"rank": 7, "suit": "Diamond"}}}, {"KnownDown": {"Natural": {"rank": 9, "suit": "Heart"}}}, {"KnownDown": {"Nat
 13094509 | 2024-05-15 18:51:12.081223 |  405251 |     5849 | "AdvancedActionCleared"
 13094510 | 2024-05-15 18:51:24.526973 |  405251 |     5849 | "AdvancedActionCleared"
 13094522 | 2024-05-15 18:51:46.492268 |  405253 |     5849 | {"Cards": [{"cards": [{"KnownDown": {"Natural": {"rank": 6, "suit": "Club"}}}, {"KnownDown": {"Natural": {"rank": 7, "suit": "Heart"}}}, {"KnownDown": {"Natura
 13094525 | 2024-05-15 18:51:49.905816 |  405253 |     5849 | {"ActionSet": {"Call": {"N": 0}}}
 13094529 | 2024-05-15 18:51:51.99148  |  405253 |     5849 | "AdvancedActionCleared"
(17 rows)

Identities was sent to table 5847. WTF? Clearly I was at table 5849.

So, now I'll look at who sends Identities and under what conditions and more specifically, where it gets the table_id from. It's been a couple days, but I'm pretty sure that tournament started with a single table, which would have been 5847 and that I started at that table. At some point I'll double check, but it looks to me like something might be caching the table id incorrectly, or not updating the cache properly. Since I tested table splitting from late registration, perhaps it's a table merge that's not doing it.

In fact, before I look at who sends Identities, I'll figure out how to dump which tables I was at, when. I think I just need to dump the MovedTo and MovedFrom variants (51 and 52).

[ctm]

Here are the moves, followed by the table creation times.

mb2=> select id, received_at at time zone 'america/denver', hand_id, table_id, message from public_table_messages where player_id is NULL and variant in (51, 52) and table_id in (5847, 5848, 5849) order by received_at;
    id    |          timezone          | hand_id | table_id |                      message                       
----------+----------------------------+---------+----------+----------------------------------------------------
 10877848 | 2024-05-15 18:16:18.708286 |  405167 |     5848 | {"MovedFrom": [11, 5847, "gerdog", null]}
 10877849 | 2024-05-15 18:16:18.713119 |  405167 |     5847 | {"MovedTo": [11, 5848]}
 10877850 | 2024-05-15 18:16:18.730897 |  405167 |     5848 | {"MovedFrom": [37, 5847, "ts4z", null]}
 10877851 | 2024-05-15 18:16:18.738805 |  405167 |     5847 | {"MovedTo": [37, 5848]}
 10878615 | 2024-05-15 18:22:36.808481 |  405194 |     5848 | {"MovedFrom": [9, 5847, "Grizz", null]}
 10878616 | 2024-05-15 18:22:36.813006 |  405197 |     5847 | {"MovedTo": [9, 5848]}
 10878617 | 2024-05-15 18:22:36.835838 |  405194 |     5848 | {"MovedFrom": [13, 5847, "🐭GamboMouse", null]}
 10878618 | 2024-05-15 18:22:36.840792 |  405197 |     5847 | {"MovedTo": [13, 5848]}
 10878619 | 2024-05-15 18:22:36.855668 |  405194 |     5848 | {"MovedFrom": [17, 5847, "ODB Phat Mack🐺", null]}
 10878620 | 2024-05-15 18:22:36.860338 |  405197 |     5847 | {"MovedTo": [17, 5848]}
 10878621 | 2024-05-15 18:22:36.873538 |  405194 |     5848 | {"MovedFrom": [10, 5847, "deadhead", null]}
 10878622 | 2024-05-15 18:22:36.878515 |  405197 |     5847 | {"MovedTo": [10, 5848]}
 10880117 | 2024-05-15 18:48:54.969427 |  405238 |     5849 | {"MovedFrom": [10, 5848, "deadhead", null]}
 10880118 | 2024-05-15 18:48:54.974283 |  405238 |     5848 | {"MovedTo": [10, 5849]}
 10880119 | 2024-05-15 18:48:54.988483 |  405238 |     5849 | {"MovedFrom": [9, 5848, "Grizz", null]}
 10880120 | 2024-05-15 18:48:54.993715 |  405238 |     5848 | {"MovedTo": [9, 5849]}
 10881830 | 2024-05-15 19:06:45.383316 |  405289 |     5849 | {"MovedFrom": [40, 5848, "margaretsm", null]}
 10881831 | 2024-05-15 19:06:45.388256 |  405290 |     5848 | {"MovedTo": [40, 5849]}
 10881832 | 2024-05-15 19:06:45.402204 |  405289 |     5849 | {"MovedFrom": [3, 5848, "Chuck", null]}
 10881833 | 2024-05-15 19:06:45.407121 |  405290 |     5848 | {"MovedTo": [3, 5849]}
 10881834 | 2024-05-15 19:06:45.42125  |  405289 |     5849 | {"MovedFrom": [13, 5848, "🐭GamboMouse", null]}
 10881835 | 2024-05-15 19:06:45.425589 |  405290 |     5848 | {"MovedTo": [13, 5849]}
 10881836 | 2024-05-15 19:06:45.438813 |  405289 |     5849 | {"MovedFrom": [11, 5848, "gerdog", null]}
 10881837 | 2024-05-15 19:06:45.443653 |  405290 |     5848 | {"MovedTo": [11, 5849]}
(24 rows)

mb2=> select id, created_at at time zone 'america/denver'  from tables where event_id = 5273 order by id;
  id  |          timezone          
------+----------------------------
 5847 | 2024-05-15 18:05:00.625453
 5848 | 2024-05-15 18:16:18.67116
 5849 | 2024-05-15 18:48:54.939093
(3 rows)

BTW, I hate having bugs, but I'm glad this one reared its head during a Championship event, because those don't allow re-entries, so that's one fewer relatively recently added feature to worry about.

Anyway… I was moved from 5847 to 5848 well after 5848 was created, so that would have been just to balance tables after ts4z bust. Then, before the bug bit me, I was moved from 5848 to 5849 when 5849 was created, presumably to accommodate smalltalkdan.

Perhaps the code that moves a player for table balancing doesn't update a table_id somewhere and then, once it's not updated, the code that splits a table for late registration isn't able to update it either. If so, I would expect to be able to reproduce the bug by forcing a table balance and then just closing the window of the player who was moved due to the balance.

I'm going to try that before I look at who is sending Identities, because if I can reproduce it, I can pepper my code with dbg!() invocations and have the source of the problem handed to me.

[ctm]

Unfortunately, I wasn't able to reproduce it, even though I could get a player to move by starting with 3-handed tables and 6 players and quitting two of them (although I could have started with 5 players and quitting one from the table with 2 players; I didn't think of that at the time). The moved player, however, was still able to close the window and have the level information reappear.

However, in both that test instance and another one where I started with 5-handed tables, the one-player-left table was never combined into the two player table to make a final table. I suspect it's either due to me quitting or due to us getting to a single player, because we have not seen this problem in our evening tournaments (although we've seen a similar problem in the past that has been fixed).

So, I'm going to work on the recombining bug I just found and put this one on hold. When I return to this issue, I plan to check to see whether Identities was being sent to the right table for the moved player in my local tests, because I think that's the easiest lead to follow.

[ctm]

Found it. I am not really sure how to reproduce it, but the problem is Table::dup contains let to_nick_mapper = self.to_nick_mapper.clone(); and ToNickMapper has a messages field that is also cloned and for some reason we get the TableId by looking inside messages rather than simply from the Table that includes the to_nick_mapper field.

I believe this problem goes away if we remote the table_id method from Messages. I think we also then want to clear out the Messages in Table::dup.

FWIW, I can see this having caused weird problems here and there since the code was written.

[ctm]

I have a fix that mostly works. Unfortunately, if a new player joins during the initial break and that forces a table split, the new player isn't told that he or she is on break. I will fix that before deploying, but it means the fix won't go out for this evening's tournament.

[ctm]

Turns out, the issue with a new player joining is present in master, so I could have deployed after all. So, I've merged it into master and will deploy after this evening's tournament is done.