From 5e9f9bfb13744e0ba6be3b053569068d38ae2436 Mon Sep 17 00:00:00 2001 From: Tim McCarthy Date: Mon, 15 Jun 2026 15:42:06 -0700 Subject: [PATCH] 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 --- README.md | 15 +++++++++++ TODO.md | 2 +- flake.nix | 24 ++++++++++++++++- frontend/src/lib/changelog.js | 2 +- src/pirats/crud_base.py | 8 ++++++ src/pirats/crud_scene.py | 4 +++ src/pirats/crud_upkeep.py | 4 +++ src/pirats/main.py | 51 +++++++++++++++++++++++++++++++++++ 8 files changed, 107 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index c031045..4c6d7d3 100644 --- a/README.md +++ b/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 diff --git a/TODO.md b/TODO.md index ca88b03..716d9da 100644 --- a/TODO.md +++ b/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. diff --git a/flake.nix b/flake.nix index 6858b12..a2dc7ff 100644 --- a/flake.nix +++ b/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,15 +153,21 @@ # 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 = { ExecStart = "${cfg.package}/bin/pirats --host ${cfg.host} --port ${toString cfg.port}"; Restart = "always"; - + # 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"; diff --git a/frontend/src/lib/changelog.js b/frontend/src/lib/changelog.js index 8871d1b..13ba547 100644 --- a/frontend/src/lib/changelog.js +++ b/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 = [ diff --git a/src/pirats/crud_base.py b/src/pirats/crud_base.py index b450bac..058b57d 100644 --- a/src/pirats/crud_base.py +++ b/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"): diff --git a/src/pirats/crud_scene.py b/src/pirats/crud_scene.py index 685e17d..92e0033 100644 --- a/src/pirats/crud_scene.py +++ b/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) diff --git a/src/pirats/crud_upkeep.py b/src/pirats/crud_upkeep.py index 9027b4c..8d28723 100644 --- a/src/pirats/crud_upkeep.py +++ b/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) diff --git a/src/pirats/main.py b/src/pirats/main.py index c96a16d..a98d605 100644 --- a/src/pirats/main.py +++ b/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")