feat(observability): Prometheus /metrics and ws.session wide event (Phase 13)

PROGRESS.md

@@ -41,8 +41,8 @@ branch; only the phase branch opens a PR into `master`.
 | 9.7 | Docker, CI/CD, and server-start optimization | done 2026-09-14 (PR #18) |
 | 10 | Frontend: play, spectate, admin, focus view | done 2026-09-14 (PR #20) |
 | 11 | Chat and personas | done 2026-09-14 (PR #21) |
-| 12 | Leaderboard | done 2026-09-14 (branch phase-12-leaderboard, PR pending) |
-| 13 | Observability | |
+| 12 | Leaderboard | done 2026-09-14 (PR #22) |
+| 13 | Observability | done 2026-09-14 (branch phase-13-observability, PR pending) |
 | 14 | CI/CD (local dry-run; no server yet) | |
 | 15 | Production deployment (deferred until local complete) | |
 | 16 | Scale and polish | |
@@ -1101,6 +1101,131 @@ the two list routes (python-reviewer, MEDIUM) -- already documented as a
 found-but-deferred gap in `docs/leaderboard.md`'s "Left for later" section
 before either review even ran.
 
+## Phase 13 — done 2026-09-14 (branch phase-13-observability)
+
+Self-planned (no formal spec; a direct continuation of context already in
+hand). DECISIONS.md §14: "Prometheus `/metrics`... everything inspectable
+locally." Scoped by first reading what already existed rather than
+assuming: wide events (Phase 1), `/health`/`/health/llm` (Phase 1/6) were
+already fully built. Only two real gaps: no `/metrics` at all, and
+`docs/admin-and-observability.md`'s own `ws.session` wide event -- listed
+in that doc's table since Phase 1 -- had never actually been wired into
+the websocket route.
+
+- **`app/metrics.py`** (new): a dedicated `CollectorRegistry` (not
+  `prometheus_client`'s process-global default, so `/metrics` is explicit
+  about exactly what it exposes and test collection can't hit the
+  classic "duplicated metric name" footgun). `botpit_active_games`/
+  `botpit_active_ws_connections` (gauges), `botpit_agent_turn_latency_seconds`/
+  `_errors_total` (per model), `botpit_agent_turn_timeouts_total` (agent
+  seats only, not `scripted`), `botpit_moves_total`, `botpit_model_swaps_total`
+  (per `base_url`). "Moves per minute" (DECISIONS §14's own wording) is a
+  plain counter, not a stored per-minute number -- graphing `rate()` over
+  it is Prometheus's own idiom for exactly this.
+- **`GET /metrics`** (new route, unauthenticated like `/health`): Prometheus
+  text exposition of that registry.
+- **Instrumentation, hooked at the existing single centralizing spot in
+  each case rather than adding new ones**: `AgentController._metrics`
+  (already fed the wide event's `llm.calls`) now also records the
+  latency histogram and error counter; `Referee._commit` (already the one
+  place a move lands) increments `MOVES_TOTAL`; `Referee._take_turn`'s
+  existing `TimeoutError` branch increments the timeout counter for real
+  agent seats; `RoomService.start`/`_finish_room` (already the exactly-
+  once start/finish pair the archiving logic relies on) increment/decrement
+  `ACTIVE_GAMES` symmetrically.
+- **`app.metrics.note_llm_call(base_url, model)`**: called right before
+  every real outbound LLM completion request
+  (`AgentController.decide`). Counts a swap when the immediately
+  preceding call to the same `base_url` used a different model --
+  DECISIONS §13's "surface swap counts in metrics," not the model-swap-
+  *aware scheduler* that decision also describes (grouping concurrent AI
+  turns by model to minimise swaps). That scheduler does not exist and is
+  explicitly out of scope here: this phase is Observability, not
+  scheduling, and this counter is exactly what would tell a future phase
+  whether building it is worth it. Needed `base_url: str` added to the
+  `LLMClient` Protocol (both real adapters already had it; `FakeLLMClient`
+  needed a `base_url` attribute added too, or every existing agent test
+  using it would have started raising `AttributeError`).
+- **`ws.session` wide event + `ACTIVE_WS_CONNECTIONS`**
+  (`app/api/routes/rooms.py`'s `room_ws`): wraps the accepted-connection
+  lifecycle (not the earlier auth/admission refusals -- a "session" is an
+  established connection). `events_sent` via `ev.incr` per message sent;
+  `close_reason="client_disconnect"` on a clean `WebSocketDisconnect`; any
+  other exception's type/message land in the wide event's own `error.*`
+  fields automatically, same as every other wide event. The gauge is
+  incremented right after `accept()` and decremented in a `finally`, so it
+  comes back down regardless of how the connection ends.
+- **Found and fixed in passing, not this phase's actual subject**:
+  `docs/admin-and-observability.md`'s wide-event table named `agent.turn`
+  as the event kind; the real `event_kind` (and every seat kind, not just
+  agents) has always been `game.turn` -- corrected.
+- **A real onboarding bug, found while adding this phase's one new
+  dependency (`prometheus-client`)**: ran a bare `uv sync` from `backend/`
+  to add it, which silently *removed* `prek`/`zizmor`/`smokeshow` from the
+  shared venv -- they're workspace-root `dev`/`github-actions` dependency
+  groups (root `pyproject.toml`), not part of `backend/pyproject.toml`'s
+  own `dependencies`, and this repo has exactly one `.venv` shared by the
+  whole uv workspace regardless of which member directory `uv sync` runs
+  from. `docs/development/setup.md` documented the exact bare `uv sync`
+  command that causes this -- meaning a fresh clone following that guide
+  verbatim would never get a working `prek run --all-files` gate at all.
+  Fixed the doc to use `uv sync --all-groups` and explained why, restored
+  the local venv the same way, and re-verified `uv run prek --version`/
+  `uv run zizmor --version` both work again before continuing.
+
+New tests: `backend/tests/observability/test_metrics.py` (5: the route
+returns valid Prometheus text, `note_llm_call`'s swap-counting logic in
+isolation, agent-turn latency/error metrics via a real `decide()` call, a
+real `Referee.run()` agent-seat timeout incrementing the counter, the
+registry never exposes anything but `botpit_*` names).
+`tests/rooms/test_room_service.py` (+2: `ACTIVE_GAMES` tracks a real
+start/finish cycle, `MOVES_TOTAL` increments on a real submitted move --
+both poll rather than assume `_finish_room`'s async completion callback
+already ran, matching this file's own established pattern for that race).
+`tests/rooms/test_rooms_ws.py` (+1: `ACTIVE_WS_CONNECTIONS` and the
+`ws.session` wide event's fields, over a real websocket connection) (787
+backend tests total; 59 Playwright tests, unchanged -- this phase touched
+no frontend code).
+
+Full gate: backend suite (787 tests) green, `ty`/`mypy`/`ruff` clean,
+verified the new `/metrics` route against the real built Docker image
+(not just `TestClient`), full Playwright suite (59 tests, unchanged)
+green against the real docker compose stack, `prek run --all-files` clean.
+
+### Review fixes (PR #23)
+
+`python-reviewer` reviewed the PR (no frontend changes this phase, so no
+`react-reviewer` pass). Verdict: approve, no CRITICAL/HIGH findings. Real,
+fixed anyway:
+
+- **Default histogram buckets didn't cover realistic LLM latency**
+  (MEDIUM): `prometheus_client`'s default buckets top out at 10s, but
+  `LLM_TIMEOUT_SECONDS` defaults to 120s -- exactly the range this metric
+  exists to characterize (a slow or VRAM-swapped call) would collapse
+  into one `+Inf` bucket, undercutting the whole point of the histogram.
+  Set explicit buckets (`0.5` through `120`, plus `+Inf`).
+- **A hard LLM failure recorded `latency_ms=0`** (LOW): `with_retries` may
+  have already spent real wall-clock time retrying before giving up, and
+  a persistent failure is exactly the call this histogram would most want
+  timed accurately. Now measures real elapsed time around the call
+  instead of hardcoding 0.
+
+**Verified, not fixed (already correct or already mitigated)**:
+`note_llm_call`'s synchronous check-then-write has no real race (no
+`await` between the read and write, same reasoning `ModelRegistry.client_for`
+already relies on -- confirmed by re-reading both); `_finish_room`'s
+unconditional `ACTIVE_GAMES.dec()` is correct in every real path (one
+narrow, pre-existing-condition edge case noted -- a DB commit failing
+immediately after a successful `runner.start()` -- already leaves
+`room.status` inconsistent before this PR, out of this phase's scope);
+`FakeLLMClient.base_url` being a shared constant combined with
+`note_llm_call`'s module-level dict never resetting between tests is a
+real test-isolation gap in the abstract, but every test already avoids it
+correctly (unique `base_url` per test, or before/after baseline diffing) --
+added a one-line comment on `FakeLLMClient.base_url` stating this
+explicitly, so a future test doesn't accidentally assert an absolute
+value there.
+
 ## Phase 9.7 — done 2026-09-14 (branch phase-9.7-infra-optimization)
 
 Infrastructure-only pass: Docker image build, Compose, CI/CD workflows,

backend/app/agents/controller.py

@@ -4,6 +4,7 @@
 
 import functools
 import json
+import time
 from collections.abc import Sequence
 from typing import Any, ClassVar
 
@@ -21,6 +22,11 @@
 )
 from app.games.base import AnyGame, PlayerView, Seat
 from app.llm.client import CompletionRequest, LLMClient, LLMError, Message, with_retries
+from app.metrics import (
+    AGENT_TURN_ERRORS_TOTAL,
+    AGENT_TURN_LATENCY_SECONDS,
+    note_llm_call,
+)
 from app.referee.seats import ControllerError, SeatKind, TurnContext
 from app.telemetry import current_event, get_logger
 
@@ -91,12 +97,20 @@ async def decide(self, view: PlayerView, ctx: TurnContext) -> dict[str, Any]:
                 keep_alive=self.keep_alive,
                 think=self.think,
             )
+            call_start = time.perf_counter()
             try:
+                note_llm_call(self.client.base_url, self.model)
                 result = await with_retries(
                     functools.partial(self.client.complete, req)
                 )
             except LLMError as exc:
-                self._metrics(latency_ms=0, ok=False, error=type(exc).__name__)
+                # Real elapsed wall-clock time, not 0 -- `with_retries` may
+                # have already spent real time retrying before giving up,
+                # and this is exactly the call this histogram most wants to
+                # characterize accurately (a persistent failure, possibly
+                # after a VRAM-swap-induced slow start).
+                elapsed_ms = (time.perf_counter() - call_start) * 1000
+                self._metrics(latency_ms=elapsed_ms, ok=False, error=type(exc).__name__)
                 raise ControllerError(f"{self.model}: {exc}") from exc
             reasoning, move = _parse_answer(result.text)
             if result.reasoning:
@@ -196,6 +210,12 @@ def _metrics(self, **fields: Any) -> None:
         ev = current_event()
         if ev is not None:
             ev.add("llm.calls", {"model": self.model, **fields})
+        AGENT_TURN_LATENCY_SECONDS.labels(model=self.model).observe(
+            fields.get("latency_ms", 0) / 1000
+        )
+        error = fields.get("error")
+        if error is not None:
+            AGENT_TURN_ERRORS_TOTAL.labels(model=self.model, error=error).inc()
 
     async def _publish(self, payload: Any, visibility: Any) -> None:
         correlation = {"game_id": self.game_id} if self.game_id else {}

backend/app/api/main.py

@@ -7,6 +7,7 @@
     items,
     leaderboard,
     login,
+    metrics,
     private,
     roles,
     rooms,
@@ -27,6 +28,7 @@
 api_router.include_router(rooms.router)
 api_router.include_router(games.router)
 api_router.include_router(leaderboard.router)
+api_router.include_router(metrics.router)
 
 
 if settings.FASTAPI_ENV == "development":

backend/app/api/routes/metrics.py

@@ -0,0 +1,19 @@
+"""``GET /metrics`` (Phase 13, DECISIONS.md §14): Prometheus text
+exposition of ``app.metrics.REGISTRY``. Unauthenticated, matching
+``GET /health`` -- both are operational endpoints meant for a scraper/
+monitor, not user data, and Prometheus scrape configs rarely carry a
+bearer token easily."""
+
+from __future__ import annotations
+
+from fastapi import APIRouter, Response
+from prometheus_client import CONTENT_TYPE_LATEST, generate_latest
+
+from app.metrics import REGISTRY
+
+router = APIRouter(tags=["metrics"])
+
+
+@router.get("/metrics")
+def metrics() -> Response:
+    return Response(generate_latest(REGISTRY), media_type=CONTENT_TYPE_LATEST)

backend/app/api/routes/rooms.py

@@ -40,6 +40,7 @@
 from app.events import Subscriber, filter_for_subscriber
 from app.games import get_game
 from app.games.move_schema import move_json_schema
+from app.metrics import ACTIVE_WS_CONNECTIONS
 from app.models import (
     Message,
     Room,
@@ -63,6 +64,7 @@
     RoomNotWaitingError,
     RoomService,
 )
+from app.telemetry import wide_event
 
 router = APIRouter(prefix="/rooms", tags=["rooms"])
 
@@ -568,10 +570,22 @@ async def room_ws(
         return
 
     await websocket.accept()
+    ACTIVE_WS_CONNECTIONS.inc()
     try:
-        async for event in service.bus.subscribe(str(room_id), since=since):
-            filtered = filter_for_subscriber(event, subscriber)
-            if filtered is not None:
-                await websocket.send_json(filtered.model_dump(mode="json"))
-    except WebSocketDisconnect:
-        pass
+        with wide_event(
+            "ws.session",
+            room_id=str(room_id),
+            user_id=str(user.id),
+            subscriber_kind=subscriber.kind,
+            seat=subscriber.seat,
+        ) as ev:
+            try:
+                async for event in service.bus.subscribe(str(room_id), since=since):
+                    filtered = filter_for_subscriber(event, subscriber)
+                    if filtered is not None:
+                        await websocket.send_json(filtered.model_dump(mode="json"))
+                        ev.incr("events_sent")
+            except WebSocketDisconnect:
+                ev.set(close_reason="client_disconnect")
+    finally:
+        ACTIVE_WS_CONNECTIONS.dec()

backend/app/llm/client.py

@@ -68,6 +68,8 @@ def __init__(self, message: str) -> None:
 
 
 class LLMClient(Protocol):
+    base_url: str
+
     async def complete(self, req: CompletionRequest) -> CompletionResult: ...
 
     async def aclose(self) -> None: ...

backend/app/llm/fake.py

@@ -29,6 +29,15 @@ def __init__(
             self._fn = responses
         self.latency_s = latency_s
         self.requests: list[CompletionRequest] = []
+        # Shared across every FakeLLMClient instance on purpose -- but note
+        # `app.metrics.note_llm_call`'s swap counter keys off `base_url` and
+        # never resets between tests, so `botpit_model_swaps_total{base_url=
+        # "fake://test"}`'s *absolute* value is order-dependent across the
+        # whole test session. Existing tests avoid this correctly (diff
+        # against a captured before/after baseline, or use a base_url unique
+        # to that one test) -- keep doing that, don't assert an absolute
+        # value for this base_url.
+        self.base_url = "fake://test"
 
     async def complete(self, req: CompletionRequest) -> CompletionResult:
         self.requests.append(req)

backend/app/metrics.py

@@ -0,0 +1,77 @@
+"""Prometheus metrics (Phase 13, DECISIONS.md §14): active games, active
+websocket connections, agent turn latency/errors per model, moves,
+model swaps. Complements the wide-event log (``app/telemetry``) rather
+than duplicating it -- wide events are for debugging one request/turn/
+game after the fact; these are for graphing trends over time.
+
+A dedicated ``CollectorRegistry`` rather than ``prometheus_client``'s
+process-global default: keeps ``GET /metrics`` explicit about exactly
+what it exposes, and avoids the classic "duplicated metric name" footgun
+if this module is ever imported twice under different names (it happens
+in test collection more often than you'd expect).
+"""
+
+from __future__ import annotations
+
+from prometheus_client import CollectorRegistry, Counter, Gauge, Histogram
+
+REGISTRY = CollectorRegistry()
+
+ACTIVE_GAMES = Gauge(
+    "botpit_active_games", "Rooms currently in_progress", registry=REGISTRY
+)
+ACTIVE_WS_CONNECTIONS = Gauge(
+    "botpit_active_ws_connections",
+    "Open room websocket connections",
+    registry=REGISTRY,
+)
+AGENT_TURN_LATENCY_SECONDS = Histogram(
+    "botpit_agent_turn_latency_seconds",
+    "Latency of one LLM completion call within an agent's turn",
+    ["model"],
+    # `prometheus_client`'s default buckets top out at 10s -- useless here:
+    # `LLM_TIMEOUT_SECONDS` defaults to 120s, and a slow/VRAM-swapped local
+    # model call landing anywhere past 10s (exactly what this metric exists
+    # to characterize) would otherwise collapse into one +Inf bucket.
+    buckets=(0.5, 1, 2, 5, 10, 20, 30, 60, 90, 120, float("inf")),
+    registry=REGISTRY,
+)
+AGENT_TURN_ERRORS_TOTAL = Counter(
+    "botpit_agent_turn_errors_total",
+    "LLM completion calls that failed or produced an unusable reply",
+    ["model", "error"],
+    registry=REGISTRY,
+)
+AGENT_TURN_TIMEOUTS_TOTAL = Counter(
+    "botpit_agent_turn_timeouts_total",
+    "Turns that hit their deadline and fell back to the referee's own move",
+    ["model"],
+    registry=REGISTRY,
+)
+MOVES_TOTAL = Counter(
+    "botpit_moves_total", "Moves applied across every game", registry=REGISTRY
+)
+MODEL_SWAPS_TOTAL = Counter(
+    "botpit_model_swaps_total",
+    "Consecutive LLM calls to the same backend that changed model -- a "
+    "likely VRAM swap (DECISIONS.md §13); the turn scheduler that would "
+    "actively minimise these remains a separate, not-yet-built feature, "
+    "this just counts them",
+    ["base_url"],
+    registry=REGISTRY,
+)
+
+_last_model_by_base_url: dict[str, str] = {}
+
+
+def note_llm_call(base_url: str, model: str) -> None:
+    """Call once right before every real outbound LLM completion request.
+    Increments ``MODEL_SWAPS_TOTAL`` when the immediately preceding call to
+    this same ``base_url`` used a different model. Synchronous with no
+    ``await`` between the read and the write, so concurrent asyncio tasks
+    cannot race this -- the same reasoning ``ModelRegistry.client_for``
+    already relies on for its own check-then-insert."""
+    last = _last_model_by_base_url.get(base_url)
+    if last is not None and last != model:
+        MODEL_SWAPS_TOTAL.labels(base_url=base_url).inc()
+    _last_model_by_base_url[base_url] = model