Backend logging: stderr + configurable rotating file

Add configure_logging() (main.py): always logs to stderr, plus a rotating
file when PIRATS_LOG_FILE is set; level from PIRATS_LOG_LEVEL (default INFO).
Called from both the CLI entrypoint and the app lifespan (idempotent), which
also logs startup/migration/shutdown.

Targeted server-side events for ops/debugging (not every game event): game
created, player joined, player removed (kick/leave), game ended.

NixOS service: new logFile (/var/log/pirats/pirats.log) and logLevel options,
wired to the env vars; LogsDirectory=pirats makes the path writable under the
sandboxed DynamicUser. README documents the env vars/options.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>

README.md

@@ -61,6 +61,15 @@ uvicorn pirats.main:app --host 0.0.0.0 --port 8000 --reload
 
 Once running, access the web UI at [http://localhost:8000](http://localhost:8000).
 
+#### Configuration (environment variables)
+
+| Variable | Default | Purpose |
+| --- | --- | --- |
+| `DATABASE_URL` | `sqlite:///./rats_with_gats.db` | SQLAlchemy database URL. |
+| `PIRATS_LOG_FILE` | _(unset)_ | If set, also write logs to this file (rotating, 10 MB × 5 backups). Logs always go to stderr regardless. |
+| `PIRATS_LOG_LEVEL` | `INFO` | Minimum log severity (`DEBUG`/`INFO`/`WARNING`/`ERROR`/`CRITICAL`). |
+| `PIRATS_DEV_MODE` | _(unset = on)_ | Default Dev Mode for new games. Unset is treated as a local checkout (on); set to `0`/`false` to disable. |
+
 ---
 
 ### Option 2: Using Nix Flakes
@@ -99,10 +108,16 @@ services.pirats = {
   host = "127.0.0.1";
   port = 8000;
   databasePath = "/var/lib/pirats/rats_with_gats.db";
+  logFile = "/var/log/pirats/pirats.log"; # rotating; stderr also goes to the journal
+  logLevel = "info";
   openFirewall = false; # Set to true to open ports in the firewall
 };
 ```
 
+The service writes its log to `logFile` (under the systemd-managed `/var/log/pirats`
+`LogsDirectory`, so the sandboxed `DynamicUser` can write to it) and additionally
+to the systemd journal via stderr (`journalctl -u pirats`).
+
 ---
 
 ## Running Tests

TODO.md

@@ -1,6 +1,6 @@
 ## DevOps/Maintenance
 
-- [ ] **Logging**: Add some logging to the backend. The Nix service should log to /var/log/pirats.log by default (but be configurable). At very least, stderr should go there, plus important server-side events, like:
+- [x] **Logging**: Add some logging to the backend. The Nix service should log to /var/log/pirats.log by default (but be configurable). At very least, stderr should go there, plus important server-side events, like:
 - [ ] **Purge old finished/inactive games**: Add a periodic task (daily is good enough, but make the interval configurable through an env variable/the nix flake) to purge games that have finished more than two weeks ago, or have had no moves played within the last month. These time windows should also be configurable. Log all purges, including crew names/uuids and how much disk space they recovered.
 - [ ] **Defensive coding.** While we trust our players, this app is exposed on the open internet. I'd like to take basic precautions like making sure we're safe against SQL injection (SQLModel should handle this?), doing some basic sanitizing of free inputs from players (valid unicode only + generous character limit should be enough), and making sure that every game action API call is specific and constrained enough that it can't just do arbitrary database updates.
 

flake.nix

@@ -112,6 +112,22 @@
               default = "/var/lib/pirats/rats_with_gats.db";
               description = "Path to the SQLite database file.";
             };
+            logFile = lib.mkOption {
+              type = lib.types.str;
+              default = "/var/log/pirats/pirats.log";
+              description = ''
+                Path to the server log file (rotating, 10 MB x 5 backups). stderr is
+                also captured by the systemd journal. The default lives under the
+                service's LogsDirectory (/var/log/pirats), which the sandboxed
+                DynamicUser can write to; a custom path elsewhere must be made
+                writable by the service separately.
+              '';
+            };
+            logLevel = lib.mkOption {
+              type = lib.types.enum [ "debug" "info" "warning" "error" "critical" ];
+              default = "info";
+              description = "Minimum severity of log messages to record.";
+            };
             openFirewall = lib.mkOption {
               type = lib.types.bool;
               default = false;
@@ -137,6 +153,8 @@
                 # Unset means "local checkout" and defaults Dev Mode on, so the
                 # service must always set it explicitly.
                 PIRATS_DEV_MODE = lib.boolToString cfg.devModeDefault;
+                PIRATS_LOG_FILE = cfg.logFile;
+                PIRATS_LOG_LEVEL = cfg.logLevel;
               };
 
               serviceConfig = {
@@ -146,6 +164,10 @@
                 # Sandboxing and security
                 DynamicUser = true;
                 StateDirectory = "pirats";
+                # Creates /var/log/pirats owned by the dynamic user and adds it to
+                # ReadWritePaths, so the default logFile under it is writable
+                # despite ProtectSystem=strict.
+                LogsDirectory = "pirats";
                 WorkingDirectory = "/var/lib/pirats";
                 
                 ProtectSystem = "strict";

frontend/src/lib/changelog.js

@@ -6,7 +6,7 @@
 //   - Add a CHANGELOG entry only when a commit changes something players can
 //     see. Skip refactors, tests, and tooling. Keep wording player-facing.
 
-export const VERSION = 8;
+export const VERSION = 9;
 
 // Newest first. Each entry: { version, date: 'YYYY-MM-DD', changes: [string, ...] }.
 export const CHANGELOG = [

src/pirats/crud_base.py

@@ -1,4 +1,5 @@
 import json
+import logging
 import os
 import random
 from typing import Any, Dict, List, Optional
@@ -6,6 +7,8 @@ from sqlmodel import Session, select
 from .models import Game, Player, GameEvent
 from . import cards
 
+logger = logging.getLogger(__name__)
+
 FACE_VALUES = ("J", "Q", "K")
 
 # --- Card and Hand Utilities ---
@@ -261,6 +264,7 @@ def create_game(db: Session, crew_name: Optional[str] = None) -> Game:
     db.add(game)
     db.commit()
     db.refresh(game)
+    logger.info("Game %s created (crew_name=%r, dev_mode=%s)", game.id, crew_name, game.dev_mode)
     return game
 
 def get_game(db: Session, game_id: str) -> Optional[Game]:
@@ -308,6 +312,10 @@ def add_player(db: Session, game_id: str, name: str, is_creator: bool = False) -
         msg += " They'll create their Pi-Rat with the crew between scenes."
     add_game_event(db, game_id, msg, kind="join")
 
+    logger.info(
+        "Player %s (%r) joined game %s (phase=%s, creator=%s)",
+        player.id, name, game_id, game.phase if game else "?", is_creator,
+    )
     return player
 
 def add_game_event(db: Session, game_id: str, message: str, kind: str = "info"):

src/pirats/crud_scene.py

@@ -1,4 +1,5 @@
 import json
+import logging
 from typing import Tuple, Dict, Any
 from sqlmodel import Session
 from .models import Game, Player, Obstacle
@@ -10,6 +11,8 @@ from .crud_base import (
     is_eligible_nominee
 )
 
+logger = logging.getLogger(__name__)
+
 # --- Scene Setup Operations ---
 
 def update_scene_role(db: Session, player_id: str, role: str):
@@ -409,3 +412,4 @@ def finish_game(db: Session, game_id: str):
     db.add(game)
     db.commit()
     add_game_event(db, game_id, "The story has ended! The Pi-Rats party til they pass out in a pile. 🎉", kind="victory")
+    logger.info("Game %s ended after %s scene(s)", game_id, game.current_scene_number)

src/pirats/crud_upkeep.py

@@ -1,3 +1,4 @@
+import logging
 import random
 from typing import List, Tuple
 from sqlmodel import Session, select
@@ -8,6 +9,8 @@ from .crud_base import (
     calculate_max_hand_size, change_player_rank, set_captain, is_eligible_nominee
 )
 
+logger = logging.getLogger(__name__)
+
 # --- Between Scenes Operations ---
 
 def eligible_vote_nominees(game: Game, voter) -> list:
@@ -252,6 +255,7 @@ def _remove_player(db: Session, game: Game, target: Player, event_message: str,
     phase's completion gate so a departed blocker can't stall the table."""
     from . import crud_character as cc
     target_id = target.id
+    logger.info("Removing player %s (%r) from game %s (%s)", target_id, target.name, game.id, event_kind)
 
     if game.captain_player_id == target_id:
         set_captain(db, game, None, reason=captain_reason)

src/pirats/main.py

@@ -6,7 +6,9 @@ from fastapi.responses import FileResponse, JSONResponse
 from fastapi.staticfiles import StaticFiles
 from sqlmodel import Session
 import logging
+from logging.handlers import RotatingFileHandler
 import re
+import sys
 import uvicorn
 import os
 from pathlib import Path
@@ -21,10 +23,58 @@ EVENT_PAGE_SIZE = 50
 
 BASE_DIR = Path(__file__).parent
 
+_logging_configured = False
+
+def configure_logging() -> None:
+    """Set up backend logging: always to stderr, plus a rotating file when
+    PIRATS_LOG_FILE is set (the NixOS service points it at /var/log/pirats/).
+    Level comes from PIRATS_LOG_LEVEL (default INFO). Idempotent so it's safe to
+    call from both the CLI entrypoint and the app's startup lifespan."""
+    global _logging_configured
+    if _logging_configured:
+        return
+    _logging_configured = True
+
+    level_name = os.environ.get("PIRATS_LOG_LEVEL", "INFO").upper()
+    level = getattr(logging, level_name, logging.INFO)
+
+    root = logging.getLogger()
+    root.setLevel(level)
+    fmt = logging.Formatter(
+        "%(asctime)s %(levelname)s [%(name)s] %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S",
+    )
+
+    stderr_handler = logging.StreamHandler(sys.stderr)
+    stderr_handler.setFormatter(fmt)
+    root.addHandler(stderr_handler)
+
+    log_file = os.environ.get("PIRATS_LOG_FILE")
+    if log_file:
+        try:
+            Path(log_file).parent.mkdir(parents=True, exist_ok=True)
+            file_handler = RotatingFileHandler(
+                log_file, maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8"
+            )
+            file_handler.setFormatter(fmt)
+            root.addHandler(file_handler)
+            logger.info("Logging to %s", log_file)
+        except OSError:
+            # A bad/unwritable path mustn't take the server down — keep stderr.
+            logger.exception("Could not open log file %s; logging to stderr only", log_file)
+
 @asynccontextmanager
 async def lifespan(app: FastAPI):
+    configure_logging()
+    logger.info(
+        "Starting Rats with Gats backend (db=%s, dev_mode_default=%s)",
+        engine.url.render_as_string(hide_password=True),
+        crud.dev_mode_default(),
+    )
     run_migrations()
+    logger.info("Database migrations applied")
     yield
+    logger.info("Shutting down")
 
 app = FastAPI(title="Rats with Gats Remote Play API", lifespan=lifespan)
 api = APIRouter()
@@ -189,6 +239,7 @@ if os.path.exists(static_dir):
     app.mount("/", StaticFiles(directory=static_dir, html=True), name="static")
 
 def main():
+    configure_logging()
     import argparse
     parser = argparse.ArgumentParser(description="Run the Rats with Gats web app")
     parser.add_argument("--host", default="0.0.0.0", help="Host address to bind to")