#!/usr/bin/env bash # Collect everything worth keeping from a finished match and upload it, then let # the container die. # # Runs from the entrypoint's trap, so it executes both on a clean victory and on # a signalled shutdown. A cancelled or timed-out match still produced turn # reports, and those should still be uploaded. # # Best-effort throughout. Every step logs and continues; the exit status reflects # the match, not the uploads. set -euo pipefail # shellcheck disable=SC2034 # read by common.sh's log helpers 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}" if [ ! -f "$MANIFEST" ]; then log "no manifest; nothing to upload" exit 0 fi # --- 1. the result, and 2. 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. # # There is a result for a match that never reached victory too: MatchHost keeps # a provisional one on disk from the first tick and replaces it at victory, so # what is here says either "victory" or "no-victory-at-exit" rather than being # absent. Absent now means the host died before it wrote anything - a scenario # that would not load, a JVM that would not start - which is worth saying in a # different sentence. LOGDIR="${ARENA_MM_LOGDIR:-$MM_HOME/logs}" if [ -f "$ARENA_STATE/result.json" ]; then log "the match ended: $(result_ending) (round $(result_round))" collect_result || true else log "no result.json - the match host wrote none" fi shot_count="$(ARENA_MM_LOGDIR="$LOGDIR" collect_images)" log "uploaded $shot_count image(s)" ARENA_MM_LOGDIR="$LOGDIR" collect_raw_record || true # --- 3. the per-layer latency table ------------------------------------------- # Suramadu logs one TRACE line per metric per session tick, which # config/log4j2-server.xml routes to stdout as # "HH:mm:ss.SSS stats,,,". Those lines are a # latency decomposition - server render, client render, network, ping - and # nobody has ever reduced them per match. Doing it here costs one sort and # puts the table in the container log next to the GC lines. # # Instances are not separated: a container plays one match, and a reconnect # makes a second instance whose numbers belong to the same match anyway. SURAMADU_LOG="$ARENA_RUN/suramadu.log" STATS="$ARENA_STATE/stats-summary.txt" if [ -f "$SURAMADU_LOG" ]; then { printf '%-28s %7s %12s %12s %12s %12s\n' metric n mean p50 p90 max awk -F, '$1 ~ / stats$/ && NF >= 4 && $4 ~ /^-?[0-9.]+([eE][-+]?[0-9]+)?$/ \ { print $3, $4 }' "$SURAMADU_LOG" \ | sort -k1,1 -k2,2g \ | awk ' # Nearest rank over an already sorted group. Interpolating between # neighbours would be false precision on a sample this coarse. function pct(p, i) { i = int(n * p + 0.999999); return v[i < 1 ? 1 : i] } function flush() { if (n == 0) return printf "%-28s %7d %12.1f %12.1f %12.1f %12.1f\n", m, n, sum / n, pct(0.5), pct(0.9), v[n] } $1 != m { flush(); m = $1; n = 0; sum = 0 } { v[++n] = $2; sum += $2 } END { flush() }' } > "$STATS" if [ "$(wc -l < "$STATS")" -gt 1 ]; then while IFS= read -r line; do log "$line"; done < "$STATS" upload "$STATS" diagnostics || true else log "no stats lines in the Suramadu log" rm -f "$STATS" fi fi # --- 4. profiles -------------------------------------------------------------- # Written only when the task set ARENA_PROFILE. Collapsed stacks, one line per # unique stack: feed them to flamegraph.pl, or diff two runs directly. # entrypoint.sh stops the JVMs before calling us on a profiled run, because the # agent dumps on the way out and an empty file is the failure mode here. shopt -s nullglob for prof in "$ARENA_STATE"/profile-*.collapsed; do if [ -s "$prof" ]; then log "profile $(basename "$prof"): $(wc -l < "$prof") stacks" upload "$prof" diagnostics || true else warn "$(basename "$prof") is empty - the JVM was killed before the agent dumped" fi done shopt -u nullglob # --- 5. the MegaMek client's own log ------------------------------------------ # The client is the one JVM whose logging we do not configure. Suramadu launches # it from suramadu.config.template with no -Dlog4j2.configurationFile, so it uses # MegaMek's shipped mmconf/log4j2.xml, which writes files under logs/ and sends # nothing to the console: the appender the config would print through is chosen # by ${env:mm.profile}, and unset resolves to the Null appender. # # Everything else is already in the container log, so this is the only logging # that dies with the task. The host and the watcher take log4j2-quiet.xml, which # is Console-only, and the Suramadu server writes to $ARENA_RUN/suramadu.log, # which entrypoint.sh mirrors line for line with a `tail -F`. # # That is not a theoretical gap. A camo overlay failing to load - the bug patch # 0009 fixes - logged one line, here, and it was unreadable after the fact for # exactly this reason. # # Both files, because they do not cover the same ground: megamek.log takes the # "megamek" logger, unified_log.log also takes Root, so a third-party library # failing shows up only in the second. The rollovers travel too - unified_log.log # rolls at 1MB, and on a long match the start of the game, which is where the # tileset and camo work happens, is in unified_log_%i.log.gz by the end. # # Not collected: bot_path_ranker.log, which is Princess's per-move ranking at # info and is large, repetitive and nothing has asked for it; megameklab.log and # mekhq.log, which belong to the other two applications and stay empty because no # logger in the config routes to them. # # The client is still running at this point - shutdown() finalizes before it # signals the JVMs - so the last lines of a log may not be here yet. log4j2 # flushes each event by default, so what has been written is on disk. # # Under `diagnostics`, the key steps 3 and 4 already use: the stats table, the # profiles and these are the same artefact class, and one key means headquarters # presigns one target rather than a new one per thing we learn to keep. log_count=0 for f in "$LOGDIR/megamek.log" "$LOGDIR/unified_log.log" "$LOGDIR"/unified_log_*.log.gz; do [ -f "$f" ] || continue upload "$f" diagnostics && log_count=$((log_count + 1)) || true done log "uploaded $log_count client log(s)" # --- 6. the match, counted ---------------------------------------------------- # One analytics event per human, so that a player who signed in on the site and # then played shows up as one person doing both rather than two unrelated # numbers. The site files "signed in" against a salted hash of the player's DID; # this files "played a match" against the same hash, which is the only reason # the two ever join up. # # Both halves of that hash have to agree, so the salt is not written here: it # arrives as ARENA_POSTHOG_SALT and must be byte-for-byte what web/src/ # analytics.ts uses. Unset - a local ./scripts/run.sh, or a fork - and this # whole section is skipped, which is the right answer for a match nobody is # counting. # # Nothing identifying goes in the properties. Not the handle, not the slot name, # not the DID: a slot name is chosen by the player and a handle is a person, and # neither is needed to answer how many matches get played and how far they get. if [ -n "${ARENA_POSTHOG_KEY:-}" ] && [ -n "${ARENA_POSTHOG_SALT:-}" ] && [ -f "$ARENA_STATE/identity.json" ]; then ph_host="${ARENA_POSTHOG_HOST:-https://eu.i.posthog.com}" match_id="$(jq -r '.matchId // ""' "$ARENA_STATE/identity.json")" humans="$(jq '[.players[] | select(.control == "human")] | length' "$ARENA_STATE/identity.json")" bots="$(jq '[.players[] | select(.control != "human")] | length' "$ARENA_STATE/identity.json")" # A match that never reached victory still played, and how far it got is the # interesting part of why it did not. `decided` is the result's own ending, # not the presence of the file: every match has a document now. rounds="$(result_round)" if [ "$(result_ending)" = victory ]; then decided=true; else decided=false; fi events="$ARENA_STATE/posthog-batch.json" : > "$events" while IFS= read -r did; do [ -n "$did" ] || continue # Must match analytics.ts's pseudonym(): SHA-256 of ":", hex. person="$(printf '%s' "$ARENA_POSTHOG_SALT:$did" | sha256sum | cut -d' ' -f1)" jq -n -c \ --arg distinct_id "$person" \ --arg insert_id "$match_id:$person" \ --arg timestamp "$(date -u +%Y-%m-%dT%H:%M:%SZ)" \ --arg match_id "$match_id" \ --argjson rounds "$rounds" \ --argjson humans "$humans" \ --argjson bots "$bots" \ --argjson decided "$decided" \ '{event: "played a match", distinct_id: $distinct_id, timestamp: $timestamp, properties: {"$insert_id": $insert_id, match_id: $match_id, rounds: $rounds, humans: $humans, bots: $bots, decided: $decided}}' >> "$events" done < <(jq -r '.players[] | select(.control == "human") | .did // empty' "$ARENA_STATE/identity.json") if [ -s "$events" ]; then # Best-effort like every other upload here: the exit status belongs to the # match, and a match is not less finished because a counter did not answer. if jq -s -c --arg api_key "$ARENA_POSTHOG_KEY" '{api_key: $api_key, batch: .}' "$events" | curl -fsS --retry 2 --retry-delay 1 --max-time "${ARENA_POSTHOG_TIMEOUT:-15}" \ -X POST -H 'content-type: application/json' --data-binary @- \ "$ph_host/batch/" >/dev/null; then log "counted the match for $(wc -l < "$events") player(s)" else warn "posthog did not accept the match event" fi fi rm -f "$events" fi emit game-over "finalized" log "done"