diff --git a/server/handlers.py b/server/handlers.py index bfe9a0d..95c40a2 100644 --- a/server/handlers.py +++ b/server/handlers.py @@ -215,6 +215,8 @@ async def handle_start_game(data: dict, ctx: ConnectionContext, *, broadcast_gam ctx.current_room.game_log_id = game_logger.log_game_start( room_code=ctx.current_room.code, num_players=len(ctx.current_room.players), + num_rounds=num_rounds, + player_ids=[p.id for p in ctx.current_room.game.players], options=options, ) diff --git a/server/services/game_logger.py b/server/services/game_logger.py index 00e284f..b3f8787 100644 --- a/server/services/game_logger.py +++ b/server/services/game_logger.py @@ -63,22 +63,20 @@ class GameLogger: self, room_code: str, num_players: int, + num_rounds: int, + player_ids: list[str], options: "GameOptions", + game_id: Optional[str] = None, ) -> str: """ - Log game start, return game_id. + Log game start. Writes the row via create_game and then populates + started_at/num_players/num_rounds/player_ids via update_game_started + so downstream queries don't see a half-initialized games_v2 row. - Creates a game record in games_v2 table. - - Args: - room_code: Room code for the game. - num_players: Number of players. - options: Game options/house rules. - - Returns: - Generated game UUID. + If create_game fails the update is skipped — the row doesn't exist. """ - game_id = str(uuid.uuid4()) + if game_id is None: + game_id = str(uuid.uuid4()) try: await self.event_store.create_game( @@ -87,9 +85,20 @@ class GameLogger: host_id="system", options=self._options_to_dict(options), ) + except Exception as e: + log.error(f"Failed to log game start (create): {e}") + return game_id + + try: + await self.event_store.update_game_started( + game_id, + num_players, + num_rounds, + player_ids, + ) log.debug(f"Logged game start: {game_id} room={room_code}") except Exception as e: - log.error(f"Failed to log game start: {e}") + log.error(f"Failed to log game start (update): {e}") return game_id @@ -97,6 +106,8 @@ class GameLogger: self, room_code: str, num_players: int, + num_rounds: int, + player_ids: list[str], options: "GameOptions", ) -> str: """ @@ -108,32 +119,29 @@ class GameLogger: game_id = str(uuid.uuid4()) try: - loop = asyncio.get_running_loop() - # Already in async context - fire task, return ID immediately - asyncio.create_task(self._log_game_start_with_id(game_id, room_code, num_players, options)) + asyncio.get_running_loop() + asyncio.create_task( + self.log_game_start_async( + room_code=room_code, + num_players=num_players, + num_rounds=num_rounds, + player_ids=player_ids, + options=options, + game_id=game_id, + ) + ) return game_id except RuntimeError: - # Not in async context - run synchronously - return asyncio.run(self.log_game_start_async(room_code, num_players, options)) - - async def _log_game_start_with_id( - self, - game_id: str, - room_code: str, - num_players: int, - options: "GameOptions", - ) -> None: - """Helper to log game start with pre-generated ID.""" - try: - await self.event_store.create_game( - game_id=game_id, - room_code=room_code, - host_id="system", - options=self._options_to_dict(options), + return asyncio.run( + self.log_game_start_async( + room_code=room_code, + num_players=num_players, + num_rounds=num_rounds, + player_ids=player_ids, + options=options, + game_id=game_id, + ) ) - log.debug(f"Logged game start: {game_id} room={room_code}") - except Exception as e: - log.error(f"Failed to log game start: {e}") async def log_game_end_async(self, game_id: str) -> None: """ diff --git a/server/test_game_lifecycle_logging.py b/server/test_game_lifecycle_logging.py index d39db63..53caa2d 100644 --- a/server/test_game_lifecycle_logging.py +++ b/server/test_game_lifecycle_logging.py @@ -21,7 +21,7 @@ from unittest.mock import AsyncMock, MagicMock, patch from game import GameOptions from room import Room, RoomManager from services.game_logger import GameLogger -from handlers import ConnectionContext, handle_end_game +from handlers import ConnectionContext, handle_end_game, handle_start_game from test_handlers import MockWebSocket, make_ctx @@ -151,6 +151,102 @@ class TestHandleEndGameMarksAbandoned: ctx = make_ctx(websocket=joiner_ws, player_id="joiner", room=room) + with patch("handlers.get_logger", return_value=mock_logger): + await handle_end_game( + {}, + ctx, + room_manager=rm, + cleanup_room_profiles=lambda _code: None, + ) + + mock_logger.log_game_abandoned.assert_not_called() + assert room.code in rm.rooms + + +class TestLogGameStartPopulatesMetadata: + """ + create_game only writes id/room_code/host_id/options. update_game_started + (which fills in started_at, num_players, num_rounds, player_ids) existed + but had zero callers — 100% of staging's 289 games had those fields NULL. + log_game_start must call both so the row is complete after start_game. + """ + + @pytest.mark.asyncio + async def test_start_calls_create_and_update(self): + event_store = MagicMock() + event_store.create_game = AsyncMock() + event_store.update_game_started = AsyncMock() + logger = GameLogger(event_store) + options = GameOptions(initial_flips=0) + + await logger.log_game_start_async( + room_code="ABCD", + num_players=3, + num_rounds=9, + player_ids=["p1", "p2", "p3"], + options=options, + ) + + event_store.create_game.assert_awaited_once() + event_store.update_game_started.assert_awaited_once() + call = event_store.update_game_started.await_args + assert call.kwargs.get("num_players", call.args[1] if len(call.args) > 1 else None) == 3 + assert call.kwargs.get("num_rounds", call.args[2] if len(call.args) > 2 else None) == 9 + assert call.kwargs.get("player_ids", call.args[3] if len(call.args) > 3 else None) == ["p1", "p2", "p3"] + + @pytest.mark.asyncio + async def test_update_uses_same_game_id_as_create(self): + event_store = MagicMock() + event_store.create_game = AsyncMock() + event_store.update_game_started = AsyncMock() + logger = GameLogger(event_store) + + await logger.log_game_start_async( + room_code="XYZW", + num_players=2, + num_rounds=1, + player_ids=["a", "b"], + options=GameOptions(initial_flips=0), + ) + + create_args = event_store.create_game.await_args + update_args = event_store.update_game_started.await_args + created_id = create_args.kwargs.get("game_id", create_args.args[0] if create_args.args else None) + updated_id = update_args.args[0] if update_args.args else update_args.kwargs.get("game_id") + assert created_id == updated_id + assert created_id # non-empty + + @pytest.mark.asyncio + async def test_create_failure_skips_update(self): + """If the row never landed, don't try to update a non-existent id.""" + event_store = MagicMock() + event_store.create_game = AsyncMock(side_effect=Exception("db down")) + event_store.update_game_started = AsyncMock() + logger = GameLogger(event_store) + + await logger.log_game_start_async( + room_code="ABCD", + num_players=2, + num_rounds=1, + player_ids=["a", "b"], + options=GameOptions(initial_flips=0), + ) + + event_store.update_game_started.assert_not_awaited() + """Only the host ends games — non-host requests are rejected unchanged.""" + rm = RoomManager() + room = rm.create_room() + room.add_player("host", "Host", MockWebSocket()) + room.get_player("host").is_host = True + joiner_ws = MockWebSocket() + room.add_player("joiner", "Joiner", joiner_ws) + room.game_log_id = "game-uuid-untouchable" + + mock_logger = MagicMock() + mock_logger.log_game_abandoned = MagicMock() + + ctx = make_ctx(websocket=joiner_ws, player_id="joiner", room=room) + with patch("handlers.get_logger", return_value=mock_logger): await handle_end_game( {},