From 876b4abd8b7d4d1750497ef5f12f782582090030 Mon Sep 17 00:00:00 2001 From: Walter Oggioni Date: Thu, 17 Sep 2026 08:26:45 +0800 Subject: [PATCH] Serve static assets with Granian and add YAML-configurable logging Granian serves the compiled SPA assets directly in Rust: hashed js/wasm/css under /static (the release build uses --public-url /static/) and the card images under /assets, configured with the GRANIAN_STATIC_PATH_ROUTE/MOUNT/ DIR_TO_FILE env vars in the Dockerfile. The Python catch-all now only serves the SPA shell (index.html) at / and for client-side routes. Every module logs through getLogger(__name__): lifecycle and business events at INFO, per-move and store detail at DEBUG. The built-in default writes DEBUG to the console; LOGGING_CONFIG points at a YAML file in the logging.config.dictConfig schema to take over the configuration. PyYAML becomes a direct dependency. --- server/.env.example | 4 ++ server/Dockerfile | 15 +++++- server/README.md | 36 ++++++++++++++ server/pyproject.toml | 1 + server/requirements.txt | 2 + server/src/tavolo/app.py | 17 ++++++- server/src/tavolo/config.py | 9 +++- server/src/tavolo/game/engine.py | 17 ++++++- server/src/tavolo/logging_config.py | 74 +++++++++++++++++++++++++++++ server/src/tavolo/routes/games.py | 12 ++++- server/src/tavolo/routes/static.py | 67 +++++++------------------- server/src/tavolo/stats.py | 11 +++++ server/src/tavolo/store.py | 7 +++ server/src/tavolo/tortoise_mixin.py | 18 +++++++ server/src/tavolo/ws.py | 32 +++++++++++++ server/tests/test_logging_config.py | 66 +++++++++++++++++++++++++ server/tests/test_routes_me.py | 27 +++-------- 17 files changed, 336 insertions(+), 79 deletions(-) create mode 100644 server/src/tavolo/logging_config.py create mode 100644 server/tests/test_logging_config.py diff --git a/server/.env.example b/server/.env.example index f98fd9d..b45ce23 100644 --- a/server/.env.example +++ b/server/.env.example @@ -28,6 +28,10 @@ HAND_ACK_TIMEOUT_SECONDS=30 # for them (covers disconnects and idle players). TURN_TIMEOUT_SECONDS=30 +# Path to a YAML logging configuration file (logging.config.dictConfig +# schema). Unset logs DEBUG to the console. +#LOGGING_CONFIG=/path/to/logging.yaml + # App server APP_HOST=0.0.0.0 APP_PORT=8080 diff --git a/server/Dockerfile b/server/Dockerfile index be2bd3b..6fdec73 100644 --- a/server/Dockerfile +++ b/server/Dockerfile @@ -33,9 +33,12 @@ COPY web/Cargo.toml web/Cargo.lock web/index.html web/style.css web/Trunk.toml . COPY web/assets ./assets COPY web/src ./src +# --public-url makes trunk emit asset URLs under /static, the prefix Granian +# serves in the runtime image (see GRANIAN_STATIC_PATH_* below). Dev builds +# (trunk serve) keep the default "/" public URL. RUN --mount=type=cache,target=/usr/local/cargo/registry \ --mount=type=cache,target=/web/target \ - trunk build --release + trunk build --release --public-url /static/ # --- Python builder ---------------------------------------------------------- FROM alpine:3.24 AS builder @@ -68,7 +71,12 @@ COPY --from=builder /build/migrations /app/migrations # aerich reads [tool.aerich] from pyproject.toml (its default config file); # the db-migrate compose service runs `aerich upgrade` with working_dir=/app. COPY --from=builder /build/pyproject.toml /app/pyproject.toml -# The compiled single-page application, served by the backend itself. +# The compiled single-page application. Granian serves the assets directly +# in Rust — hashed js/wasm/css under /static/* and the card images under +# /assets/* (see the GRANIAN_STATIC_PATH_* env vars below; click splits +# multi-value env vars on whitespace for routes and ':' for paths). The +# Python app only serves the SPA shell (index.html) at / and for +# client-side routes (STATIC_DIR). COPY --from=web-builder /web/dist /app/web/dist ENV PATH="/opt/venv/bin:$PATH" \ @@ -77,6 +85,9 @@ ENV PATH="/opt/venv/bin:$PATH" \ GRANIAN_HOST=0.0.0.0 \ GRANIAN_PORT=8080 \ GRANIAN_INTERFACE=rsgi \ + GRANIAN_STATIC_PATH_ROUTE="/static /assets" \ + GRANIAN_STATIC_PATH_MOUNT="/app/web/dist:/app/web/dist/assets" \ + GRANIAN_STATIC_PATH_DIR_TO_FILE=index.html \ STATIC_DIR=/app/web/dist USER app diff --git a/server/README.md b/server/README.md index e58cc27..6bb8bd1 100644 --- a/server/README.md +++ b/server/README.md @@ -53,8 +53,44 @@ All configuration comes from environment variables (see `.env.example`): | `GAME_TTL_SECONDS` | `86400` | Sliding TTL of a live game in Redis | | `HAND_ACK_TIMEOUT_SECONDS` | `30` | Seconds the between-hands scoring summary waits for acknowledgements | | `TURN_TIMEOUT_SECONDS` | `30` | Seconds a player has to play before the server plays a random legal card for them | +| `LOGGING_CONFIG` | unset | Path to a YAML logging configuration file (see below). Unset logs DEBUG to the console | | `APP_HOST` / `APP_PORT` | `0.0.0.0` / `8080` | Bind address | +## Logging + +The application logs through the Python stdlib `logging` module, one +`getLogger(__name__)` per module: lifecycle and business events at INFO +(game created/joined, websocket connections, match results, auto-plays), +per-move and store detail at DEBUG. + +By default everything at DEBUG level goes to the console. Set +`LOGGING_CONFIG` to the path of a YAML file to take over the +configuration; the file follows the +[`logging.config.dictConfig`](https://docs.python.org/3/library/logging.config.html#logging-config-dictschema) +schema. Keep `disable_existing_loggers: false` — Granian configures its own +loggers before importing the app, and disabling them would silence the +server. Example for quieter production logs (WARNING for third parties, +INFO for the application): + +```yaml +version: 1 +disable_existing_loggers: false +formatters: + default: + format: "{asctime} [{levelname}] ({processName:s}/{threadName:s}) - {name} - {message}" + style: "{" +handlers: + console: + class: logging.StreamHandler + formatter: default +root: + level: WARNING + handlers: [console] +loggers: + tavolo: + level: INFO +``` + ## Data model ### Redis (live games) diff --git a/server/pyproject.toml b/server/pyproject.toml index b2845ca..d2b8b8a 100644 --- a/server/pyproject.toml +++ b/server/pyproject.toml @@ -22,6 +22,7 @@ dependencies = [ "httpx", "PyJWT[crypto]", "pwo", + "PyYAML", "redis", ] diff --git a/server/requirements.txt b/server/requirements.txt index bf6b4ab..3df862f 100644 --- a/server/requirements.txt +++ b/server/requirements.txt @@ -84,6 +84,8 @@ pyjwt[crypto]==2.14.0 # tavolo (pyproject.toml) pypika-tortoise==0.6.5 # via tortoise-orm +pyyaml==6.0.3 + # via tavolo (pyproject.toml) redis==8.1.0 # via # kaya-session-redis diff --git a/server/src/tavolo/app.py b/server/src/tavolo/app.py index 154e691..3aaae64 100644 --- a/server/src/tavolo/app.py +++ b/server/src/tavolo/app.py @@ -18,6 +18,7 @@ their modules at the bottom; imports must happen after ``app`` is built. from __future__ import annotations from importlib.metadata import version as _pkg_version +from logging import getLogger from kaya.core import KayaApp from kaya.oidc import OIDCConfig, OIDCMixin @@ -27,9 +28,13 @@ from kaya.session.redis import RedisSessionStore from redis.asyncio import Redis from .config import settings +from .logging_config import configure_logging from .store import GameStore, InMemoryGameStore, RedisGameStore from .tortoise_mixin import TortoiseMixin +configure_logging(settings.logging_config) +log = getLogger(__name__) + session_store: SessionStore if settings.redis_url is not None: # Lazy client: no connection is opened until a session is actually @@ -39,9 +44,11 @@ if settings.redis_url is not None: Redis.from_url(settings.redis_url, decode_responses=False), ttl_seconds=settings.game_ttl_seconds, ) + log.info("using Redis stores (sessions + live games, game TTL %ds)", settings.game_ttl_seconds) else: session_store = InMemorySessionStore() game_store = InMemoryGameStore() + log.info("REDIS_URL unset: using in-memory stores (sessions + live games)") session_mixin = SessionMixin(session_store) oidc_mixin = OIDCMixin( @@ -70,11 +77,17 @@ tortoise_mixin = TortoiseMixin( ) app = KayaApp(mixins=[session_mixin, oidc_mixin, tortoise_mixin, openapi_mixin]) +log.debug( + "timeouts: hand_ack=%ds turn=%ds", + settings.hand_ack_timeout_seconds, + settings.turn_timeout_seconds, +) # Register routes by importing modules. Order does not matter; each module # pulls ``app`` from here and decorates its handlers at import time. The -# static SPA catch-all is registered last and only matches paths no other -# route claimed. +# static SPA-shell catch-all is registered last and only matches paths no +# other route claimed (asset files under /static are served by Granian +# itself and never reach the app). from .routes import games, health, me, stats # noqa: E402,F401 from . import ws # noqa: E402,F401 from .routes import static # noqa: E402,F401 diff --git a/server/src/tavolo/config.py b/server/src/tavolo/config.py index 921d616..ff111e1 100644 --- a/server/src/tavolo/config.py +++ b/server/src/tavolo/config.py @@ -37,8 +37,9 @@ class Settings: # How long a live game (and its join-code index) survives in Redis # without activity, in seconds. Defaults to 24h. game_ttl_seconds: int - # Directory holding the compiled frontend (trunk's dist output), - # served for every path that is not under /api or /auth. + # Directory holding the compiled frontend (trunk's dist output). Only + # used to locate index.html for the SPA shell; the assets themselves + # are served by Granian under /static (GRANIAN_STATIC_PATH_* env vars). static_dir: str # Seconds the between-hands scoring summary waits for acknowledgements # before dealing the next hand anyway. @@ -46,6 +47,9 @@ class Settings: # Seconds a player has to play before the server plays a random legal # card for them (covering disconnects and idle players). turn_timeout_seconds: int + # Path to a YAML logging configuration file (logging.config.dictConfig + # schema). Unset uses the built-in default: DEBUG to the console. + logging_config: Optional[str] @staticmethod def from_env() -> "Settings": @@ -67,6 +71,7 @@ class Settings: static_dir=_env("STATIC_DIR", "web/dist"), hand_ack_timeout_seconds=int(_env("HAND_ACK_TIMEOUT_SECONDS", "30")), turn_timeout_seconds=int(_env("TURN_TIMEOUT_SECONDS", "30")), + logging_config=os.environ.get("LOGGING_CONFIG"), ) diff --git a/server/src/tavolo/game/engine.py b/server/src/tavolo/game/engine.py index edfe29d..c06a328 100644 --- a/server/src/tavolo/game/engine.py +++ b/server/src/tavolo/game/engine.py @@ -1,6 +1,7 @@ """Pure rules engine for scopone scientifico. -Every function here is deterministic and I/O-free: it mutates (or reads) +Every function here is deterministic and I/O-free (the only side effect is +debug logging): it mutates (or reads) :class:`~tavolo.game.state.GameState` and raises :class:`~tavolo.game.errors.GameError` subclasses on rule violations. This makes the whole rule set unit-testable without Redis, Postgres or HTTP. @@ -29,6 +30,7 @@ from __future__ import annotations import random from datetime import datetime, timedelta, timezone from itertools import combinations +from logging import getLogger from typing import Dict, List, Optional, Sequence, Tuple from .errors import ( @@ -55,6 +57,8 @@ from .state import ( parse_card, ) +log = getLogger(__name__) + # Number of cards dealt to each player at the start of a hand. HAND_SIZE = 10 PLAYERS = 4 @@ -191,6 +195,7 @@ def _deal_hand(state: GameState) -> None: for seat in range(PLAYERS): player = _player_at(state, (state.dealer + 1 + seat) % PLAYERS) player.hand.append(deck.pop()) + log.debug("game %s: hand %d dealt (dealer seat %d)", state.id, state.hand_number, state.dealer) def _player_at(state: GameState, seat: int) -> PlayerState: @@ -334,11 +339,21 @@ def _end_hand(state: GameState) -> None: state.hand_scores.append(details) a, b = state.scores + log.debug( + "game %s: hand %d scored A+%d B+%d (totals %d-%d)", + state.id, + state.hand_number, + points[0], + points[1], + a, + b, + ) reached = max(a, b) >= state.target_score if reached and a != b: state.phase = PHASE_FINISHED state.winner = 0 if a > b else 1 state.finished_at = datetime.now(timezone.utc).isoformat() + log.debug("game %s: match ended, team %s wins", state.id, "A" if state.winner == 0 else "B") return # Pause for the scoring summary instead of dealing immediately. diff --git a/server/src/tavolo/logging_config.py b/server/src/tavolo/logging_config.py new file mode 100644 index 0000000..daabeaa --- /dev/null +++ b/server/src/tavolo/logging_config.py @@ -0,0 +1,74 @@ +"""Logging setup for the tavolo application. + +Configured once at app import time (see :mod:`tavolo.app`). By default a +single console handler at DEBUG level is installed, formatting records as +``{asctime} [{levelname}] ({processName}/{threadName}) - {name} - {message}``. +Point the ``LOGGING_CONFIG`` environment variable at a YAML file to take +over the configuration entirely; the file follows the +:data:`logging.config.dictConfig` schema, e.g.:: + + version: 1 + disable_existing_loggers: false + formatters: + default: + format: "{asctime} [{levelname}] ({processName:s}/{threadName:s}) - {name} - {message}" + style: "{" + handlers: + console: + class: logging.StreamHandler + formatter: default + root: + level: WARNING + handlers: [console] + loggers: + tavolo: + level: INFO + +``disable_existing_loggers`` should stay ``false``: Granian configures its +own loggers before importing the application, and disabling them would +silence the server and Tortoise. +""" +from __future__ import annotations + +from logging.config import dictConfig +from typing import Optional + +import yaml + +DEFAULT_CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "default": { + "format": "{asctime} [{levelname}] ({processName:s}/{threadName:s}) - {name} - {message}", + "style": "{", + }, + }, + "handlers": { + "console": { + "class": "logging.StreamHandler", + "formatter": "default", + "level": "DEBUG", + }, + }, + "root": { + "level": "DEBUG", + "handlers": ["console"], + }, +} + + +def configure_logging(config_path: Optional[str]) -> None: + """Apply the YAML logging configuration at ``config_path``, or the + built-in default when unset.""" + if config_path is None: + dictConfig(DEFAULT_CONFIG) + return + try: + with open(config_path, "rb") as handle: + config = yaml.safe_load(handle) + except OSError as exc: + raise RuntimeError(f"Cannot read LOGGING_CONFIG file: {config_path}") from exc + if not isinstance(config, dict): + raise RuntimeError(f"LOGGING_CONFIG file is not a YAML mapping: {config_path}") + dictConfig(config) diff --git a/server/src/tavolo/routes/games.py b/server/src/tavolo/routes/games.py index e01ed04..87efc3a 100644 --- a/server/src/tavolo/routes/games.py +++ b/server/src/tavolo/routes/games.py @@ -10,6 +10,7 @@ from __future__ import annotations import secrets import uuid +from logging import getLogger from typing import Any, Dict, Optional from kaya.core import HttpContext @@ -24,6 +25,8 @@ from ..game.errors import GameError from ..game.state import DEFAULT_TARGET_SCORE, PHASE_LOBBY, GameState from ..http import JsonRequestError, read_json, read_json_optional, send_error, send_json +log = getLogger(__name__) + # Join codes avoid characters that are easy to confuse when read aloud. _CODE_ALPHABET = "ABCDEFGHJKLMNPQRSTUVWXYZ23456789" _CODE_LENGTH = 6 @@ -111,6 +114,7 @@ async def create_game(ctx: HttpContext) -> None: await send_error(ctx, 400, str(exc)) return await game_store.save(state) + log.info("game %s created by %s (target score %d)", game_id, user.sub, target_score) await send_json(ctx, 201, _lobby_payload(state)) @@ -154,6 +158,7 @@ async def join_game(ctx: HttpContext) -> None: assert user is not None existing = await game_store.find_by_code(code) if existing is None: + log.debug("join rejected for %s: unknown code %r", user.sub, code) await send_error(ctx, 404, "unknown join code") return @@ -165,14 +170,19 @@ async def join_game(ctx: HttpContext) -> None: try: engine.join_game(state, user.sub, auth.display_name(user)) except GameError as exc: + log.debug("join rejected for %s in game %s: %s", user.sub, state.id, exc) await send_error(ctx, 409, str(exc)) return await game_store.save(state) await game_store.publish(state.id) + seat = next(p.seat for p in state.players if p.sub == user.sub) if state.phase == PHASE_LOBBY: - await send_json(ctx, 200, _lobby_payload(state)) + log.info("%s joined game %s (seat %d, %d/4 players)", user.sub, state.id, seat, len(state.players)) else: + log.info("%s joined game %s (seat %d); match started", user.sub, state.id, seat) await send_json(ctx, 200, engine.state_for_player(state, user.sub)) + return + await send_json(ctx, 200, _lobby_payload(state)) @app.GET("/api/games/${game_id}") diff --git a/server/src/tavolo/routes/static.py b/server/src/tavolo/routes/static.py index 895aee9..60a84e8 100644 --- a/server/src/tavolo/routes/static.py +++ b/server/src/tavolo/routes/static.py @@ -1,10 +1,10 @@ -"""Static hosting for the compiled single-page application. +"""SPA shell hosting for the compiled single-page application. -In production the kaya backend itself serves the WASM frontend built into -``STATIC_DIR`` (the ``web/dist`` output of ``trunk build --release``; see -the Docker image). A glob catch-all (``/*``) handles every path that did -not match an API or auth route: real files are served with their content -type, anything else falls back to ``index.html`` so client-side routes +Static assets (wasm, js, css, card images) are served by Granian itself +under the ``/static`` prefix (``GRANIAN_STATIC_PATH_*`` env vars; see the +Dockerfile) and never reach Python. This module only serves ``index.html`` +from ``STATIC_DIR``: at the site root and — via the glob catch-all — for +every path no API or auth route claimed, so client-side routes (``/game/`` etc.) work on direct loads and refreshes. kaya-openapi deliberately skips glob routes, so this handler never appears @@ -14,66 +14,33 @@ from __future__ import annotations import asyncio from pathlib import Path -from typing import Mapping from kaya.core import HttpContext from ..app import app from ..config import settings -# Explicit content types: wasm-pack/trunk outputs (.wasm, .js) are not -# consistently covered by the system mime database in slim containers. -_CONTENT_TYPES: Mapping[str, str] = { - ".html": "text/html; charset=utf-8", - ".js": "text/javascript; charset=utf-8", - ".mjs": "text/javascript; charset=utf-8", - ".wasm": "application/wasm", - ".css": "text/css; charset=utf-8", - ".svg": "image/svg+xml", - ".png": "image/png", - ".ico": "image/x-icon", - ".json": "application/json", - ".webmanifest": "application/manifest+json", - ".woff2": "font/woff2", -} - -def _static_root() -> Path: - return Path(settings.static_dir).resolve() - - -async def _send_path(ctx: HttpContext, target: Path) -> None: - """Serve a static file, or 404 when it does not exist. - - Uses ``send_bytes`` rather than kaya's ``send_file`` (unimplemented by - the ASGI adapter); frontend artifacts are small enough to buffer. - """ - if not target.is_file(): +async def _send_shell(ctx: HttpContext) -> None: + """Serve the SPA shell, or 404 when the frontend build is missing.""" + index = Path(settings.static_dir) / "index.html" + if not index.is_file(): await ctx.send_empty(404) return - content_type = _CONTENT_TYPES.get(target.suffix.lower(), "application/octet-stream") - body = await asyncio.to_thread(target.read_bytes) - await ctx.send_bytes(200, body, {"content-type": (content_type,)}) + body = await asyncio.to_thread(index.read_bytes) + await ctx.send_bytes(200, body, {"content-type": ("text/html; charset=utf-8",)}) @app.GET("/") async def index(ctx: HttpContext) -> None: """Serve the SPA shell at the site root (the glob below cannot match an empty path).""" - await _send_path(ctx, _static_root() / "index.html") + await _send_shell(ctx) @app.GET("/*", recursive=True) async def spa(ctx: HttpContext, _matched: object = None) -> None: - root = _static_root() - relative = ctx.path.lstrip("/") - target = (root / relative).resolve() if relative else root - # Path-traversal guard: the resolved target must stay inside the dist - # directory. - if root != target and root not in target.parents: - await ctx.send_empty(404) - return - if not target.is_file(): - # SPA fallback: unknown paths render the app shell. - target = root / "index.html" - await _send_path(ctx, target) + """SPA fallback: any path that matched no other route renders the app + shell. Requests under ``/static`` are answered by Granian before the + app is ever called, so they never arrive here.""" + await _send_shell(ctx) diff --git a/server/src/tavolo/stats.py b/server/src/tavolo/stats.py index 1a85ef7..1966a54 100644 --- a/server/src/tavolo/stats.py +++ b/server/src/tavolo/stats.py @@ -8,12 +8,15 @@ from __future__ import annotations import uuid from datetime import datetime, timezone +from logging import getLogger from typing import Optional from tortoise.transactions import in_transaction from .game.state import PHASE_FINISHED, TEAM_NAMES, GameState +log = getLogger(__name__) + def _parse_timestamp(value: Optional[str]) -> datetime: if value: @@ -55,3 +58,11 @@ async def save_match_result(state: GameState) -> None: won=player.team == state.winner, ) state.stats_saved = True + log.info( + "match result persisted: game %s, team %s won %d-%d over %d hands", + state.id, + TEAM_NAMES[state.winner], + state.scores[0], + state.scores[1], + state.hand_number, + ) diff --git a/server/src/tavolo/store.py b/server/src/tavolo/store.py index 74de27c..c7066cc 100644 --- a/server/src/tavolo/store.py +++ b/server/src/tavolo/store.py @@ -25,12 +25,15 @@ import asyncio import contextlib import json from abc import ABC, abstractmethod +from logging import getLogger from typing import AsyncContextManager, AsyncIterator, Dict, Optional, Set from redis.asyncio import Redis from .game.state import GameState +log = getLogger(__name__) + GAME_KEY_PREFIX = "tavolo:game:" CODE_KEY_PREFIX = "tavolo:code:" CHANNEL_PREFIX = "tavolo:game:" @@ -86,9 +89,11 @@ class RedisGameStore(GameStore): raw = await self._redis.get(f"{GAME_KEY_PREFIX}{game_id}") if raw is None: + log.debug("redis load %s: miss", game_id) return None if isinstance(raw, bytes): raw = raw.decode("utf-8") + log.debug("redis load %s: hit", game_id) return GameState.from_json(json.loads(raw)) async def save(self, state: GameState) -> None: @@ -98,6 +103,7 @@ class RedisGameStore(GameStore): pipe.set(f"{GAME_KEY_PREFIX}{state.id}", payload, ex=self._ttl) pipe.set(f"{CODE_KEY_PREFIX}{state.join_code}", state.id, ex=self._ttl) await pipe.execute() + log.debug("redis save %s (phase %s, ttl %ds)", state.id, state.phase, self._ttl) async def find_by_code(self, code: str) -> Optional[GameState]: game_id = await self._redis.get(f"{CODE_KEY_PREFIX}{code.upper()}") @@ -120,6 +126,7 @@ class RedisGameStore(GameStore): async def publish(self, game_id: str) -> None: await self._redis.publish(_channel(game_id), "update") + log.debug("redis publish %s", game_id) async def _redis_events(pubsub) -> AsyncIterator[None]: diff --git a/server/src/tavolo/tortoise_mixin.py b/server/src/tavolo/tortoise_mixin.py index 7e72d14..f292551 100644 --- a/server/src/tavolo/tortoise_mixin.py +++ b/server/src/tavolo/tortoise_mixin.py @@ -35,6 +35,7 @@ from __future__ import annotations from asyncio import AbstractEventLoop, get_running_loop from logging import getLogger from typing import AbstractSet, Optional, Sequence +from urllib.parse import urlsplit, urlunsplit from kaya.core import HttpContext, KayaApp, KayaMixin, WebSocket from tortoise.context import TortoiseContext, _current_context @@ -42,6 +43,19 @@ from tortoise.context import TortoiseContext, _current_context log = getLogger(__name__) +def _safe_url(database_url: str) -> str: + """The database URL with any credentials stripped, for logging.""" + parts = urlsplit(database_url) + host = parts.hostname or "" + try: + if parts.port: + host = f"{host}:{parts.port}" + except ValueError: + # Non-numeric netloc (e.g. sqlite://:memory:): keep the host only. + pass + return urlunsplit((parts.scheme, host, parts.path, "", "")) + + class TortoiseMixin(KayaMixin): """Initialize and tear down a per-loop :class:`TortoiseContext`.""" @@ -64,6 +78,7 @@ class TortoiseMixin(KayaMixin): def shutdown(self, loop: AbstractEventLoop) -> None: if self._init_loop is loop and self._ctx is not None: + log.info("closing database connections") loop.create_task(self._ctx.close_connections()) self._ctx = None self._init_loop = None @@ -75,11 +90,13 @@ class TortoiseMixin(KayaMixin): db_url=self._database_url, modules={"models": self._models_modules}, ) + log.info("database context initialized (%s)", _safe_url(self._database_url)) # Schema creation is only done for sqlite (in-memory test # databases). Postgres schemas are managed by aerich migrations # (applied by the db-migrate compose service / `aerich upgrade`). if self._database_url.startswith("sqlite"): await ctx.generate_schemas() + log.info("sqlite schemas generated") return ctx async def _bind(self) -> None: @@ -88,6 +105,7 @@ class TortoiseMixin(KayaMixin): if self._ctx is not None: # A previous test loop went away; drop its context. self._ctx = None + log.debug("building a Tortoise context for a new event loop") self._ctx = await self._build_context() self._init_loop = loop assert self._ctx is not None diff --git a/server/src/tavolo/ws.py b/server/src/tavolo/ws.py index 69f4e7c..234eaca 100644 --- a/server/src/tavolo/ws.py +++ b/server/src/tavolo/ws.py @@ -42,6 +42,7 @@ import asyncio import json from contextlib import suppress from datetime import datetime, timezone +from logging import getLogger from typing import Any, Awaitable, Callable, Dict, Optional from kaya.core import WebSocket @@ -53,6 +54,8 @@ from .game.errors import GameError from .game.state import PHASE_FINISHED, PHASE_HAND_END, PHASE_PLAYING, GameState from .stats import save_match_result +log = getLogger(__name__) + Send = Callable[[Dict[str, Any]], Awaitable[None]] @@ -68,18 +71,22 @@ def _state_message(state: GameState, sub: str) -> Dict[str, Any]: async def game_socket(ws: WebSocket, game_id: str) -> None: user = auth.get_ws_user(ws) if user is None: + log.debug("websocket %s rejected: no authenticated user", game_id) await ws.close(4401) return state = await game_store.load(game_id) if state is None: + log.debug("websocket rejected: unknown game %s", game_id) await ws.close(4404) return if not state.seated(user.sub): + log.debug("websocket %s rejected: %s is not seated", game_id, user.sub) await ws.close(4403) return await ws.accept() + log.info("%s connected to game %s", user.sub, game_id) send_lock = asyncio.Lock() @@ -106,6 +113,7 @@ async def game_socket(ws: WebSocket, game_id: str) -> None: forward.cancel() with suppress(asyncio.CancelledError): await forward + log.debug("%s disconnected from game %s", user.sub, game_id) async def _forward( @@ -135,9 +143,11 @@ async def _handle_message(send: Send, game_id: str, sub: str, raw: str) -> None: try: data = json.loads(raw) except (ValueError, TypeError): + log.debug("game %s: malformed message from %s (not JSON)", game_id, sub) await send(_error("invalid JSON")) return if not isinstance(data, dict): + log.debug("game %s: malformed message from %s (not an object)", game_id, sub) await send(_error("message must be a JSON object")) return @@ -172,6 +182,7 @@ async def _handle_ack(send: Send, game_id: str, sub: str) -> None: except GameError as exc: await send(_error(str(exc), code="illegal_move")) return + log.debug("game %s: %s acknowledged hand %d", game_id, sub, state.hand_number) await game_store.save(state) await game_store.publish(game_id) @@ -198,6 +209,11 @@ def schedule_hand_end_timer(game_id: str, hand_number: int, timeout: int) -> Non engine.acknowledge_hand(state, player.sub) await game_store.save(state) await game_store.publish(game_id) + log.info( + "game %s: hand %d auto-advanced after the acknowledgement timeout", + game_id, + hand_number, + ) finally: _hand_end_timers.pop(key, None) @@ -252,6 +268,12 @@ def schedule_turn_timer(game_id: str, state: GameState) -> None: engine.auto_play(state) except GameError: return + log.info( + "game %s: auto-played for %s (turn timeout, hand %d)", + game_id, + state.players[turn].sub if turn < len(state.players) else "?", + hand_number, + ) await _after_play(state, game_id) finally: _turn_timers.pop(key, None) @@ -268,6 +290,13 @@ async def _after_play(state: GameState, game_id: str) -> None: """ if state.phase == PHASE_FINISHED: await save_match_result(state) + log.info( + "game %s finished: team %s wins %d-%d", + game_id, + "A" if state.winner == 0 else "B", + state.scores[0], + state.scores[1], + ) elif state.phase == PHASE_HAND_END: schedule_hand_end_timer(game_id, state.hand_number, state.hand_ack_timeout) await game_store.save(state) @@ -297,10 +326,13 @@ async def _handle_play( try: engine.play(state, sub, card, capture) except GameError as exc: + log.debug("game %s: illegal move by %s: %s", game_id, sub, exc) await send(_error(str(exc), code="illegal_move")) return except ValueError: + log.debug("game %s: invalid card code from %s: %r", game_id, sub, card) await send(_error("invalid card code", code="illegal_move")) return + log.debug("game %s: %s played %s (capture: %s)", game_id, sub, card, capture or "-") await _after_play(state, game_id) diff --git a/server/tests/test_logging_config.py b/server/tests/test_logging_config.py new file mode 100644 index 0000000..3e695d9 --- /dev/null +++ b/server/tests/test_logging_config.py @@ -0,0 +1,66 @@ +"""Tests for the logging configuration entry point.""" +from __future__ import annotations + +import logging +import tempfile +import unittest +from pathlib import Path + +from tavolo.logging_config import configure_logging + + +class LoggingConfigTest(unittest.TestCase): + def setUp(self) -> None: + # configure_logging mutates the global logging state; snapshot and + # restore it so the rest of the suite is unaffected. + root = logging.getLogger() + self._root_handlers = root.handlers[:] + self._root_level = root.level + tavolo = logging.getLogger("tavolo") + self._tavolo_level = tavolo.level + + def tearDown(self) -> None: + root = logging.getLogger() + root.handlers = self._root_handlers + root.level = self._root_level + logging.getLogger("tavolo").level = self._tavolo_level + + def test_default_config_when_unset(self) -> None: + configure_logging(None) + root = logging.getLogger() + self.assertEqual(logging.DEBUG, root.level) + self.assertTrue( + any(isinstance(h, logging.StreamHandler) for h in root.handlers), + "default config installs a console stream handler", + ) + + def test_yaml_config_is_applied(self) -> None: + with tempfile.TemporaryDirectory() as tmp: + config = Path(tmp) / "logging.yaml" + config.write_text( + "version: 1\n" + "disable_existing_loggers: false\n" + "root:\n" + " level: WARNING\n" + "loggers:\n" + " tavolo:\n" + " level: DEBUG\n" + ) + configure_logging(str(config)) + self.assertEqual(logging.DEBUG, logging.getLogger("tavolo").getEffectiveLevel()) + self.assertEqual(logging.WARNING, logging.getLogger().getEffectiveLevel()) + + def test_missing_file_raises(self) -> None: + with self.assertRaises(RuntimeError): + configure_logging("/nonexistent/logging.yaml") + + def test_non_mapping_yaml_raises(self) -> None: + with tempfile.TemporaryDirectory() as tmp: + config = Path(tmp) / "logging.yaml" + config.write_text("- just\n- a\n- list\n") + with self.assertRaises(RuntimeError): + configure_logging(str(config)) + + +if __name__ == "__main__": + unittest.main() diff --git a/server/tests/test_routes_me.py b/server/tests/test_routes_me.py index d0e39e3..f590169 100644 --- a/server/tests/test_routes_me.py +++ b/server/tests/test_routes_me.py @@ -34,15 +34,13 @@ class MeRouteTest(unittest.TestCase): class StaticRouteTest(unittest.TestCase): + """The app only serves the SPA shell; asset files under /static are + served by Granian and are not reachable through the ASGI transport.""" + @async_test - async def test_serves_files_and_spa_fallback(self) -> None: + async def test_serves_shell_and_spa_fallback(self) -> None: with tempfile.TemporaryDirectory() as dist: - root = Path(dist) - (root / "index.html").write_text("spa") - (root / "app.js").write_text("console.log(1)") - cards = root / "assets" / "cards" - cards.mkdir(parents=True) - (cards / "07D.svg").write_text("") + (Path(dist) / "index.html").write_text("spa") patched = dataclasses.replace(settings, static_dir=dist) with mock.patch("tavolo.routes.static.settings", patched): @@ -50,27 +48,14 @@ class StaticRouteTest(unittest.TestCase): async with AsyncClient(transport=transport, base_url="http://127.0.0.1") as client: index = await client.get("/") self.assertEqual(200, index.status_code) + self.assertEqual("text/html; charset=utf-8", index.headers["content-type"]) self.assertIn(b"spa", index.content) - js = await client.get("/app.js") - self.assertEqual(200, js.status_code) - self.assertEqual("text/javascript; charset=utf-8", js.headers["content-type"]) - - svg = await client.get("/assets/cards/07D.svg") - self.assertEqual(200, svg.status_code) - self.assertEqual("image/svg+xml", svg.headers["content-type"]) - # Unknown client-side route falls back to the app shell. fallback = await client.get("/game/some-id") self.assertEqual(200, fallback.status_code) self.assertIn(b"spa", fallback.content) - # Traversal attempts never escape the dist directory. - traversal = await client.get("/..%2F..%2Fetc%2Fpasswd") - self.assertIn(traversal.status_code, (200, 404)) - if traversal.status_code == 200: - self.assertIn(b"spa", traversal.content) - @async_test async def test_missing_dist_returns_404(self) -> None: patched = dataclasses.replace(settings, static_dir="/nonexistent-dist")