From 4a5ba51a53987382649e6b523f527c2ffae3dbbc Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 15:54:53 -0700 Subject: [PATCH 1/4] feat(booth): log each booth session locally for booth analytics [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Nothing measures how long people play at the booth or which game they pick. The booth cut for Heroes vs. Villains needs real session lengths, and the post-event report needs counts. - app/booth_log.gd appends JSON Lines to a local file: a launch line per run, then a start and an end line per game session. An end carries the duration (monotonic clock), how the session ended (menu, idle or quit) and how many retries it held. Nothing about players is recorded and nothing uses the network. Each event opens, appends and closes the file, so a crash loses at most one line; a start with no end marks a crash, power cut or kill. A write failure turns logging off with a warning and never touches gameplay. - AppRouter starts the log with --booth (user://booth/sessions.jsonl), or --session-log= with or without --booth, for playtests. go() reports each route change; the idle return passes "idle", and a forced quit ends the session as "quit". Menus end a session but never start one; re-entering the same game counts as a retry. - tools/booth/sessions_report.py summarizes one or more logs (per game sessions, median, mean and P90 length, end reasons, starts by hour, unfinished sessions) and can write one CSV row per session. Its unit tests run in the lint job. - tests/booth_session_log.gd covers flag parsing, child launches with and without the flags, retries, menu, idle and quit endings, an unwritable path, and that the log holds only the documented fields. --- .github/workflows/ci.yml | 2 + docs/builds.md | 8 + hoppys-adventure-arcade/app/app_router.gd | 39 ++++- hoppys-adventure-arcade/app/booth_log.gd | 85 ++++++++++ hoppys-adventure-arcade/app/booth_log.gd.uid | 1 + .../tests/booth_session_log.gd | 153 ++++++++++++++++++ .../tests/booth_session_log.gd.uid | 1 + tools/booth/sessions_report.py | 148 +++++++++++++++++ tools/booth/test_sessions_report.py | 118 ++++++++++++++ 9 files changed, 550 insertions(+), 5 deletions(-) create mode 100644 hoppys-adventure-arcade/app/booth_log.gd create mode 100644 hoppys-adventure-arcade/app/booth_log.gd.uid create mode 100644 hoppys-adventure-arcade/tests/booth_session_log.gd create mode 100644 hoppys-adventure-arcade/tests/booth_session_log.gd.uid create mode 100644 tools/booth/sessions_report.py create mode 100644 tools/booth/test_sessions_report.py diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 2ca9eb7e..12357e53 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -104,6 +104,8 @@ jobs: run: python tools/vendor/vendor_lock.py --check - name: Vendor lock unit tests run: python -m unittest discover -s tools/vendor -v + - name: Booth tools unit tests + run: python -m unittest discover -s tools/booth -v gitleaks: name: gitleaks diff --git a/docs/builds.md b/docs/builds.md index bbad89f7..b8bfdfed 100644 --- a/docs/builds.md +++ b/docs/builds.md @@ -36,6 +36,14 @@ open -a "Hoppy’s Adventure Arcade.app" --args -- --booth --route=heroes_vs_vil - **Idle reset.** After 90 seconds with no keyboard, mouse, touch or controller input, any game returns to the hub, whose rotating previews act as the attract screen. - **No quitting from the menu.** The menu's **Quit Game** does nothing in booth mode; staff close the window (Cmd+Q, Alt+F4). - **Launch route.** `--route=` opens a route at launch (`heroes_vs_villains`, `code_city_brawl`, `bay_area_blitz`, `orbital_ops`, `enchanted_repo`, `runner`, `platformer`, `beatem_up`, `hub`), with or without `--booth`. An unknown name logs an error and opens the hub. +- **Session log.** Booth mode appends each game session's start and end to `user://booth/sessions.jsonl`. Each entry records the game, the local start and end times, the duration, how the session ended (`menu`, `idle` or `quit`) and how many times the player retried. It records nothing about players and never uses the network. A start with no end means the game stopped without quitting: a crash, a power cut or a forced kill. The game prints the log's full path at startup. `--session-log=` writes to another file and works without `--booth`, for playtests. + +`user://` is `~/Library/Application Support/Godot/app_userdata/Hoppy’s Adventure Arcade/` on macOS, `%APPDATA%\Godot\app_userdata\Hoppy’s Adventure Arcade\` on Windows and `~/.local/share/godot/app_userdata/Hoppy’s Adventure Arcade/` on Linux. To summarize the logs, copy them off each machine and run: + +```sh +python3 tools/booth/sessions_report.py sessions.jsonl # sessions per game, durations, end reasons, starts by hour +python3 tools/booth/sessions_report.py booth-a.jsonl booth-b.jsonl --csv sessions.csv # combine machines; one CSV row per session +``` ## Build locally diff --git a/hoppys-adventure-arcade/app/app_router.gd b/hoppys-adventure-arcade/app/app_router.gd index 9f9a7eb2..446ecf15 100644 --- a/hoppys-adventure-arcade/app/app_router.gd +++ b/hoppys-adventure-arcade/app/app_router.gd @@ -1,4 +1,5 @@ extends CanvasLayer +const BoothLog := preload("res://app/booth_log.gd") const ROUTES := { "heroes_vs_villains": "res://scenes/beatem_up/reinvent/heroes_vs_villains.tscn", "code_city_brawl": "res://scenes/beatem_up/code_city_brawl.tscn", @@ -23,11 +24,17 @@ const BOOTH_FLAG := "--booth" const ROUTE_PREFIX := "--route=" const IDLE_SECONDS := 90.0 const STICK_DEADZONE := 0.4 +## Booth analytics (app/booth_log.gd): with --booth, each game session's start and end are appended +## to SESSION_LOG_DEFAULT. `--session-log=` (absolute or user://) picks another file and also +## works without --booth, for playtests. Nothing is logged unless one of them is passed. +const SESSION_LOG_PREFIX := "--session-log=" +const SESSION_LOG_DEFAULT := "user://booth/sessions.jsonl" var busy := false var veil: ColorRect var booth := false var idle_limit := IDLE_SECONDS var idle_seconds := 0.0 +var session_log: BoothLog func _ready() -> void: # The veil tween must keep running while a microgame has the tree paused. process_mode = Node.PROCESS_MODE_ALWAYS @@ -44,10 +51,15 @@ func _ready() -> void: smoke_routes.call_deferred() return set_booth(BOOTH_FLAG in args) + var log_path := session_log_path(args, booth) + if log_path != "": + start_session_log(log_path) var start := launch_route(args) if start != "": _launch.call_deferred(start) -func go(route: String) -> void: +## `reason` is how a game session in progress ends, for the session log: "menu" unless the router +## itself is leaving the game (booth mode's idle return passes "idle"). +func go(route: String, reason := "menu") -> void: if busy or not ROUTES.has(route) or not ResourceLoader.exists(ROUTES[route]): return busy = true @@ -60,6 +72,8 @@ func go(route: String) -> void: else: # A microgame may have paused the tree; never hand a paused tree to the next scene. get_tree().paused = false + if session_log: + session_log.route_changed(route, reason) if route == "hub": AudioService.play_default_music() await create_tween().tween_property(veil, "modulate:a", 0.0, 0.25).finished @@ -70,10 +84,13 @@ func go(route: String) -> void: func quit_game(force := false) -> void: if booth and not force: return + if busy and not force: + return + if session_log: + session_log.end("quit") if busy: - if force: - AudioService.shutdown() - get_tree().quit() + AudioService.shutdown() + get_tree().quit() return busy = true veil.mouse_filter = Control.MOUSE_FILTER_STOP @@ -95,6 +112,18 @@ static func launch_route(args: PackedStringArray) -> String: push_error("Unknown --route %s; expected one of %s" % [route, ", ".join(ROUTES.keys())]) return "" +## The session log these arguments ask for: `--session-log=`, else the default file in booth +## mode, else "" (no logging). +static func session_log_path(args: PackedStringArray, booth_mode: bool) -> String: + for arg in args: + if arg.begins_with(SESSION_LOG_PREFIX) and arg.length() > SESSION_LOG_PREFIX.length(): + return arg.trim_prefix(SESSION_LOG_PREFIX) + return SESSION_LOG_DEFAULT if booth_mode else "" + +func start_session_log(path: String) -> void: + session_log = BoothLog.new(path) + print("AppRouter: session log at %s" % ProjectSettings.globalize_path(path)) + func _launch(route: String) -> void: await go(route) var scene := get_tree().current_scene @@ -123,7 +152,7 @@ func _process(delta: float) -> void: idle_seconds = 0.0 var scene := get_tree().current_scene if scene == null or scene.scene_file_path != ROUTES["hub"]: - go("hub") + go("hub", "idle") func smoke_routes() -> void: # Let the launch scene finish its opening frames, as a player would, before switching. diff --git a/hoppys-adventure-arcade/app/booth_log.gd b/hoppys-adventure-arcade/app/booth_log.gd new file mode 100644 index 00000000..2438a3f8 --- /dev/null +++ b/hoppys-adventure-arcade/app/booth_log.gd @@ -0,0 +1,85 @@ +extends RefCounted +## Local booth analytics: an append-only JSON Lines file, one line per event. Nothing leaves the +## machine and nothing identifies a player. The only fields are the game, local times, the session +## length and how it ended: +## {"event":"launch","launch":"2026-11-30T09:58:12","time":"2026-11-30T09:58:12", +## "version":"0.1.0"} +## {"event":"start","launch":"2026-11-30T09:58:12","session":1,"game":"heroes_vs_villains", +## "time":"2026-11-30T10:02:03"} +## {"event":"end","launch":"2026-11-30T09:58:12","session":1,"game":"heroes_vs_villains", +## "time":"2026-11-30T10:04:26","duration_s":143.2,"ended_by":"idle","retries":0} +## A session is one visit to a game route. Re-entering the same game (the runner's or a platformer +## level's Retry) counts as a retry within it. `ended_by` is "menu" (the player left through the +## game's own menu), "idle" (booth mode's idle return) or "quit". A start with no end means the game +## stopped without quitting: a crash, a power cut or a forced kill. +## tools/booth/sessions_report.py summarizes the file. + +## Routes that are games. The hub and mode menus end a session but never start one. +const GAMES: Array[String] = ["heroes_vs_villains", "code_city_brawl", "bay_area_blitz", + "orbital_ops", "enchanted_repo", "runner_game"] +var path := "" +## When this run of the game started; with `session` it identifies a session across restarts. +var launch := "" +## The game being played, or "" between sessions. +var game := "" +var session := 0 +var retries := 0 +var started_msec := 0 +## Set after the first failed write: the game keeps running, unlogged, rather than retrying. +var failed := false + +func _init(log_path: String) -> void: + path = log_path + launch = Time.get_datetime_string_from_system() + var directory := path.get_base_dir() + if directory != "" and not DirAccess.dir_exists_absolute(directory): + DirAccess.make_dir_recursive_absolute(directory) + _write({"event": "launch", "time": launch, + "version": str(ProjectSettings.get_setting("application/config/version", ""))}) + +## AppRouter calls this after each successful route change. `reason` is how the session in +## progress, if any, ends. +func route_changed(route: String, reason: String) -> void: + if game != "" and route == game: + retries += 1 + return + end(reason) + if route in GAMES: + game = route + session += 1 + retries = 0 + started_msec = Time.get_ticks_msec() + _write({"event": "start", "session": session, "game": game, + "time": Time.get_datetime_string_from_system()}) + +## Close the session in progress, if any. Durations use the monotonic clock, so a wall-clock change +## mid-session can't skew them. +func end(reason: String) -> void: + if game == "": + return + var seconds := (Time.get_ticks_msec() - started_msec) / 1000.0 + _write({"event": "end", "session": session, "game": game, + "time": Time.get_datetime_string_from_system(), "duration_s": snappedf(seconds, 0.1), + "ended_by": reason, "retries": retries}) + game = "" + +## Open, append and close per event, so a crash loses at most the line being written. +func _write(fields: Dictionary) -> void: + if failed: + return + var record := {"event": fields.event, "launch": launch} + record.merge(fields) + var file := FileAccess.open(path, FileAccess.READ_WRITE if FileAccess.file_exists(path) + else FileAccess.WRITE) + if file == null: + _fail(error_string(FileAccess.get_open_error())) + return + file.seek_end() + var written := file.store_line(JSON.stringify(record, "", false)) + file.close() + if not written: + _fail("write failed") + +func _fail(reason: String) -> void: + failed = true + push_warning("Booth session log: cannot write %s (%s); session logging is off." % [path, reason]) diff --git a/hoppys-adventure-arcade/app/booth_log.gd.uid b/hoppys-adventure-arcade/app/booth_log.gd.uid new file mode 100644 index 00000000..1d336df3 --- /dev/null +++ b/hoppys-adventure-arcade/app/booth_log.gd.uid @@ -0,0 +1 @@ +uid://0qkhsv822dvw diff --git a/hoppys-adventure-arcade/tests/booth_session_log.gd b/hoppys-adventure-arcade/tests/booth_session_log.gd new file mode 100644 index 00000000..4bb115a5 --- /dev/null +++ b/hoppys-adventure-arcade/tests/booth_session_log.gd @@ -0,0 +1,153 @@ +extends SceneTree +## Booth session log (app/booth_log.gd): each visit to a game writes a start and an end line, +## re-entering the same game counts as a retry, menus never start a session, idle and quit say how +## a session ended, and nothing is written unless --booth or --session-log asks for it. The flags +## are checked by launching the game as a child process, so _ready()'s argument handling is covered. +## Run headless with --script res://tests/booth_session_log.gd. +const BoothLog := preload("res://app/booth_log.gd") +const LOG := "user://test_booth_sessions.jsonl" +const CHILD_LOG := "user://test_booth_child_sessions.jsonl" +## Every field the log may contain. Anything else would be new data about players: review it first. +const FIELDS := ["event", "launch", "time", "version", "session", "game", "duration_s", "ended_by", + "retries"] +var failures := 0 +var router: Node + +func _initialize() -> void: + call_deferred("run") + +func check(ok: bool, message: String) -> void: + print("PASS: " if ok else "FAIL: ", message) + if not ok: + failures += 1 + +func wait(seconds: float) -> void: + await create_timer(seconds, true).timeout + +func settle_route() -> void: + for i in 300: + if not router.busy: + break + await process_frame + await process_frame + +func visit(route: String) -> void: + router.go(route) + await settle_route() + +## Launch the game headless with user args for two simulated seconds and return its exit code. +func launch(user_args: Array[String]) -> int: + var args: Array[String] = ["--headless", "--path", ProjectSettings.globalize_path("res://"), + "--fixed-fps", "60", "--quit-after", "120", "--"] + args.append_array(user_args) + var output: Array = [] + return OS.execute(OS.get_executable_path(), args, output, true) + +## The log's records in order; a line that isn't a JSON object is a failed check. +func records(path: String) -> Array[Dictionary]: + var result: Array[Dictionary] = [] + var file := FileAccess.open(path, FileAccess.READ) + if file == null: + return result + while not file.eof_reached(): + var line := file.get_line() + if line.is_empty(): + continue + var parsed: Variant = JSON.parse_string(line) + check(parsed is Dictionary, "Log line is a JSON object: " + line) + if parsed is Dictionary: + result.append(parsed) + return result + +func events(entries: Array[Dictionary], kind: String) -> Array[Dictionary]: + return entries.filter(func(record: Dictionary) -> bool: return record.event == kind) + +func run() -> void: + router = root.get_node("AppRouter") + await wait(0.3) + check(router.session_log == null, "No session log without --booth or --session-log") + check(router.session_log_path(PackedStringArray(), false) == "", + "No flags means no session log") + check(router.session_log_path(PackedStringArray(["--booth"]), true) == router.SESSION_LOG_DEFAULT, + "Booth mode logs to the default file") + check(router.session_log_path(PackedStringArray(["--session-log=user://playtest.jsonl"]), false) + == "user://playtest.jsonl", "--session-log picks a file, with or without --booth") + check(router.session_log_path(PackedStringArray(["--session-log="]), false) == "", + "An empty --session-log is ignored") + + check(launch(["--route=bay_area_blitz"]) == 0, "A plain launch exits cleanly") + check(not FileAccess.file_exists(router.SESSION_LOG_DEFAULT), + "A launch without --booth writes no session log") + check(launch(["--booth", "--route=heroes_vs_villains"]) == 0, "A booth launch exits cleanly") + var booth_log := records(router.SESSION_LOG_DEFAULT) + check(booth_log.size() == 2 and booth_log[0].event == "launch" + and booth_log[0].version == ProjectSettings.get_setting("application/config/version") + and booth_log[1].event == "start" and booth_log[1].game == "heroes_vs_villains", + "--booth logs the launch and the launch route's session start") + # --quit-after stops the child without a quit request, as a crash would: the start stays open. + check(events(booth_log, "end").is_empty(), "A run that stops without quitting leaves no end") + check(launch(["--session-log=" + ProjectSettings.globalize_path(CHILD_LOG), + "--route=orbital_ops"]) == 0, "A --session-log launch exits cleanly") + var child_log := records(CHILD_LOG) + check(child_log.size() == 2 and child_log[1].game == "orbital_ops", + "--session-log logs without --booth") + + # A file where the log's folder should be: logging switches itself off with a warning. + var blocker := FileAccess.open("user://test_booth_blocker", FileAccess.WRITE) + blocker.store_line("not a folder") + blocker.close() + var broken := BoothLog.new("user://test_booth_blocker/sessions.jsonl") + broken.route_changed("heroes_vs_villains", "menu") + broken.end("quit") + check(broken.failed and broken.game == "", + "An unwritable log turns itself off and the session bookkeeping carries on") + + router.start_session_log(LOG) + await visit("bay_area_blitz") + await visit("bay_area_blitz") + await visit("platformer") + await visit("heroes_vs_villains") + router.set_booth(true) + router.idle_limit = 0.5 + await wait(1.0) + await settle_route() + router.set_booth(false) + router.idle_limit = router.IDLE_SECONDS + await visit("code_city_brawl") + router.set_booth(true) + router.quit_game() + check(router.session_log.game == "code_city_brawl", + "The menu's Quit, ignored in booth mode, leaves the session open") + router.set_booth(false) + # quit_game(true) would end this suite; it calls the same end("quit"). + router.session_log.end("quit") + + var entries := records(LOG) + var starts := events(entries, "start") + var ends := events(entries, "end") + check(entries.size() > 0 and entries[0].event == "launch", "The log opens with a launch line") + check(starts.map(func(record: Dictionary) -> String: return record.game) + == ["bay_area_blitz", "heroes_vs_villains", "code_city_brawl"], + "Each game visit starts one session; menus and the hub start none") + check(ends.size() == 3, "Every session ends") + if ends.size() == 3: + check(ends[0].ended_by == "menu" and int(ends[0].retries) == 1, + "Re-entering a game is a retry; leaving for a menu ends the session") + check(ends[1].ended_by == "idle", "Booth mode's idle return ends a session as idle") + check(ends[2].ended_by == "quit", "Quitting ends a session as quit") + var numbered := true + for i in 3: + numbered = numbered and int(starts[i].session) == i + 1 and int(ends[i].session) == i + 1 \ + and starts[i].launch == entries[0].launch and ends[i].game == starts[i].game \ + and float(ends[i].duration_s) > 0.0 + check(numbered, "Starts and ends pair by launch and session, with a positive duration") + var extra := [] + for record in entries: + for key in record: + if key not in FIELDS: + extra.append(key) + check(extra.is_empty(), "The log holds only the documented fields (found %s)" % [extra]) + + await root.get_node("AudioService").settle() + print("Booth session log failures: ", failures) + quit(1 if failures else 0) diff --git a/hoppys-adventure-arcade/tests/booth_session_log.gd.uid b/hoppys-adventure-arcade/tests/booth_session_log.gd.uid new file mode 100644 index 00000000..fb6d2441 --- /dev/null +++ b/hoppys-adventure-arcade/tests/booth_session_log.gd.uid @@ -0,0 +1 @@ +uid://cbw4cryaigjjy diff --git a/tools/booth/sessions_report.py b/tools/booth/sessions_report.py new file mode 100644 index 00000000..f2a12532 --- /dev/null +++ b/tools/booth/sessions_report.py @@ -0,0 +1,148 @@ +"""Summarize the session logs that booth mode writes (hoppys-adventure-arcade/app/booth_log.gd). + +Usage: + python3 tools/booth/sessions_report.py sessions.jsonl [more.jsonl ...] + python3 tools/booth/sessions_report.py sessions.jsonl --csv sessions.csv + +Each line of a log is one event: "launch" (the game started), then "start" and "end" for each +game session. Starts and ends pair by file, launch and session number. A start without an end +means the game stopped without quitting (a crash, a power cut or a forced kill); it is reported +as unfinished. Pass every machine's log at once to combine them. Standard library only. +""" +from __future__ import annotations + +import argparse +import csv +import json +import statistics +import sys +from collections import Counter +from dataclasses import dataclass +from pathlib import Path + + +@dataclass +class Session: + source: str + launch: str + number: int + game: str + start: str + end: str = "" + duration_s: float | None = None + ended_by: str = "" + retries: int = 0 + + +@dataclass +class Log: + sessions: list[Session] + launches: int + skipped: list[str] + + +def read(paths: list[Path]) -> Log: + """Pair the start and end events in these files. Lines that don't parse are skipped and named.""" + sessions: dict[tuple[str, str, int], Session] = {} + launches = 0 + skipped: list[str] = [] + for path in paths: + with path.open(encoding="utf-8") as handle: + for number, line in enumerate(handle, 1): + if not line.strip(): + continue + where = f"{path}:{number}" + try: + event = json.loads(line) + kind = event["event"] + if kind == "launch": + launches += 1 + continue + key = (str(path), str(event["launch"]), int(event["session"])) + if kind == "start": + sessions[key] = Session(key[0], key[1], key[2], str(event["game"]), str(event["time"])) + elif kind == "end": + session = sessions.get(key) + if session is None: + skipped.append(f"{where}: end without a start") + continue + session.end = str(event["time"]) + session.duration_s = float(event["duration_s"]) + session.ended_by = str(event["ended_by"]) + session.retries = int(event.get("retries", 0)) + else: + skipped.append(f"{where}: unknown event {kind!r}") + except (json.JSONDecodeError, KeyError, TypeError, ValueError) as error: + skipped.append(f"{where}: {type(error).__name__}: {error}") + ordered = sorted(sessions.values(), key=lambda s: (s.start, s.source, s.launch, s.number)) + return Log(ordered, launches, skipped) + + +def clock(seconds: float) -> str: + """143.2 -> '2:23'.""" + whole = int(round(seconds)) + return f"{whole // 60}:{whole % 60:02d}" + + +def p90(values: list[float]) -> float: + """The 90th percentile, or the largest value when there are too few to interpolate.""" + if len(values) < 2: + return max(values) + return statistics.quantiles(values, n=10, method="inclusive")[-1] + + +def summary(log: Log) -> str: + finished = [s for s in log.sessions if s.duration_s is not None] + unfinished = len(log.sessions) - len(finished) + lines = [ + f"Launches: {log.launches}", + f"Sessions: {len(log.sessions)} ({len(finished)} finished, {unfinished} unfinished)", + ] + if finished: + lines += ["", f"{'Game':<20} {'Sessions':>8} {'Median':>7} {'Mean':>7} {'P90':>7} {'Retries':>8}"] + for game in sorted({s.game for s in finished}): + durations = [s.duration_s for s in finished if s.game == game] + retries = sum(s.retries for s in finished if s.game == game) + lines.append( + f"{game:<20} {len(durations):>8} {clock(statistics.median(durations)):>7}" + f" {clock(statistics.fmean(durations)):>7} {clock(p90(durations)):>7} {retries:>8}" + ) + ended = Counter(s.ended_by for s in finished) + lines += ["", "Ended by: " + ", ".join(f"{reason} {count}" for reason, count in sorted(ended.items()))] + if log.sessions: + hours = Counter(s.start[11:13] for s in log.sessions if len(s.start) >= 13) + lines.append("Starts by hour: " + ", ".join(f"{hour}:00 {count}" for hour, count in sorted(hours.items()))) + if log.skipped: + lines += ["", f"Skipped {len(log.skipped)} line(s):"] + [f" {entry}" for entry in log.skipped] + return "\n".join(lines) + + +def write_csv(log: Log, target: Path) -> None: + """One row per session, for spreadsheets and the post-event report.""" + with target.open("w", newline="", encoding="utf-8") as handle: + writer = csv.writer(handle) + writer.writerow(["source", "launch", "session", "game", "start", "end", "duration_s", "ended_by", "retries"]) + for s in log.sessions: + duration = "" if s.duration_s is None else f"{s.duration_s:.1f}" + writer.writerow([s.source, s.launch, s.number, s.game, s.start, s.end, duration, s.ended_by or "unfinished", s.retries]) + + +def main(argv: list[str] | None = None) -> int: + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0]) + parser.add_argument("logs", nargs="+", type=Path, help="session logs (JSON Lines)") + parser.add_argument("--csv", type=Path, help="also write one row per session to this CSV file") + args = parser.parse_args(argv) + missing = [str(path) for path in args.logs if not path.is_file()] + if missing: + print("No such log: " + ", ".join(missing), file=sys.stderr) + return 2 + log = read(args.logs) + print(summary(log)) + if args.csv: + write_csv(log, args.csv) + print(f"\nWrote {len(log.sessions)} session(s) to {args.csv}") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/booth/test_sessions_report.py b/tools/booth/test_sessions_report.py new file mode 100644 index 00000000..0f789305 --- /dev/null +++ b/tools/booth/test_sessions_report.py @@ -0,0 +1,118 @@ +"""Unit tests for sessions_report.py. Run: python3 -m unittest discover -s tools/booth -v""" +from __future__ import annotations + +import csv +import io +import json +import sys +import tempfile +import unittest +from contextlib import redirect_stderr, redirect_stdout +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import sessions_report # noqa: E402 + +LAUNCH = "2026-11-30T09:58:12" + + +def event(kind: str, **fields: object) -> str: + return json.dumps({"event": kind, "launch": LAUNCH, **fields}) + + +def start(session: int, game: str, time: str) -> str: + return event("start", session=session, game=game, time=time) + + +def end(session: int, game: str, time: str, duration: float, ended_by: str, retries: int = 0) -> str: + return event("end", session=session, game=game, time=time, duration_s=duration, ended_by=ended_by, retries=retries) + + +class SessionsReportTest(unittest.TestCase): + def setUp(self) -> None: + self.folder = tempfile.TemporaryDirectory() + self.addCleanup(self.folder.cleanup) + + def write(self, name: str, lines: list[str]) -> Path: + path = Path(self.folder.name) / name + path.write_text("\n".join(lines) + "\n", encoding="utf-8") + return path + + def sample(self) -> Path: + return self.write("booth.jsonl", [ + event("launch", time=LAUNCH, version="0.1.0"), + start(1, "heroes_vs_villains", "2026-11-30T10:02:03"), + end(1, "heroes_vs_villains", "2026-11-30T10:04:26", 143.2, "idle"), + start(2, "heroes_vs_villains", "2026-11-30T10:05:00"), + end(2, "heroes_vs_villains", "2026-11-30T10:08:00", 180.0, "menu", retries=2), + start(3, "runner_game", "2026-11-30T11:00:00"), + end(3, "runner_game", "2026-11-30T11:01:00", 60.0, "quit"), + start(4, "code_city_brawl", "2026-11-30T11:30:00"), + ]) + + def test_pairs_starts_and_ends_and_keeps_unfinished_sessions(self) -> None: + log = sessions_report.read([self.sample()]) + self.assertEqual(log.launches, 1) + self.assertEqual([s.game for s in log.sessions], ["heroes_vs_villains", "heroes_vs_villains", "runner_game", "code_city_brawl"]) + self.assertEqual(log.sessions[1].retries, 2) + self.assertEqual(log.sessions[0].ended_by, "idle") + self.assertIsNone(log.sessions[3].duration_s, "a start without an end is unfinished") + self.assertEqual(log.skipped, []) + + def test_summary_reports_games_reasons_and_hours(self) -> None: + text = sessions_report.summary(sessions_report.read([self.sample()])) + self.assertIn("Sessions: 4 (3 finished, 1 unfinished)", text) + hvv = next(line for line in text.splitlines() if line.startswith("heroes_vs_villains")) + # Two sessions: 143.2 s and 180 s. Median and mean 161.6 s; P90 interpolates to 176.3 s. + self.assertEqual(hvv.split(), ["heroes_vs_villains", "2", "2:42", "2:42", "2:56", "2"]) + self.assertIn("Ended by: idle 1, menu 1, quit 1", text) + self.assertIn("Starts by hour: 10:00 2, 11:00 2", text) + + def test_same_launch_in_two_files_stays_separate(self) -> None: + first = self.write("a.jsonl", [start(1, "runner_game", "2026-11-30T10:00:00"), end(1, "runner_game", "2026-11-30T10:01:00", 60, "menu")]) + second = self.write("b.jsonl", [start(1, "orbital_ops", "2026-11-30T10:00:30")]) + log = sessions_report.read([first, second]) + self.assertEqual([(s.game, s.duration_s) for s in log.sessions], [("runner_game", 60.0), ("orbital_ops", None)]) + + def test_bad_lines_are_skipped_and_named(self) -> None: + path = self.write("bad.jsonl", [ + "not json", + json.dumps({"event": "start", "launch": LAUNCH}), + end(9, "runner_game", "2026-11-30T10:01:00", 60, "menu"), + event("mystery"), + "", + start(1, "runner_game", "2026-11-30T10:00:00"), + ]) + log = sessions_report.read([path]) + self.assertEqual(len(log.sessions), 1) + self.assertEqual(len(log.skipped), 4) + self.assertIn("bad.jsonl:3: end without a start", log.skipped[2]) + self.assertIn("Skipped 4 line(s):", sessions_report.summary(log)) + + def test_csv_has_one_row_per_session(self) -> None: + target = Path(self.folder.name) / "out.csv" + with redirect_stdout(io.StringIO()): + self.assertEqual(sessions_report.main([str(self.sample()), "--csv", str(target)]), 0) + with target.open(encoding="utf-8") as handle: + rows = list(csv.DictReader(handle)) + self.assertEqual(len(rows), 4) + self.assertEqual(rows[0]["duration_s"], "143.2") + self.assertEqual(rows[3]["ended_by"], "unfinished") + self.assertEqual(rows[3]["duration_s"], "") + + def test_missing_log_is_an_error(self) -> None: + with redirect_stderr(io.StringIO()) as err: + self.assertEqual(sessions_report.main([str(Path(self.folder.name) / "nope.jsonl")]), 2) + self.assertIn("No such log", err.getvalue()) + + def test_empty_log_prints_counts_only(self) -> None: + text = sessions_report.summary(sessions_report.read([self.write("empty.jsonl", [])])) + self.assertEqual(text, "Launches: 0\nSessions: 0 (0 finished, 0 unfinished)") + + def test_clock(self) -> None: + self.assertEqual(sessions_report.clock(143.2), "2:23") + self.assertEqual(sessions_report.clock(59.6), "1:00") + + +if __name__ == "__main__": + unittest.main() From 93a6b7a8fb6e092c8d9a70b2dff6c26d7813c39a Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 16:27:40 -0700 Subject: [PATCH 2/4] fix(booth): harden the session report and isolate the session-log suite [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Addresses CodeRabbit review 5541040174 on #74: - sessions_report.py converts every end field before touching the session, so a malformed end leaves it unfinished. NaN, infinite, negative and overflowing durations count as malformed lines. - The per-game table counts every visit, with a new Unfinished column; lengths and retries still come from finished sessions, and a game with only unfinished visits is listed with dashes. - --csv refuses a target that resolves to one of the input logs. - Launch ids carry milliseconds, so a relaunch appending to the same log never reuses one. A test appends two launches to one file. - tests/booth_session_log.gd gives its child launches a throwaway user-data root and finds the log from the path the game prints, so a standalone run never reads or writes a real booth log. It removes every file it creates and guards the pairing loop's indices. - A child process (tests/support/session_log_quit.gd, skipped as a suite) quits through AppRouter.quit_game(true), and the suite checks its "quit" end, instead of calling end("quit") directly. --- hoppys-adventure-arcade/app/booth_log.gd | 15 +- .../tests/booth_session_log.gd | 139 +++++++++++++++--- .../tests/support/session_log_quit.gd | 24 +++ .../tests/support/session_log_quit.gd.uid | 1 + tools/booth/sessions_report.py | 34 +++-- tools/booth/test_sessions_report.py | 46 +++++- tools/tests/suites.toml | 1 + 7 files changed, 211 insertions(+), 49 deletions(-) create mode 100644 hoppys-adventure-arcade/tests/support/session_log_quit.gd create mode 100644 hoppys-adventure-arcade/tests/support/session_log_quit.gd.uid diff --git a/hoppys-adventure-arcade/app/booth_log.gd b/hoppys-adventure-arcade/app/booth_log.gd index 2438a3f8..73a44906 100644 --- a/hoppys-adventure-arcade/app/booth_log.gd +++ b/hoppys-adventure-arcade/app/booth_log.gd @@ -2,11 +2,11 @@ extends RefCounted ## Local booth analytics: an append-only JSON Lines file, one line per event. Nothing leaves the ## machine and nothing identifies a player. The only fields are the game, local times, the session ## length and how it ended: -## {"event":"launch","launch":"2026-11-30T09:58:12","time":"2026-11-30T09:58:12", +## {"event":"launch","launch":"2026-11-30T09:58:12.345","time":"2026-11-30T09:58:12", ## "version":"0.1.0"} -## {"event":"start","launch":"2026-11-30T09:58:12","session":1,"game":"heroes_vs_villains", +## {"event":"start","launch":"2026-11-30T09:58:12.345","session":1,"game":"heroes_vs_villains", ## "time":"2026-11-30T10:02:03"} -## {"event":"end","launch":"2026-11-30T09:58:12","session":1,"game":"heroes_vs_villains", +## {"event":"end","launch":"2026-11-30T09:58:12.345","session":1,"game":"heroes_vs_villains", ## "time":"2026-11-30T10:04:26","duration_s":143.2,"ended_by":"idle","retries":0} ## A session is one visit to a game route. Re-entering the same game (the runner's or a platformer ## level's Retry) counts as a retry within it. `ended_by` is "menu" (the player left through the @@ -18,7 +18,8 @@ extends RefCounted const GAMES: Array[String] = ["heroes_vs_villains", "code_city_brawl", "bay_area_blitz", "orbital_ops", "enchanted_repo", "runner_game"] var path := "" -## When this run of the game started; with `session` it identifies a session across restarts. +## When this run of the game started, to the millisecond, so two runs logging to one file (a +## watchdog relaunch, or a second copy) stay apart. With `session` it identifies a session. var launch := "" ## The game being played, or "" between sessions. var game := "" @@ -30,11 +31,13 @@ var failed := false func _init(log_path: String) -> void: path = log_path - launch = Time.get_datetime_string_from_system() + var now := Time.get_unix_time_from_system() + var local := int(now) + int(Time.get_time_zone_from_system().bias) * 60 + launch = "%s.%03d" % [Time.get_datetime_string_from_unix_time(local), int(fmod(now, 1.0) * 1000.0)] var directory := path.get_base_dir() if directory != "" and not DirAccess.dir_exists_absolute(directory): DirAccess.make_dir_recursive_absolute(directory) - _write({"event": "launch", "time": launch, + _write({"event": "launch", "time": launch.get_slice(".", 0), "version": str(ProjectSettings.get_setting("application/config/version", ""))}) ## AppRouter calls this after each successful route change. `reason` is how the session in diff --git a/hoppys-adventure-arcade/tests/booth_session_log.gd b/hoppys-adventure-arcade/tests/booth_session_log.gd index 4bb115a5..728b9cac 100644 --- a/hoppys-adventure-arcade/tests/booth_session_log.gd +++ b/hoppys-adventure-arcade/tests/booth_session_log.gd @@ -2,11 +2,18 @@ extends SceneTree ## Booth session log (app/booth_log.gd): each visit to a game writes a start and an end line, ## re-entering the same game counts as a retry, menus never start a session, idle and quit say how ## a session ended, and nothing is written unless --booth or --session-log asks for it. The flags -## are checked by launching the game as a child process, so _ready()'s argument handling is covered. -## Run headless with --script res://tests/booth_session_log.gd. +## and the window-close quit are checked in child processes, so _ready()'s argument handling and +## quit_game() are covered. Child launches get a throwaway user-data root, so a standalone run never +## reads or writes a real booth log. Run headless with --script res://tests/booth_session_log.gd. const BoothLog := preload("res://app/booth_log.gd") const LOG := "user://test_booth_sessions.jsonl" const CHILD_LOG := "user://test_booth_child_sessions.jsonl" +const QUIT_LOG := "user://test_booth_quit_sessions.jsonl" +const RELAUNCH_LOG := "user://test_booth_relaunch_sessions.jsonl" +const BLOCKER := "user://test_booth_blocker" +const CHILD_HOME := "user://test_booth_home" +const ISOLATED := ["HOME", "XDG_DATA_HOME", "XDG_CONFIG_HOME", "APPDATA", "LOCALAPPDATA", + "USERPROFILE"] ## Every field the log may contain. Anything else would be new data about players: review it first. const FIELDS := ["event", "launch", "time", "version", "session", "game", "duration_s", "ended_by", "retries"] @@ -35,13 +42,41 @@ func visit(route: String) -> void: router.go(route) await settle_route() -## Launch the game headless with user args for two simulated seconds and return its exit code. -func launch(user_args: Array[String]) -> int: - var args: Array[String] = ["--headless", "--path", ProjectSettings.globalize_path("res://"), - "--fixed-fps", "60", "--quit-after", "120", "--"] - args.append_array(user_args) +## Run Godot on this project and return its exit code and output. +func godot(args: Array[String]) -> Dictionary: + var full: Array[String] = ["--headless", "--path", ProjectSettings.globalize_path("res://")] + full.append_array(args) var output: Array = [] - return OS.execute(OS.get_executable_path(), args, output, true) + var code := OS.execute(OS.get_executable_path(), full, output, true) + return {"code": code, "log": "\n".join(output)} + +## Launch the game for two simulated seconds with a throwaway user-data root (the variables Godot +## reads on each OS), so the default booth log is never a real one. +func launch(user_args: Array[String]) -> Dictionary: + var home := ProjectSettings.globalize_path(CHILD_HOME) + var saved := {} + for variable in ISOLATED: + saved[variable] = OS.get_environment(variable) if OS.has_environment(variable) else null + var values := [home, home.path_join(".local/share"), home.path_join(".config"), + home.path_join("AppData/Roaming"), home.path_join("AppData/Local"), home] + for i in ISOLATED.size(): + OS.set_environment(ISOLATED[i], values[i]) + var args: Array[String] = ["--fixed-fps", "60", "--quit-after", "120", "--"] + args.append_array(user_args) + var result := godot(args) + for variable in saved: + if saved[variable] == null: + OS.unset_environment(variable) + else: + OS.set_environment(variable, saved[variable]) + return result + +## The log path a child printed at startup, or "". +func logged_path(output: String) -> String: + for line in output.split("\n"): + if line.begins_with("AppRouter: session log at "): + return line.trim_prefix("AppRouter: session log at ").strip_edges() + return "" ## The log's records in order; a line that isn't a JSON object is a failed check. func records(path: String) -> Array[Dictionary]: @@ -62,8 +97,38 @@ func records(path: String) -> Array[Dictionary]: func events(entries: Array[Dictionary], kind: String) -> Array[Dictionary]: return entries.filter(func(record: Dictionary) -> bool: return record.event == kind) +func find_file(directory: String, file_name: String) -> bool: + var dir := DirAccess.open(directory) + if dir == null: + return false + dir.include_hidden = true + if file_name in dir.get_files(): + return true + for child in dir.get_directories(): + if find_file(directory.path_join(child), file_name): + return true + return false + +func remove_tree(directory: String) -> void: + var dir := DirAccess.open(directory) + if dir == null: + return + dir.include_hidden = true + for file_name in dir.get_files(): + dir.remove(file_name) + for child in dir.get_directories(): + remove_tree(directory.path_join(child)) + DirAccess.remove_absolute(directory) + +func clean() -> void: + for path in [LOG, CHILD_LOG, QUIT_LOG, RELAUNCH_LOG, BLOCKER]: + if FileAccess.file_exists(path): + DirAccess.remove_absolute(path) + remove_tree(ProjectSettings.globalize_path(CHILD_HOME)) + func run() -> void: router = root.get_node("AppRouter") + clean() await wait(0.3) check(router.session_log == null, "No session log without --booth or --session-log") check(router.session_log_path(PackedStringArray(), false) == "", @@ -75,28 +140,52 @@ func run() -> void: check(router.session_log_path(PackedStringArray(["--session-log="]), false) == "", "An empty --session-log is ignored") - check(launch(["--route=bay_area_blitz"]) == 0, "A plain launch exits cleanly") - check(not FileAccess.file_exists(router.SESSION_LOG_DEFAULT), + var plain := launch(["--route=bay_area_blitz"]) + check(plain.code == 0, "A plain launch exits cleanly") + check(logged_path(plain.log) == "" + and not find_file(ProjectSettings.globalize_path(CHILD_HOME), "sessions.jsonl"), "A launch without --booth writes no session log") - check(launch(["--booth", "--route=heroes_vs_villains"]) == 0, "A booth launch exits cleanly") - var booth_log := records(router.SESSION_LOG_DEFAULT) + var kiosk := launch(["--booth", "--route=heroes_vs_villains"]) + var booth_path := logged_path(kiosk.log) + check(kiosk.code == 0, "A booth launch exits cleanly") + check(booth_path.begins_with(ProjectSettings.globalize_path(CHILD_HOME)) + and booth_path.ends_with("booth/sessions.jsonl"), + "--booth logs to booth/sessions.jsonl in the user data (%s)" % booth_path) + var booth_log := records(booth_path) check(booth_log.size() == 2 and booth_log[0].event == "launch" and booth_log[0].version == ProjectSettings.get_setting("application/config/version") and booth_log[1].event == "start" and booth_log[1].game == "heroes_vs_villains", "--booth logs the launch and the launch route's session start") # --quit-after stops the child without a quit request, as a crash would: the start stays open. check(events(booth_log, "end").is_empty(), "A run that stops without quitting leaves no end") - check(launch(["--session-log=" + ProjectSettings.globalize_path(CHILD_LOG), - "--route=orbital_ops"]) == 0, "A --session-log launch exits cleanly") + var child := launch(["--session-log=" + ProjectSettings.globalize_path(CHILD_LOG), + "--route=orbital_ops"]) var child_log := records(CHILD_LOG) - check(child_log.size() == 2 and child_log[1].game == "orbital_ops", + check(child.code == 0 and child_log.size() == 2 and child_log[1].game == "orbital_ops", "--session-log logs without --booth") + var closed := godot(["--script", "res://tests/support/session_log_quit.gd", "--", + ProjectSettings.globalize_path(QUIT_LOG)]) + var quit_ends := events(records(QUIT_LOG), "end") + check(closed.code == 0 and quit_ends.size() == 1 and quit_ends[0].ended_by == "quit" + and quit_ends[0].game == "bay_area_blitz", + "A window close (quit_game(true)) ends the session as quit") + + var first := BoothLog.new(RELAUNCH_LOG) + first.route_changed("runner_game", "menu") + OS.delay_msec(5) # Real relaunches are seconds apart; launch ids have millisecond resolution. + var second := BoothLog.new(RELAUNCH_LOG) + second.route_changed("runner_game", "menu") + var relaunched := records(RELAUNCH_LOG) + var launches := events(relaunched, "launch") + check(relaunched.size() == 4 and launches.size() == 2 + and launches[0].launch != launches[1].launch, + "A relaunch appends to the same log under a new launch id") # A file where the log's folder should be: logging switches itself off with a warning. - var blocker := FileAccess.open("user://test_booth_blocker", FileAccess.WRITE) + var blocker := FileAccess.open(BLOCKER, FileAccess.WRITE) blocker.store_line("not a folder") blocker.close() - var broken := BoothLog.new("user://test_booth_blocker/sessions.jsonl") + var broken := BoothLog.new(BLOCKER + "/sessions.jsonl") broken.route_changed("heroes_vs_villains", "menu") broken.end("quit") check(broken.failed and broken.game == "", @@ -119,7 +208,7 @@ func run() -> void: check(router.session_log.game == "code_city_brawl", "The menu's Quit, ignored in booth mode, leaves the session open") router.set_booth(false) - # quit_game(true) would end this suite; it calls the same end("quit"). + # The child above covers quit_game(true); here the session just needs an end. router.session_log.end("quit") var entries := records(LOG) @@ -130,7 +219,7 @@ func run() -> void: == ["bay_area_blitz", "heroes_vs_villains", "code_city_brawl"], "Each game visit starts one session; menus and the hub start none") check(ends.size() == 3, "Every session ends") - if ends.size() == 3: + if ends.size() == 3 and starts.size() == 3: check(ends[0].ended_by == "menu" and int(ends[0].retries) == 1, "Re-entering a game is a retry; leaving for a menu ends the session") check(ends[1].ended_by == "idle", "Booth mode's idle return ends a session as idle") @@ -142,12 +231,14 @@ func run() -> void: and float(ends[i].duration_s) > 0.0 check(numbered, "Starts and ends pair by launch and session, with a positive duration") var extra := [] - for record in entries: - for key in record: - if key not in FIELDS: - extra.append(key) - check(extra.is_empty(), "The log holds only the documented fields (found %s)" % [extra]) + for path in [LOG, CHILD_LOG, QUIT_LOG, booth_path]: + for record in records(path): + for key in record: + if key not in FIELDS: + extra.append(key) + check(extra.is_empty(), "The logs hold only the documented fields (found %s)" % [extra]) + clean() await root.get_node("AudioService").settle() print("Booth session log failures: ", failures) quit(1 if failures else 0) diff --git a/hoppys-adventure-arcade/tests/support/session_log_quit.gd b/hoppys-adventure-arcade/tests/support/session_log_quit.gd new file mode 100644 index 00000000..aa5aa278 --- /dev/null +++ b/hoppys-adventure-arcade/tests/support/session_log_quit.gd @@ -0,0 +1,24 @@ +extends SceneTree +## Child process for tests/booth_session_log.gd, skipped as a suite in tools/tests/suites.toml. It +## opens a game with a session log, then quits through AppRouter.quit_game(true), as a window close +## does, so the parent can check the log's "quit" end without quitting itself. +## Usage: --script res://tests/support/session_log_quit.gd -- + +func _initialize() -> void: + call_deferred("run") + +func run() -> void: + var args := OS.get_cmdline_user_args() + var router := root.get_node("AppRouter") + if args.is_empty(): + push_error("session_log_quit: pass the log path after --") + quit(2) + return + router.start_session_log(args[0]) + router.go("bay_area_blitz") + for i in 300: + await process_frame + if not router.busy and current_scene != null \ + and current_scene.scene_file_path == router.ROUTES["bay_area_blitz"]: + break + router.quit_game(true) diff --git a/hoppys-adventure-arcade/tests/support/session_log_quit.gd.uid b/hoppys-adventure-arcade/tests/support/session_log_quit.gd.uid new file mode 100644 index 00000000..d79e7e7d --- /dev/null +++ b/hoppys-adventure-arcade/tests/support/session_log_quit.gd.uid @@ -0,0 +1 @@ +uid://bmuc2luyvs7d3 diff --git a/tools/booth/sessions_report.py b/tools/booth/sessions_report.py index f2a12532..b2ef375c 100644 --- a/tools/booth/sessions_report.py +++ b/tools/booth/sessions_report.py @@ -14,6 +14,7 @@ import argparse import csv import json +import math import statistics import sys from collections import Counter @@ -66,13 +67,15 @@ def read(paths: list[Path]) -> Log: if session is None: skipped.append(f"{where}: end without a start") continue - session.end = str(event["time"]) - session.duration_s = float(event["duration_s"]) - session.ended_by = str(event["ended_by"]) - session.retries = int(event.get("retries", 0)) + # Convert every field first, so a malformed end leaves the session as it was. + end, ended_by = str(event["time"]), str(event["ended_by"]) + duration_s, retries = float(event["duration_s"]), int(event.get("retries", 0)) + if not math.isfinite(duration_s) or duration_s < 0: + raise ValueError(f"duration_s must be a finite, non-negative number, not {duration_s}") + session.end, session.duration_s, session.ended_by, session.retries = end, duration_s, ended_by, retries else: skipped.append(f"{where}: unknown event {kind!r}") - except (json.JSONDecodeError, KeyError, TypeError, ValueError) as error: + except (json.JSONDecodeError, KeyError, TypeError, ValueError, OverflowError) as error: skipped.append(f"{where}: {type(error).__name__}: {error}") ordered = sorted(sessions.values(), key=lambda s: (s.start, s.source, s.launch, s.number)) return Log(ordered, launches, skipped) @@ -98,15 +101,19 @@ def summary(log: Log) -> str: f"Launches: {log.launches}", f"Sessions: {len(log.sessions)} ({len(finished)} finished, {unfinished} unfinished)", ] - if finished: - lines += ["", f"{'Game':<20} {'Sessions':>8} {'Median':>7} {'Mean':>7} {'P90':>7} {'Retries':>8}"] - for game in sorted({s.game for s in finished}): - durations = [s.duration_s for s in finished if s.game == game] - retries = sum(s.retries for s in finished if s.game == game) + if log.sessions: + # Sessions and Unfinished count every visit; lengths and retries come from finished ones. + lines += ["", f"{'Game':<20} {'Sessions':>8} {'Unfinished':>10} {'Median':>7} {'Mean':>7} {'P90':>7} {'Retries':>8}"] + for game in sorted({s.game for s in log.sessions}): + visits = [s for s in log.sessions if s.game == game] + durations = [s.duration_s for s in visits if s.duration_s is not None] + lengths = (clock(statistics.median(durations)), clock(statistics.fmean(durations)), clock(p90(durations))) \ + if durations else ("-", "-", "-") lines.append( - f"{game:<20} {len(durations):>8} {clock(statistics.median(durations)):>7}" - f" {clock(statistics.fmean(durations)):>7} {clock(p90(durations)):>7} {retries:>8}" + f"{game:<20} {len(visits):>8} {len(visits) - len(durations):>10} {lengths[0]:>7} {lengths[1]:>7}" + f" {lengths[2]:>7} {sum(s.retries for s in visits if s.duration_s is not None):>8}" ) + if finished: ended = Counter(s.ended_by for s in finished) lines += ["", "Ended by: " + ", ".join(f"{reason} {count}" for reason, count in sorted(ended.items()))] if log.sessions: @@ -136,6 +143,9 @@ def main(argv: list[str] | None = None) -> int: if missing: print("No such log: " + ", ".join(missing), file=sys.stderr) return 2 + if args.csv and any(args.csv.resolve() == path.resolve() for path in args.logs): + print(f"--csv {args.csv} is one of the logs; pick another file so the log isn't overwritten", file=sys.stderr) + return 2 log = read(args.logs) print(summary(log)) if args.csv: diff --git a/tools/booth/test_sessions_report.py b/tools/booth/test_sessions_report.py index 0f789305..164f74b5 100644 --- a/tools/booth/test_sessions_report.py +++ b/tools/booth/test_sessions_report.py @@ -48,12 +48,15 @@ def sample(self) -> Path: start(3, "runner_game", "2026-11-30T11:00:00"), end(3, "runner_game", "2026-11-30T11:01:00", 60.0, "quit"), start(4, "code_city_brawl", "2026-11-30T11:30:00"), + start(5, "code_city_brawl", "2026-11-30T11:45:00"), + end(5, "code_city_brawl", "2026-11-30T11:46:30", 90.0, "menu"), ]) def test_pairs_starts_and_ends_and_keeps_unfinished_sessions(self) -> None: log = sessions_report.read([self.sample()]) self.assertEqual(log.launches, 1) - self.assertEqual([s.game for s in log.sessions], ["heroes_vs_villains", "heroes_vs_villains", "runner_game", "code_city_brawl"]) + self.assertEqual([s.game for s in log.sessions], + ["heroes_vs_villains", "heroes_vs_villains", "runner_game", "code_city_brawl", "code_city_brawl"]) self.assertEqual(log.sessions[1].retries, 2) self.assertEqual(log.sessions[0].ended_by, "idle") self.assertIsNone(log.sessions[3].duration_s, "a start without an end is unfinished") @@ -61,12 +64,19 @@ def test_pairs_starts_and_ends_and_keeps_unfinished_sessions(self) -> None: def test_summary_reports_games_reasons_and_hours(self) -> None: text = sessions_report.summary(sessions_report.read([self.sample()])) - self.assertIn("Sessions: 4 (3 finished, 1 unfinished)", text) - hvv = next(line for line in text.splitlines() if line.startswith("heroes_vs_villains")) + self.assertIn("Sessions: 5 (4 finished, 1 unfinished)", text) + rows = {line.split()[0]: line.split() for line in text.splitlines() if line.split() and "_" in line.split()[0]} # Two sessions: 143.2 s and 180 s. Median and mean 161.6 s; P90 interpolates to 176.3 s. - self.assertEqual(hvv.split(), ["heroes_vs_villains", "2", "2:42", "2:42", "2:56", "2"]) - self.assertIn("Ended by: idle 1, menu 1, quit 1", text) - self.assertIn("Starts by hour: 10:00 2, 11:00 2", text) + self.assertEqual(rows["heroes_vs_villains"], ["heroes_vs_villains", "2", "0", "2:42", "2:42", "2:56", "2"]) + # One finished (90 s) and one unfinished visit: both count, the lengths come from the finished one. + self.assertEqual(rows["code_city_brawl"], ["code_city_brawl", "2", "1", "1:30", "1:30", "1:30", "0"]) + self.assertIn("Ended by: idle 1, menu 2, quit 1", text) + self.assertIn("Starts by hour: 10:00 2, 11:00 3", text) + + def test_a_game_with_only_unfinished_sessions_is_listed(self) -> None: + path = self.write("crash.jsonl", [start(1, "orbital_ops", "2026-11-30T10:00:00")]) + rows = [line.split() for line in sessions_report.summary(sessions_report.read([path])).splitlines()] + self.assertIn(["orbital_ops", "1", "1", "-", "-", "-", "0"], rows) def test_same_launch_in_two_files_stays_separate(self) -> None: first = self.write("a.jsonl", [start(1, "runner_game", "2026-11-30T10:00:00"), end(1, "runner_game", "2026-11-30T10:01:00", 60, "menu")]) @@ -89,13 +99,35 @@ def test_bad_lines_are_skipped_and_named(self) -> None: self.assertIn("bad.jsonl:3: end without a start", log.skipped[2]) self.assertIn("Skipped 4 line(s):", sessions_report.summary(log)) + def test_a_rejected_end_leaves_its_session_unfinished(self) -> None: + path = self.write("rejected.jsonl", [ + start(1, "runner_game", "2026-11-30T10:00:00"), + end(1, "runner_game", "2026-11-30T10:01:00", "soon", "menu"), # type: ignore[arg-type] + event("end", session=1, game="runner_game", time="2026-11-30T10:01:00", duration_s=float("nan"), ended_by="menu"), + event("end", session=1, game="runner_game", time="2026-11-30T10:01:00", duration_s=1e400, ended_by="menu"), + event("end", session=1, game="runner_game", time="2026-11-30T10:01:00", duration_s=-5, ended_by="menu"), + ]) + log = sessions_report.read([path]) + session = log.sessions[0] + self.assertEqual((session.end, session.duration_s, session.ended_by, session.retries), ("", None, "", 0)) + self.assertEqual(len(log.skipped), 4) + self.assertIn("Sessions: 1 (0 finished, 1 unfinished)", sessions_report.summary(log)) + + def test_csv_target_cannot_be_a_log(self) -> None: + log = self.sample() + original = log.read_bytes() + with redirect_stderr(io.StringIO()) as err: + self.assertEqual(sessions_report.main([str(log), "--csv", str(log.parent / "." / log.name)]), 2) + self.assertIn("is one of the logs", err.getvalue()) + self.assertEqual(log.read_bytes(), original) + def test_csv_has_one_row_per_session(self) -> None: target = Path(self.folder.name) / "out.csv" with redirect_stdout(io.StringIO()): self.assertEqual(sessions_report.main([str(self.sample()), "--csv", str(target)]), 0) with target.open(encoding="utf-8") as handle: rows = list(csv.DictReader(handle)) - self.assertEqual(len(rows), 4) + self.assertEqual(len(rows), 5) self.assertEqual(rows[0]["duration_s"], "143.2") self.assertEqual(rows[3]["ended_by"], "unfinished") self.assertEqual(rows[3]["duration_s"], "") diff --git a/tools/tests/suites.toml b/tools/tests/suites.toml index 5f3f47e9..ec9681c7 100644 --- a/tools/tests/suites.toml +++ b/tools/tests/suites.toml @@ -13,6 +13,7 @@ menu_smoke = "Drives the menu with pointer hover, which a headless run never pro menu_hoppy_smoke = "Drives the menu with pointer hover, which a headless run never produces." capture_code_city_bosses = "Writes the Code City boss stills into docs/previews/; a graphical run only." exit_leak = "Needs a --scenario per process; CI runs every scenario through tools/checks/exit_leak.py." +"support/session_log_quit" = "Child process for booth_session_log: it quits through AppRouter on purpose." # Suites with wall-clock budgets, or that occupy every core, run alone after the parallel # batch, so CPU contention from other suites can't fail them (or them, the others). From aa04e7059bb0d79fd0d5778809a7d572c0394e16 Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 16:36:31 -0700 Subject: [PATCH 3/4] fix(booth): give each run its own session log file and validate end events [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Addresses CodeRabbit review 5541172249 on #74: - Two runs never share a file now. The log is a folder (user://booth by default; --session-log=) holding sessions--.jsonl per run, so concurrent copies can't truncate or interleave each other, and a line cut off by a crash can't merge with the next run's first line. The game prints its file's path; the report reads whole folders. - An end event must name the session's game and carry non-empty string time and ended_by; otherwise it is skipped and the session stays open. - --csv is compared with each input by file identity (samefile), so a hardlink to a log is refused too. --- docs/builds.md | 8 +- hoppys-adventure-arcade/app/app_router.gd | 19 ++--- hoppys-adventure-arcade/app/booth_log.gd | 30 ++++--- .../tests/booth_session_log.gd | 81 ++++++++++--------- .../tests/support/session_log_quit.gd | 4 +- tools/booth/sessions_report.py | 51 ++++++++---- tools/booth/test_sessions_report.py | 28 ++++++- 7 files changed, 142 insertions(+), 79 deletions(-) diff --git a/docs/builds.md b/docs/builds.md index b8bfdfed..9726d5f8 100644 --- a/docs/builds.md +++ b/docs/builds.md @@ -36,13 +36,13 @@ open -a "Hoppy’s Adventure Arcade.app" --args -- --booth --route=heroes_vs_vil - **Idle reset.** After 90 seconds with no keyboard, mouse, touch or controller input, any game returns to the hub, whose rotating previews act as the attract screen. - **No quitting from the menu.** The menu's **Quit Game** does nothing in booth mode; staff close the window (Cmd+Q, Alt+F4). - **Launch route.** `--route=` opens a route at launch (`heroes_vs_villains`, `code_city_brawl`, `bay_area_blitz`, `orbital_ops`, `enchanted_repo`, `runner`, `platformer`, `beatem_up`, `hub`), with or without `--booth`. An unknown name logs an error and opens the hub. -- **Session log.** Booth mode appends each game session's start and end to `user://booth/sessions.jsonl`. Each entry records the game, the local start and end times, the duration, how the session ended (`menu`, `idle` or `quit`) and how many times the player retried. It records nothing about players and never uses the network. A start with no end means the game stopped without quitting: a crash, a power cut or a forced kill. The game prints the log's full path at startup. `--session-log=` writes to another file and works without `--booth`, for playtests. +- **Session log.** Booth mode records each game session's start and end in `user://booth/`, one file per run of the game (`sessions--.jsonl`). Each entry records the game, the local start and end times, the duration, how the session ended (`menu`, `idle` or `quit`) and how many times the player retried. It records nothing about players and never uses the network. A start with no end means the game stopped without quitting: a crash, a power cut or a forced kill. The game prints its file's full path at startup. `--session-log=` writes to another folder and works without `--booth`, for playtests. -`user://` is `~/Library/Application Support/Godot/app_userdata/Hoppy’s Adventure Arcade/` on macOS, `%APPDATA%\Godot\app_userdata\Hoppy’s Adventure Arcade\` on Windows and `~/.local/share/godot/app_userdata/Hoppy’s Adventure Arcade/` on Linux. To summarize the logs, copy them off each machine and run: +`user://` is `~/Library/Application Support/Godot/app_userdata/Hoppy’s Adventure Arcade/` on macOS, `%APPDATA%\Godot\app_userdata\Hoppy’s Adventure Arcade\` on Windows and `~/.local/share/godot/app_userdata/Hoppy’s Adventure Arcade/` on Linux. To summarize the logs, copy each machine's `booth` folder and run: ```sh -python3 tools/booth/sessions_report.py sessions.jsonl # sessions per game, durations, end reasons, starts by hour -python3 tools/booth/sessions_report.py booth-a.jsonl booth-b.jsonl --csv sessions.csv # combine machines; one CSV row per session +python3 tools/booth/sessions_report.py booth/ # sessions per game, durations, end reasons, starts by hour +python3 tools/booth/sessions_report.py booth-a/ booth-b/ --csv sessions.csv # combine machines; one CSV row per session ``` ## Build locally diff --git a/hoppys-adventure-arcade/app/app_router.gd b/hoppys-adventure-arcade/app/app_router.gd index 446ecf15..85ef6a3d 100644 --- a/hoppys-adventure-arcade/app/app_router.gd +++ b/hoppys-adventure-arcade/app/app_router.gd @@ -24,11 +24,12 @@ const BOOTH_FLAG := "--booth" const ROUTE_PREFIX := "--route=" const IDLE_SECONDS := 90.0 const STICK_DEADZONE := 0.4 -## Booth analytics (app/booth_log.gd): with --booth, each game session's start and end are appended -## to SESSION_LOG_DEFAULT. `--session-log=` (absolute or user://) picks another file and also -## works without --booth, for playtests. Nothing is logged unless one of them is passed. +## Booth analytics (app/booth_log.gd): with --booth, each game session's start and end go to a file +## for this run in the SESSION_LOG_DEFAULT folder. `--session-log=` (absolute or user://) +## picks another folder and also works without --booth, for playtests. Nothing is logged unless one +## of them is passed. const SESSION_LOG_PREFIX := "--session-log=" -const SESSION_LOG_DEFAULT := "user://booth/sessions.jsonl" +const SESSION_LOG_DEFAULT := "user://booth" var busy := false var veil: ColorRect var booth := false @@ -112,17 +113,17 @@ static func launch_route(args: PackedStringArray) -> String: push_error("Unknown --route %s; expected one of %s" % [route, ", ".join(ROUTES.keys())]) return "" -## The session log these arguments ask for: `--session-log=`, else the default file in booth -## mode, else "" (no logging). +## The session-log folder these arguments ask for: `--session-log=`, else the default in +## booth mode, else "" (no logging). static func session_log_path(args: PackedStringArray, booth_mode: bool) -> String: for arg in args: if arg.begins_with(SESSION_LOG_PREFIX) and arg.length() > SESSION_LOG_PREFIX.length(): return arg.trim_prefix(SESSION_LOG_PREFIX) return SESSION_LOG_DEFAULT if booth_mode else "" -func start_session_log(path: String) -> void: - session_log = BoothLog.new(path) - print("AppRouter: session log at %s" % ProjectSettings.globalize_path(path)) +func start_session_log(folder: String) -> void: + session_log = BoothLog.new(folder) + print("AppRouter: session log at %s" % ProjectSettings.globalize_path(session_log.path)) func _launch(route: String) -> void: await go(route) diff --git a/hoppys-adventure-arcade/app/booth_log.gd b/hoppys-adventure-arcade/app/booth_log.gd index 73a44906..83bb799e 100644 --- a/hoppys-adventure-arcade/app/booth_log.gd +++ b/hoppys-adventure-arcade/app/booth_log.gd @@ -1,7 +1,9 @@ extends RefCounted -## Local booth analytics: an append-only JSON Lines file, one line per event. Nothing leaves the -## machine and nothing identifies a player. The only fields are the game, local times, the session -## length and how it ended: +## Local booth analytics: JSON Lines, one line per event, in a folder that holds one file per run of +## the game (sessions--.jsonl). A watchdog relaunch or a second +## copy started by mistake never writes to another run's file. Nothing leaves the machine and +## nothing identifies a player. The only fields are the game, local times, the session length and +## how it ended: ## {"event":"launch","launch":"2026-11-30T09:58:12.345","time":"2026-11-30T09:58:12", ## "version":"0.1.0"} ## {"event":"start","launch":"2026-11-30T09:58:12.345","session":1,"game":"heroes_vs_villains", @@ -12,14 +14,15 @@ extends RefCounted ## level's Retry) counts as a retry within it. `ended_by` is "menu" (the player left through the ## game's own menu), "idle" (booth mode's idle return) or "quit". A start with no end means the game ## stopped without quitting: a crash, a power cut or a forced kill. -## tools/booth/sessions_report.py summarizes the file. +## tools/booth/sessions_report.py summarizes a folder of these files. ## Routes that are games. The hub and mode menus end a session but never start one. const GAMES: Array[String] = ["heroes_vs_villains", "code_city_brawl", "bay_area_blitz", "orbital_ops", "enchanted_repo", "runner_game"] +## This run's file. var path := "" -## When this run of the game started, to the millisecond, so two runs logging to one file (a -## watchdog relaunch, or a second copy) stay apart. With `session` it identifies a session. +## When this run of the game started, to the millisecond. With `session` it identifies a session +## when logs from several runs are read together. var launch := "" ## The game being played, or "" between sessions. var game := "" @@ -29,14 +32,17 @@ var started_msec := 0 ## Set after the first failed write: the game keeps running, unlogged, rather than retrying. var failed := false -func _init(log_path: String) -> void: - path = log_path +## Start this run's file in `folder` (absolute or user://), creating the folder if needed. +func _init(folder: String) -> void: var now := Time.get_unix_time_from_system() var local := int(now) + int(Time.get_time_zone_from_system().bias) * 60 - launch = "%s.%03d" % [Time.get_datetime_string_from_unix_time(local), int(fmod(now, 1.0) * 1000.0)] - var directory := path.get_base_dir() - if directory != "" and not DirAccess.dir_exists_absolute(directory): - DirAccess.make_dir_recursive_absolute(directory) + var stamp := Time.get_datetime_string_from_unix_time(local) + var millis := int(fmod(now, 1.0) * 1000.0) + launch = "%s.%03d" % [stamp, millis] + path = folder.path_join("sessions-%s-%03d-%d.jsonl" % [stamp.replace(":", "-"), millis, + OS.get_process_id()]) + if not DirAccess.dir_exists_absolute(folder): + DirAccess.make_dir_recursive_absolute(folder) _write({"event": "launch", "time": launch.get_slice(".", 0), "version": str(ProjectSettings.get_setting("application/config/version", ""))}) diff --git a/hoppys-adventure-arcade/tests/booth_session_log.gd b/hoppys-adventure-arcade/tests/booth_session_log.gd index 728b9cac..86836f96 100644 --- a/hoppys-adventure-arcade/tests/booth_session_log.gd +++ b/hoppys-adventure-arcade/tests/booth_session_log.gd @@ -6,10 +6,10 @@ extends SceneTree ## quit_game() are covered. Child launches get a throwaway user-data root, so a standalone run never ## reads or writes a real booth log. Run headless with --script res://tests/booth_session_log.gd. const BoothLog := preload("res://app/booth_log.gd") -const LOG := "user://test_booth_sessions.jsonl" -const CHILD_LOG := "user://test_booth_child_sessions.jsonl" -const QUIT_LOG := "user://test_booth_quit_sessions.jsonl" -const RELAUNCH_LOG := "user://test_booth_relaunch_sessions.jsonl" +const LOG_DIR := "user://test_booth_sessions" +const CHILD_DIR := "user://test_booth_child_sessions" +const QUIT_DIR := "user://test_booth_quit_sessions" +const RELAUNCH_DIR := "user://test_booth_relaunch_sessions" const BLOCKER := "user://test_booth_blocker" const CHILD_HOME := "user://test_booth_home" const ISOLATED := ["HOME", "XDG_DATA_HOME", "XDG_CONFIG_HOME", "APPDATA", "LOCALAPPDATA", @@ -97,15 +97,17 @@ func records(path: String) -> Array[Dictionary]: func events(entries: Array[Dictionary], kind: String) -> Array[Dictionary]: return entries.filter(func(record: Dictionary) -> bool: return record.event == kind) -func find_file(directory: String, file_name: String) -> bool: +## True when a file whose name starts with `prefix` exists anywhere under `directory`. +func find_file(directory: String, prefix: String) -> bool: var dir := DirAccess.open(directory) if dir == null: return false dir.include_hidden = true - if file_name in dir.get_files(): - return true + for file_name in dir.get_files(): + if file_name.begins_with(prefix): + return true for child in dir.get_directories(): - if find_file(directory.path_join(child), file_name): + if find_file(directory.path_join(child), prefix): return true return false @@ -121,10 +123,10 @@ func remove_tree(directory: String) -> void: DirAccess.remove_absolute(directory) func clean() -> void: - for path in [LOG, CHILD_LOG, QUIT_LOG, RELAUNCH_LOG, BLOCKER]: - if FileAccess.file_exists(path): - DirAccess.remove_absolute(path) - remove_tree(ProjectSettings.globalize_path(CHILD_HOME)) + if FileAccess.file_exists(BLOCKER): + DirAccess.remove_absolute(BLOCKER) + for folder in [LOG_DIR, CHILD_DIR, QUIT_DIR, RELAUNCH_DIR, CHILD_HOME]: + remove_tree(ProjectSettings.globalize_path(folder)) func run() -> void: router = root.get_node("AppRouter") @@ -133,24 +135,25 @@ func run() -> void: check(router.session_log == null, "No session log without --booth or --session-log") check(router.session_log_path(PackedStringArray(), false) == "", "No flags means no session log") - check(router.session_log_path(PackedStringArray(["--booth"]), true) == router.SESSION_LOG_DEFAULT, - "Booth mode logs to the default file") - check(router.session_log_path(PackedStringArray(["--session-log=user://playtest.jsonl"]), false) - == "user://playtest.jsonl", "--session-log picks a file, with or without --booth") + check(router.session_log_path(PackedStringArray(["--booth"]), true) == "user://booth", + "Booth mode logs to the booth folder") + check(router.session_log_path(PackedStringArray(["--session-log=user://playtest"]), false) + == "user://playtest", "--session-log picks a folder, with or without --booth") check(router.session_log_path(PackedStringArray(["--session-log="]), false) == "", "An empty --session-log is ignored") var plain := launch(["--route=bay_area_blitz"]) check(plain.code == 0, "A plain launch exits cleanly") check(logged_path(plain.log) == "" - and not find_file(ProjectSettings.globalize_path(CHILD_HOME), "sessions.jsonl"), + and not find_file(ProjectSettings.globalize_path(CHILD_HOME), "sessions-"), "A launch without --booth writes no session log") var kiosk := launch(["--booth", "--route=heroes_vs_villains"]) var booth_path := logged_path(kiosk.log) check(kiosk.code == 0, "A booth launch exits cleanly") check(booth_path.begins_with(ProjectSettings.globalize_path(CHILD_HOME)) - and booth_path.ends_with("booth/sessions.jsonl"), - "--booth logs to booth/sessions.jsonl in the user data (%s)" % booth_path) + and booth_path.get_base_dir().ends_with("/booth") + and booth_path.get_file().begins_with("sessions-") and booth_path.ends_with(".jsonl"), + "--booth logs this run to booth/sessions-