OpenFUT/openfut-blaze-host/gate-evidence.sh

#!/usr/bin/env bash
# Capture evidence for one live-FIFA gate.
#
#   gate-evidence.sh <gate-label> [outdir]
#
# Records what the system was configured to do AND what it observably did, and
# reports them separately.
#
# WHY BOTH
#
# `blaze-switch.sh status = ON` is an assertion produced by the same tooling
# that performs the switch. If that tooling is wrong — and it has been once
# already, reporting a rollback that had not happened — the assertion is
# worthless. The observed half comes from a different source entirely: the
# sidecar's own record of which peers connected to it. A remote peer appearing
# in the sidecar log is proof the client reached Rust that does not depend on
# reading an iptables rule correctly.
#
# Run it after each gate. It never modifies anything.
set -uo pipefail

HERE="$(cd "$(dirname "$(readlink -f "$0")")" && pwd)"
ROOT="$(cd "$HERE/.." && pwd)"
RUNDIR="${OPENFUT_SIDECAR_RUNDIR:-${TMPDIR:-/tmp}/openfut-sidecar}"
LOGFILE="${OPENFUT_SIDECAR_LOG:-$RUNDIR/sidecar.log}"
TRACE="${OPENFUT_BLAZE_TRACE:-}"

LABEL="${1:-}"
OUT="${2:-$ROOT/gate-evidence}"
[[ -n "$LABEL" ]] || { echo "usage: gate-evidence.sh <gate-label> [outdir]" >&2; exit 2; }

STAMP="$(date -u +%Y%m%dT%H%M%SZ)"
DEST="$OUT/${STAMP}-${LABEL}"
mkdir -p "$DEST"

say() { echo "$@"; }
both() { echo "$@" | tee -a "$DEST/summary.txt" >/dev/null; echo "$@"; }

both "=== gate evidence: $LABEL ($STAMP) ==="
both ""

# ---------------------------------------------------- configured (asserted)
both "--- CONFIGURED (asserted by tooling) ---"
{
  "$HERE/blaze-switch.sh" status 2>&1
  echo
  "$HERE/sidecar.sh" status 2>&1
} > "$DEST/configured.txt"
sed 's/^/  /' "$DEST/configured.txt" | tee -a "$DEST/summary.txt"

# Raw rules, straight from the kernel, not via our parser.
{ sudo iptables -t nat -S 2>/dev/null || true; } > "$DEST/iptables-nat.txt"
both ""

# ------------------------------------------------------ observed (measured)
both "--- OBSERVED (measured from the sidecar's own record) ---"

if [[ ! -f "$LOGFILE" ]]; then
  both "  no sidecar log at $LOGFILE — nothing observed"
else
  cp "$LOGFILE" "$DEST/sidecar.log" 2>/dev/null

  banner="$(grep -m1 'openfut-blaze-host v' "$LOGFILE" 2>/dev/null || true)"
  both "  build: ${banner:-<none>}"
  if grep -q 'tree=DIRTY' <<<"$banner"; then
    both "  !! DIRTY BUILD — this run is NOT parity evidence"
  fi

  conns="$(grep -c 'CONNECT from' "$LOGFILE" 2>/dev/null || echo 0)"
  both "  connections accepted: $conns"

  # THE INDEPENDENT ASSERTION: which peers actually reached this process.
  peers="$(grep -o 'CONNECT from [0-9.]*' "$LOGFILE" 2>/dev/null | awk '{print $3}' | sort -u || true)"
  remote="$(grep -v '^127\.' <<<"$peers" | grep -v '^$' || true)"
  both "  peers: $(tr '\n' ' ' <<<"$peers")"
  if [[ -n "$remote" ]]; then
    both "  REMOTE peer(s) reached the Rust sidecar: $(tr '\n' ' ' <<<"$remote")"
    both "  => the client's Blaze traffic observably landed on Rust"
  else
    both "  no remote peer connected — only loopback (or nothing) reached Rust"
    both "  => a FIFA session did NOT land here"
  fi

  # Session shape, straight from the log.
  logins="$(grep -c 'Authentication::login .*REPLY' "$LOGFILE" 2>/dev/null || echo 0)"
  notifs="$(grep -c 'UserSessions::<' "$LOGFILE" 2>/dev/null || echo 0)"
  both "  login replies: $logins   UserSessions notifications: $notifs"
  both "  close reasons:"
  grep -o 'CLOSE after [0-9]* frame(s): .*' "$LOGFILE" 2>/dev/null \
    | sort | uniq -c | sed 's/^/    /' | tee -a "$DEST/summary.txt" || true

  # Anything that looks wrong.
  probs="$(grep -E 'DECODE FAILED|REJECT|FAILED|absurd' "$LOGFILE" 2>/dev/null | head -20 || true)"
  if [[ -n "$probs" ]]; then
    both "  ANOMALIES:"
    sed 's/^/    /' <<<"$probs" | tee -a "$DEST/summary.txt"
  else
    both "  no anomalies in the log"
  fi
fi

# ------------------------------------------------------------------ trace
both ""
both "--- TRACE ---"
if [[ -n "$TRACE" && -f "$TRACE" ]]; then
  cp "$TRACE" "$DEST/rust-blaze.trace"
  # Count FRAME lines only. `^conn-` also matches the OPEN/CLOSE markers, and
  # counting those inflated the figure by one or two — which then looked like a
  # capture/trace divergence when compared against the capture's record count.
  frames="$(grep -cE '^conn-[0-9]+ (RX|TX) ' "$TRACE" 2>/dev/null || echo 0)"
  markers="$(grep -cE '^conn-[0-9]+ (OPEN|CLOSE)' "$TRACE" 2>/dev/null || echo 0)"
  both "  $TRACE -> $DEST/rust-blaze.trace ($frames traced frames, $markers lifecycle markers)"
  # Capture and trace are written continuously; on a LIVE session they are only
  # comparable if read at the same instant.
  if [[ -n "${OPENFUT_BLAZE_CAPTURE:-}" && -f "${OPENFUT_BLAZE_CAPTURE}" ]]; then
    cp "$OPENFUT_BLAZE_CAPTURE" "$DEST/raw.ofcap" 2>/dev/null && chmod 600 "$DEST/raw.ofcap"
    both "  raw capture -> $DEST/raw.ofcap (0600, NEVER commit)"
  fi
  both "  routes seen:"
  grep -o '^conn-[0-9]* \(RX\|TX\) [^ ]* [A-Za-z]*::[^ ]*' "$TRACE" 2>/dev/null \
    | awk '{print $2, $4}' | sort | uniq -c | sort -rn | head -20 \
    | sed 's/^/    /' | tee -a "$DEST/summary.txt" || true
else
  both "  no trace configured (set OPENFUT_BLAZE_TRACE before starting the sidecar)"
fi

# --------------------------------------------- python side (the other half)
#
# "Rust did not receive it" is weaker than "Python did". The redirector always
# runs on Python and is never switched, so it advertises the Blaze endpoint on
# every run; whether Python then receives the Blaze CONNECT it just advertised
# is the positive observation that says where the hop actually went.
both ""
both "--- PYTHON SIDE (positive/negative observation) ---"
PYLOG=/tmp/blaze_responder.log
if docker exec openfut-fut-backend test -f "$PYLOG" 2>/dev/null; then
  docker exec openfut-fut-backend sh -c "grep -E 'REDIR SENT|BLAZE CONNECT from|closed' $PYLOG" \
    > "$DEST/python-blaze.log" 2>/dev/null || true
  CLIENT="${OPENFUT_CLIENT_IP:-}"
  if [[ -z "$CLIENT" ]]; then
    both "  OPENFUT_CLIENT_IP not set — skipping the client-specific correlation"
    both "  (set it to the FIFA machine's address for positive/negative observation)"
  fi
  redirs="$(grep -c "REDIR SENT ('$CLIENT'" "$DEST/python-blaze.log" 2>/dev/null || echo 0)"
  blazes="$(grep -c "BLAZE CONNECT from ('$CLIENT'" "$DEST/python-blaze.log" 2>/dev/null || echo 0)"
  both "  client $CLIENT — redirector hops served by Python: $redirs"
  both "  client $CLIENT — Blaze connections received by Python: $blazes"
  both "  most recent:"
  grep -E "\('$CLIENT'" "$DEST/python-blaze.log" 2>/dev/null | tail -4 | sed 's/^/    /' \
    | tee -a "$DEST/summary.txt" || true
  both ""
  both "  interpretation: a redirector hop with NO following Python Blaze CONNECT"
  both "  means the Blaze hop went elsewhere (the Rust sidecar). A Python Blaze"
  both "  CONNECT means it went to Python."
else
  both "  python blaze log not readable (container not running?)"
fi

# ------------------------------------------------- FUT actions (UTAS side)
#
# "Known FUT action succeeded" is a client-side fact, but it leaves an
# independent trace: FUT actions go over UTAS (Python, never switched), so the
# UTAS log confirms them without relying on anyone's recollection of what they
# clicked.
both ""
both "--- FUT ACTIONS (observed on UTAS, which is always Python) ---"
UTASLOG=/tmp/utas_server.log
if docker exec openfut-fut-backend test -f "$UTASLOG" 2>/dev/null; then
  docker exec openfut-fut-backend sh -c "grep -E 'STORE:|SQUAD:|SBC:|TRADE:' $UTASLOG" \
    > "$DEST/utas-actions.log" 2>/dev/null || true
  # Window to THIS gate. The UTAS log is cumulative across the whole
  # deployment, so a raw count reads as if 45 packs were opened in this gate.
  # The sidecar is restarted per gate, so its first log line is the window
  # start. Both numbers are reported, labelled, because a bare count in a gate
  # report is read as belonging to that gate.
  since="$(head -1 "$LOGFILE" 2>/dev/null | sed -E 's/^\[([0-9]+)\..*/\1/')"
  since_hm="$(date -d "@${since:-0}" '+%H:%M' 2>/dev/null || echo '00:00')"
  all_packs="$(grep -c 'opened pack' "$DEST/utas-actions.log" 2>/dev/null || echo 0)"
  gate_packs="$(awk -F'[][]' -v t="$since_hm" '$2>=t' "$DEST/utas-actions.log" 2>/dev/null \
                 | grep -c 'opened pack' || echo 0)"
  both "  pack opens THIS GATE (since $since_hm): $gate_packs"
  both "  pack opens in the whole log (cumulative, all deployments): $all_packs"
  both "  actions this gate:"
  awk -F'[][]' -v t="$since_hm" '$2>=t' "$DEST/utas-actions.log" 2>/dev/null | tail -6 \
    | sed 's/^/    /' | tee -a "$DEST/summary.txt" || true
else
  both "  utas log not readable"
fi

# ----------------------------------------------------------- python health
both ""
both "--- PYTHON BACKEND (must stay healthy throughout) ---"
if contract="$(cd "$ROOT/fifa17-recon" && timeout 120 python3 tools/test_fut_contract.py 2>&1 | tail -1)"; then
  both "  contract suite: $contract"
else
  both "  contract suite: FAILED TO RUN"
fi

both ""
both "evidence bundle: $DEST"