c02b0054c2
Two issues in the GAME_OVER broadcast path: 1. log_game_end called update_game_completed with winner_id=None default, so games_v2.winner_id was NULL on all 17 completed staging rows. The denormalized column existed but carried no information. Compute winner (lowest total; None on tie) in broadcast_game_state and thread through. 2. _process_stats_safe had no idempotency guard. log_game_end was already self-guarding via game_log_id=None after first fire, but nothing stopped repeated GAME_OVER broadcasts from re-firing stats and double-counting games_played/games_won. Add Room.stats_processed latch; reset it in handle_start_game so a re-used room still records. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
329 lines
10 KiB
Python
329 lines
10 KiB
Python
# SPDX-License-Identifier: GPL-3.0-or-later
|
|
"""
|
|
PostgreSQL-backed game logging for AI decision analysis.
|
|
|
|
Replaces SQLite game_log.py with unified event store integration.
|
|
Provides sync-compatible interface for existing callers (main.py, ai.py).
|
|
|
|
Usage:
|
|
# Initialize in main.py lifespan
|
|
from services.game_logger import GameLogger, set_logger
|
|
game_logger = GameLogger(event_store)
|
|
set_logger(game_logger)
|
|
|
|
# Use in handlers
|
|
from services.game_logger import get_logger
|
|
logger = get_logger()
|
|
if logger:
|
|
logger.log_move(game_id, player, is_cpu=False, action="swap", ...)
|
|
"""
|
|
|
|
from dataclasses import asdict
|
|
from typing import Optional, TYPE_CHECKING
|
|
import asyncio
|
|
import uuid
|
|
import logging
|
|
|
|
if TYPE_CHECKING:
|
|
from stores.event_store import EventStore
|
|
from game import Card, Player, Game, GameOptions
|
|
|
|
log = logging.getLogger(__name__)
|
|
|
|
|
|
class GameLogger:
|
|
"""
|
|
Logs game events and moves to PostgreSQL.
|
|
|
|
Provides sync wrappers for compatibility with existing callers.
|
|
Uses fire-and-forget async tasks to avoid blocking game logic.
|
|
"""
|
|
|
|
def __init__(self, event_store: "EventStore"):
|
|
"""
|
|
Initialize the game logger.
|
|
|
|
Args:
|
|
event_store: PostgreSQL event store instance.
|
|
"""
|
|
self.event_store = event_store
|
|
|
|
@staticmethod
|
|
def _options_to_dict(options: "GameOptions") -> dict:
|
|
"""Convert GameOptions to dict for storage, excluding non-rule fields."""
|
|
d = asdict(options)
|
|
d.pop("deck_colors", None)
|
|
return d
|
|
|
|
# -------------------------------------------------------------------------
|
|
# Game Lifecycle
|
|
# -------------------------------------------------------------------------
|
|
|
|
async def log_game_start_async(
|
|
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. 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.
|
|
|
|
If create_game fails the update is skipped — the row doesn't exist.
|
|
"""
|
|
if game_id is None:
|
|
game_id = str(uuid.uuid4())
|
|
|
|
try:
|
|
await self.event_store.create_game(
|
|
game_id=game_id,
|
|
room_code=room_code,
|
|
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 (update): {e}")
|
|
|
|
return game_id
|
|
|
|
def log_game_start(
|
|
self,
|
|
room_code: str,
|
|
num_players: int,
|
|
num_rounds: int,
|
|
player_ids: list[str],
|
|
options: "GameOptions",
|
|
) -> str:
|
|
"""
|
|
Sync wrapper for log_game_start_async.
|
|
|
|
In async context: fires task and returns generated ID immediately.
|
|
In sync context: runs synchronously.
|
|
"""
|
|
game_id = str(uuid.uuid4())
|
|
|
|
try:
|
|
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:
|
|
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,
|
|
)
|
|
)
|
|
|
|
async def log_game_end_async(
|
|
self,
|
|
game_id: str,
|
|
winner_id: Optional[str] = None,
|
|
) -> None:
|
|
"""
|
|
Mark game as ended. winner_id is the player who finished with the
|
|
lowest total — None when tied or when the caller doesn't have it.
|
|
"""
|
|
try:
|
|
await self.event_store.update_game_completed(game_id, winner_id)
|
|
log.debug(f"Logged game end: {game_id} winner={winner_id}")
|
|
except Exception as e:
|
|
log.error(f"Failed to log game end: {e}")
|
|
|
|
def log_game_end(self, game_id: str, winner_id: Optional[str] = None) -> None:
|
|
"""
|
|
Sync wrapper for log_game_end_async.
|
|
|
|
Fires async task in async context, skips in sync context.
|
|
"""
|
|
if not game_id:
|
|
return
|
|
|
|
try:
|
|
asyncio.get_running_loop()
|
|
asyncio.create_task(self.log_game_end_async(game_id, winner_id))
|
|
except RuntimeError:
|
|
# Not in async context - skip (simulations don't need this)
|
|
pass
|
|
|
|
async def log_game_abandoned_async(self, game_id: str) -> None:
|
|
"""Mark game as abandoned (room emptied before GAME_OVER)."""
|
|
try:
|
|
await self.event_store.update_game_abandoned(game_id)
|
|
log.debug(f"Logged game abandoned: {game_id}")
|
|
except Exception as e:
|
|
log.error(f"Failed to log game abandoned: {e}")
|
|
|
|
def log_game_abandoned(self, game_id: str) -> None:
|
|
"""Sync wrapper: fires async task in async context, no-op otherwise."""
|
|
if not game_id:
|
|
return
|
|
try:
|
|
asyncio.get_running_loop()
|
|
asyncio.create_task(self.log_game_abandoned_async(game_id))
|
|
except RuntimeError:
|
|
pass
|
|
|
|
# -------------------------------------------------------------------------
|
|
# Move Logging
|
|
# -------------------------------------------------------------------------
|
|
|
|
async def log_move_async(
|
|
self,
|
|
game_id: str,
|
|
player: "Player",
|
|
is_cpu: bool,
|
|
action: str,
|
|
card: Optional["Card"] = None,
|
|
position: Optional[int] = None,
|
|
game: Optional["Game"] = None,
|
|
decision_reason: Optional[str] = None,
|
|
) -> None:
|
|
"""
|
|
Log a move with AI context to PostgreSQL.
|
|
|
|
Args:
|
|
game_id: Game UUID.
|
|
player: Player who made the move.
|
|
is_cpu: Whether this is a CPU player.
|
|
action: Action type (draw_deck, take_discard, swap, discard, flip, etc.).
|
|
card: Card involved in the action.
|
|
position: Hand position (0-5) for swaps/flips.
|
|
game: Game instance for context capture.
|
|
decision_reason: AI reasoning for the decision.
|
|
"""
|
|
# Build AI context from game state
|
|
hand_state = None
|
|
discard_top = None
|
|
visible_opponents = None
|
|
|
|
if game:
|
|
# Serialize player's hand
|
|
hand_state = [
|
|
{"rank": c.rank.value, "suit": c.suit.value, "face_up": c.face_up}
|
|
for c in player.cards
|
|
]
|
|
|
|
# Serialize discard top
|
|
dt = game.discard_top()
|
|
if dt:
|
|
discard_top = {"rank": dt.rank.value, "suit": dt.suit.value}
|
|
|
|
# Serialize visible opponent cards
|
|
visible_opponents = {}
|
|
for p in game.players:
|
|
if p.id != player.id:
|
|
visible = [
|
|
{"rank": c.rank.value, "suit": c.suit.value}
|
|
for c in p.cards if c.face_up
|
|
]
|
|
visible_opponents[p.name] = visible
|
|
|
|
try:
|
|
await self.event_store.append_move(
|
|
game_id=game_id,
|
|
player_id=player.id,
|
|
player_name=player.name,
|
|
is_cpu=is_cpu,
|
|
action=action,
|
|
card_rank=card.rank.value if card else None,
|
|
card_suit=card.suit.value if card else None,
|
|
position=position,
|
|
hand_state=hand_state,
|
|
discard_top=discard_top,
|
|
visible_opponents=visible_opponents,
|
|
decision_reason=decision_reason,
|
|
)
|
|
except Exception as e:
|
|
log.error(f"Failed to log move: {e}")
|
|
|
|
def log_move(
|
|
self,
|
|
game_id: str,
|
|
player: "Player",
|
|
is_cpu: bool,
|
|
action: str,
|
|
card: Optional["Card"] = None,
|
|
position: Optional[int] = None,
|
|
game: Optional["Game"] = None,
|
|
decision_reason: Optional[str] = None,
|
|
) -> None:
|
|
"""
|
|
Sync wrapper for log_move_async.
|
|
|
|
Fires async task in async context. Does nothing if no game_id or not in async context.
|
|
"""
|
|
if not game_id:
|
|
return
|
|
|
|
try:
|
|
loop = asyncio.get_running_loop()
|
|
asyncio.create_task(
|
|
self.log_move_async(
|
|
game_id, player, is_cpu, action,
|
|
card=card, position=position, game=game, decision_reason=decision_reason
|
|
)
|
|
)
|
|
except RuntimeError:
|
|
# Not in async context - skip logging (simulations)
|
|
pass
|
|
|
|
|
|
# -------------------------------------------------------------------------
|
|
# Global Instance Management
|
|
# -------------------------------------------------------------------------
|
|
|
|
_game_logger: Optional[GameLogger] = None
|
|
|
|
|
|
def get_logger() -> Optional[GameLogger]:
|
|
"""
|
|
Get the global game logger instance.
|
|
|
|
Returns:
|
|
GameLogger if initialized, None otherwise.
|
|
"""
|
|
return _game_logger
|
|
|
|
|
|
def set_logger(logger: GameLogger) -> None:
|
|
"""
|
|
Set the global game logger instance.
|
|
|
|
Called during application startup in main.py lifespan.
|
|
|
|
Args:
|
|
logger: GameLogger instance to use globally.
|
|
"""
|
|
global _game_logger
|
|
_game_logger = logger
|
|
log.info("Game logger initialized with PostgreSQL backend")
|