diff --git a/TODO.md b/TODO.md index 6e10147..6412b53 100644 --- a/TODO.md +++ b/TODO.md @@ -118,6 +118,20 @@ the finish is supposed to leave behind. any of them is worth the ~18% of client EDT time they cost (PERFORMANCE.md); that is a product call, not an open question about the mechanism. +- [x] **The result no longer waits for the container to stop.** + `container/watch/results.sh` sends the result and the end-of-game images + when the host writes the game-over marker, which is a minute before + finalize used to see them and in a moment when nothing else is happening. + `container/lib/collect.sh` holds both collectors and a `state/sent/` + marker per artifact, so `exit/finalize.sh` runs the same two and re-sends + only what did not land. Everything that is *not* complete at victory - + the latency table, the client's logs, the profiles - still goes at exit, + because that is when the JVMs stop writing them. +- [ ] **The rest of the artifacts still ride the shutdown.** That window is a + SIGTERM and a bounded wait on Fargate, and a diagnostic that does not + finish inside it is gone. The logs could be shipped in rolling chunks and + the stats table could be summarised at game-over from the log so far; + neither is worth doing until one has actually been lost. - [ ] **Multi-human matches** are expressible in the manifest and handled by `MatchHost`, and every human seat now renders its own Suramadu app at `/` — cloned at render time from the template app with only diff --git a/container/entrypoint.sh b/container/entrypoint.sh index 604e804..c3a0c2b 100755 --- a/container/entrypoint.sh +++ b/container/entrypoint.sh @@ -38,6 +38,7 @@ WS_PID="" HOST_PID="" WATCHER_PID="" UPLOADER_PID="" +RESULTS_PID="" IDLE_PID="" FINALIZED=0 @@ -144,7 +145,7 @@ shutdown() { log "signal received; shutting down" if profiling; then flush_profiles; fi finalize_once - for pid in "$IDLE_PID" "$UPLOADER_PID" "$WATCHER_PID" "$HOST_PID" "$WS_PID"; do + for pid in "$IDLE_PID" "$RESULTS_PID" "$UPLOADER_PID" "$WATCHER_PID" "$HOST_PID" "$WS_PID"; do [ -n "$pid" ] && kill -TERM "$pid" 2>/dev/null || true done # Give the JVMs a moment to close their sockets before the container dies. @@ -315,6 +316,12 @@ else log "observer disabled by manifest; no turn reports will be uploaded" fi +# --- the result, sent when it exists rather than when we stop ----------------- +# Outside the observer block on purpose: a match with no observer still has a +# result and end-of-game images, and those belong to its players either way. +"$ARENA_HOME/container/watch/results.sh" & +RESULTS_PID=$! + # --- readiness -------------------------------------------------------------- # Both ports, not just Suramadu's. headquarters called a match ready as soon as # the web server answered, which - with the host started after it - was always @@ -366,7 +373,7 @@ if profiling; then flush_profiles; fi finalize_once -for pid in "$UPLOADER_PID" "$WATCHER_PID" "$WS_PID"; do +for pid in "$RESULTS_PID" "$UPLOADER_PID" "$WATCHER_PID" "$WS_PID"; do [ -n "$pid" ] && kill -TERM "$pid" 2>/dev/null || true done diff --git a/container/exit/finalize.sh b/container/exit/finalize.sh index 5c71201..6f88349 100755 --- a/container/exit/finalize.sh +++ b/container/exit/finalize.sh @@ -13,6 +13,8 @@ set -euo pipefail ARENA_LOG_TAG=exit/finalize # shellcheck source=../lib/common.sh . "${ARENA_HOME:-/opt/arena}/container/lib/common.sh" +# shellcheck source=../lib/collect.sh +. "${ARENA_HOME:-/opt/arena}/container/lib/collect.sh" MM_HOME="${MM_HOME:-$ARENA_HOME/megamek}" SENT="$ARENA_SPOOL/sent" @@ -32,41 +34,21 @@ for f in "$ARENA_SPOOL"/*.txt "$FAILED"/*.txt; do done shopt -u nullglob -# --- 2. the result ------------------------------------------------------------ +# --- 2. the result, and 3. the end-of-game images ----------------------------- +# Both are collected by container/lib/collect.sh, and watch/results.sh has +# normally sent them already - at victory, rather than in the container's last +# seconds. What is left here is the second pass: anything that failed then, and +# everything from a match that never reached victory at all. +# +# The collectors skip what has already been accepted, so this costs nothing +# when the early pass did its job, and says what it sent when it did not. +LOGDIR="${ARENA_MM_LOGDIR:-$MM_HOME/logs}" if [ -f "$ARENA_STATE/result.json" ]; then - # Attribution travels with the result: headquarters needs the DID-to-slot map - # to publish anything to a player's PDS, and it is the one thing arena knows - # that the result itself does not carry. - if [ -f "$ARENA_STATE/identity.json" ]; then - jq -s '.[0] * {identity: .[1]}' "$ARENA_STATE/result.json" "$ARENA_STATE/identity.json" \ - > "$ARENA_STATE/result-final.json" 2>/dev/null \ - || cp "$ARENA_STATE/result.json" "$ARENA_STATE/result-final.json" - else - cp "$ARENA_STATE/result.json" "$ARENA_STATE/result-final.json" - fi - upload "$ARENA_STATE/result-final.json" result || warn "result upload failed" + collect_result || true else log "no result.json - the match did not reach victory" fi - -# --- 3. end-of-game images ---------------------------------------------------- -# MegaMek writes these itself, per round, from the client. See the -# GameSummary* preferences in megamek/clientsettings.xml.template. -LOGDIR="${ARENA_MM_LOGDIR:-$MM_HOME/logs}" -shot_count=0 -for kind in board minimap; do - dir="$LOGDIR/gameSummaries/$kind" - [ -d "$dir" ] || continue - # One subdirectory per game UUID; there is exactly one game per container, but - # globbing is still simpler than guessing the UUID. - while IFS= read -r img; do - [ -f "$img" ] || continue - # Flatten into a name that stays unique and says what it is. - dest="$ARENA_STATE/$kind-$(basename "$img")" - cp "$img" "$dest" - upload "$dest" screenshots && shot_count=$((shot_count + 1)) || true - done < <(find "$dir" -type f \( -name '*.png' -o -name '*.gif' \) 2>/dev/null | sort) -done +shot_count="$(ARENA_MM_LOGDIR="$LOGDIR" collect_images)" log "uploaded $shot_count image(s)" # --- 4. the per-layer latency table ------------------------------------------- diff --git a/container/lib/collect.sh b/container/lib/collect.sh new file mode 100644 index 0000000..295e9d1 --- /dev/null +++ b/container/lib/collect.sh @@ -0,0 +1,100 @@ +#!/usr/bin/env bash +# What a finished match leaves behind, and how it is sent. +# Sourced, never executed. Requires lib/common.sh to be sourced first. +# +# . "$ARENA_HOME/container/lib/collect.sh" +# +# Two callers run these, in this order: +# +# watch/results.sh as soon as the game is decided, while the container is +# still up and nothing is in a hurry +# exit/finalize.sh on the way out, for whatever the first pass could not +# send and for everything that is only complete at exit +# +# Which is why every function here is idempotent. An artifact that has been +# accepted leaves a marker in state/sent/, and a later pass skips it - so +# finalize can call the same collectors unconditionally and re-send only what +# actually failed. Markers are per basename, and every name these produce is +# already unique within a match. +# +# The alternative - collecting only at exit - put the result, the images and +# the summary GIF in the same few seconds as the container's shutdown, which +# is the least reliable moment in a match's life: on Fargate it is a SIGTERM +# and a bounded wait, and anything that does not finish inside it is gone with +# the writable layer. The result in particular is the one artifact a player is +# owed, and it is complete a minute before that. + +SENT_DIR="${SENT_DIR:-$ARENA_STATE/sent}" + +# upload_once +# +# Non-zero when the upload was attempted and did not land, so a caller can +# count failures; zero for "already sent" as well as for a fresh success. +upload_once() { + local file="$1" key="$2" marker + marker="$SENT_DIR/$(basename "$file")" + [ -f "$marker" ] && return 0 + mkdir -p "$SENT_DIR" + upload "$file" "$key" || return 1 + : > "$marker" +} + +# The result, with attribution attached. +# +# Written by MatchHost the moment the game is decided, so this is complete +# well before the container stops. Absent means the match never reached +# victory, which is not a failure here - a cancelled or timed-out match still +# had turn reports. +# +# collect_result -> non-zero only when there was a result and it did not land +collect_result() { + [ -f "$ARENA_STATE/result.json" ] || return 0 + + # headquarters needs the DID-to-slot map to publish anything to a player's + # PDS, and it is the one thing arena knows that the result itself does not + # carry. + if [ -f "$ARENA_STATE/identity.json" ]; then + jq -s '.[0] * {identity: .[1]}' "$ARENA_STATE/result.json" "$ARENA_STATE/identity.json" \ + > "$ARENA_STATE/result-final.json" 2>/dev/null \ + || cp "$ARENA_STATE/result.json" "$ARENA_STATE/result-final.json" + else + cp "$ARENA_STATE/result.json" "$ARENA_STATE/result-final.json" + fi + + upload_once "$ARENA_STATE/result-final.json" result || { + warn "result upload failed" + return 1 + } +} + +# The end-of-game images MegaMek writes itself, per round, from the client. +# See the GameSummary* preferences in megamek/clientsettings.xml.template. +# +# Prints how many landed. The board views are written as the game goes, and +# the minimap GIF is closed when the client sees the victory phase, so a pass +# at game-over finds the same set the exit pass would - a beat later, in the +# case of the GIF, which is why the early caller settles first and why +# whatever it misses is picked up on the way out. +collect_images() { + local logdir="${ARENA_MM_LOGDIR:-${MM_HOME:-$ARENA_HOME/megamek}/logs}" + local count=0 kind dir img dest + + shopt -s nullglob + for kind in board minimap; do + dir="$logdir/gameSummaries/$kind" + [ -d "$dir" ] || continue + # One subdirectory per game UUID; there is exactly one game per container, + # but globbing is still simpler than guessing the UUID. + while IFS= read -r img; do + [ -f "$img" ] || continue + # Flatten into a name that stays unique and says what it is. + dest="$ARENA_STATE/$kind-$(basename "$img")" + [ -f "$SENT_DIR/$(basename "$dest")" ] && continue + cp "$img" "$dest" + upload_once "$dest" screenshots && count=$((count + 1)) || true + done < <(find "$dir" -type f \( -name '*.png' -o -name '*.gif' \) 2>/dev/null | sort) + done + shopt -u nullglob + + printf '%s' "$count" +} diff --git a/container/watch/results.sh b/container/watch/results.sh new file mode 100755 index 0000000..0f84055 --- /dev/null +++ b/container/watch/results.sh @@ -0,0 +1,53 @@ +#!/usr/bin/env bash +# Send the result and the end-of-game images as soon as the game is decided, +# instead of waiting for the container to stop. +# +# The host writes state/result.json and touches state/game-over the moment a +# match reaches victory, and then lingers - a minute in which nothing else is +# happening and the network is idle. Everything these artifacts need is already +# on disk by then, so exit/finalize.sh was collecting them a minute late, in the +# worst moment of a match's life: on Fargate the container's last seconds are a +# SIGTERM and a bounded wait, and an upload that does not finish inside it is +# gone with the writable layer. +# +# This does not replace finalize. It goes first, marks what landed, and leaves +# the rest - the latency table, the client's logs, the profiles - to the exit +# pass, because those are only complete when the JVMs stop. Anything this pass +# fails to send is retried there. +# +# Deliberately not part of watch/turn-reports.sh, which is the other thing +# watching for game-over: that one is gated on the manifest's observer, and a +# match with no observer still has a result its players are owed. +set -euo pipefail +# shellcheck disable=SC2034 # read by common.sh's log helpers +ARENA_LOG_TAG=watch/results +# shellcheck source=../lib/common.sh +. "${ARENA_HOME:-/opt/arena}/container/lib/common.sh" +# shellcheck source=../lib/collect.sh +. "${ARENA_HOME:-/opt/arena}/container/lib/collect.sh" + +require_cmd curl jq find + +POLL="${ARENA_RESULTS_POLL:-2}" +# The GIF is closed by the client's writer thread when it sees the victory +# phase, which is the same instant the host writes the marker. A short settle +# keeps the common case to one upload rather than one here and a second at +# exit; missing it costs nothing but that. +SETTLE="${ARENA_RESULTS_SETTLE:-5}" + +over() { + [ -f "$ARENA_STATE/game-over" ] && return 0 + [ "$(head -n1 "$ARENA_STATE/host.status" 2>/dev/null || true)" = "game-over" ] +} + +log "watching for the end of the game" +while ! over; do + sleep "$POLL" +done + +sleep "$SETTLE" +log "the game is decided; collecting what is already complete" + +collect_result || true +shots="$(collect_images)" +log "sent $shots image(s) ahead of the exit pass" diff --git a/tests/shell/test-results-watch.sh b/tests/shell/test-results-watch.sh new file mode 100755 index 0000000..555e649 --- /dev/null +++ b/tests/shell/test-results-watch.sh @@ -0,0 +1,94 @@ +#!/usr/bin/env bash +# watch/results.sh exists to move the result and the end-of-game images out of +# the container's last seconds and into the minute after victory, when nothing +# else is happening. Three things have to hold for that to be worth having: it +# waits rather than firing early, it sends both kinds when the game is decided, +# and it does not re-send what a previous pass already got through. +# +# The manifest here carries no upload targets, the same as the dev manifest +# scripts/run.sh writes, so `upload` reports what it would have sent and returns +# non-zero. That is what the assertions read: the file was found and offered, no +# network involved. +set -uo pipefail + +ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd)" +TMP="$(mktemp -d)" +trap 'rm -rf "$TMP"' EXIT + +fail=0 +check() { # + if "${@:2}"; then echo "ok $1"; else echo "FAIL $1"; fail=1; fi +} + +# The image collects container/ under ARENA_HOME; the watcher sources +# lib/common.sh and lib/collect.sh from there. +mkdir -p "$TMP/home" "$TMP/run/state" +ln -s "$ROOT/container" "$TMP/home/container" +echo '{"matchId":"test-match"}' > "$TMP/run/manifest.json" +STATE="$TMP/run/state" + +# What the host writes at victory, and what the client leaves in its log dir. +echo '{"round": 7, "players": []}' > "$STATE/result.json" +echo '{"matchId": "test-match", "players": []}' > "$STATE/identity.json" +LOGS="$TMP/logs" +mkdir -p "$LOGS/gameSummaries/board/game-uuid" "$LOGS/gameSummaries/minimap/game-uuid" +touch "$LOGS/gameSummaries/board/game-uuid/round_1_9_TARGETING.png" \ + "$LOGS/gameSummaries/minimap/game-uuid/round_1_9_TARGETING.png" \ + "$LOGS/gameSummaries/minimap/game-uuid/game-uuid.gif" + +run_watcher() { # -> prints the watcher's output, having touched game-over + local out + out="$TMP/out.txt" + : > "$out" + ARENA_HOME="$TMP/home" ARENA_RUN="$TMP/run" ARENA_MM_LOGDIR="$LOGS" \ + ARENA_RESULTS_POLL=0.2 ARENA_RESULTS_SETTLE=0 \ + bash "$ROOT/container/watch/results.sh" > "$out" 2>&1 & + local pid=$! + + # It must still be waiting a beat later: firing before the game is decided + # would upload a half-written result, and the whole point is that this runs + # while there is time to spare. + # Written to a file, not a variable: this function runs in a command + # substitution, so a variable set here dies with the subshell. + sleep 1 + if kill -0 "$pid" 2>/dev/null; then echo yes > "$TMP/waiting"; else echo no > "$TMP/waiting"; fi + + : > "$STATE/game-over" + for _ in $(seq 50); do + kill -0 "$pid" 2>/dev/null || break + sleep 0.2 + done + kill -TERM "$pid" 2>/dev/null + wait "$pid" 2>/dev/null + cat "$out" +} + +# --- a decided game ----------------------------------------------------------- +out="$(run_watcher)" + +check "waits for the game to be decided" test "$(cat "$TMP/waiting")" = yes +check "offers the result" grep -q "result.*result-final.json" <<<"$out" +check "attaches identity to the result" bash -c \ + "grep -q '\"identity\"' \"\$1/result-final.json\"" _ "$STATE" +check "offers the board summary" grep -q "board-round_1_9_TARGETING.png" <<<"$out" +check "offers the minimap summary" grep -q "minimap-round_1_9_TARGETING.png" <<<"$out" +check "offers the summary GIF" grep -q "minimap-game-uuid.gif" <<<"$out" +check "counts what it sent" grep -q "image(s) ahead of the exit pass" <<<"$out" + +# --- what a previous pass already got through --------------------------------- +# The marker file is the whole of the contract between this and finalize: an +# artifact that has been accepted is never sent twice, however many passes run. +rm -f "$STATE/game-over" +mkdir -p "$STATE/sent" +: > "$STATE/sent/result-final.json" +: > "$STATE/sent/minimap-game-uuid.gif" + +out="$(run_watcher)" + +check "a sent result is not offered again" bash -c \ + "! grep -q 'result-final.json' <<<\"\$1\"" _ "$out" +check "a sent GIF is not offered again" bash -c \ + "! grep -q 'minimap-game-uuid.gif' <<<\"\$1\"" _ "$out" +check "an unsent image still is" grep -q "board-round_1_9_TARGETING.png" <<<"$out" + +exit "$fail"