worldbox-observer-mod/scripts/soak-audit-player-log.sh

#!/usr/bin/env bash
# Audit IdleSpectator Watching / DROP / BAD / STATE from Player.log.
#
# Usage:
#   ./scripts/soak-audit-player-log.sh              # last 120s wall wait, then audit new bytes
#   ./scripts/soak-audit-player-log.sh 60           # wait 60s then audit
#   ./scripts/soak-audit-player-log.sh --since-bytes N   # audit from byte offset (no wait)
#   ./scripts/soak-audit-player-log.sh --since-bytes N 60  # wait 60s, then audit from N
#   ./scripts/soak-audit-player-log.sh --no-wait    # audit empty window from current EOF
#
# Env:
#   PLAYER_LOG - override Player.log path
set -euo pipefail

LOG="${PLAYER_LOG:-$HOME/.config/unity3d/mkarpenko/WorldBox/Player.log}"
SECONDS_WAIT=0
SINCE_BYTES=""

while [[ $# -gt 0 ]]; do
  case "$1" in
    --since-bytes)
      SINCE_BYTES="${2:-}"
      shift 2
      ;;
    --no-wait)
      SECONDS_WAIT=0
      shift
      ;;
    -h|--help)
      sed -n '2,12p' "$0"
      exit 0
      ;;
    *)
      if [[ "$1" =~ ^[0-9]+$ ]]; then
        SECONDS_WAIT="$1"
      else
        echo "Unknown arg: $1" >&2
        exit 2
      fi
      shift
      ;;
  esac
done

if [[ ! -f "$LOG" ]]; then
  echo "Player.log not found: $LOG" >&2
  exit 1
fi

MARKED_FROM_EOF=0
if [[ -z "$SINCE_BYTES" ]]; then
  SINCE_BYTES=$(wc -c < "$LOG" | tr -d ' ')
  MARKED_FROM_EOF=1
fi

if [[ "$SECONDS_WAIT" -gt 0 ]]; then
  echo "Marked offset $SINCE_BYTES; waiting ${SECONDS_WAIT}s (leave Idle Spectator running) ..."
  sleep "$SECONDS_WAIT"
elif [[ "$MARKED_FROM_EOF" -eq 1 ]]; then
  echo "No wait and no --since-bytes: auditing from current EOF (empty window)."
  echo "Tip: ./scripts/soak-audit-player-log.sh 60"
fi

python3 - "$LOG" "$SINCE_BYTES" <<'PY'
import re, sys
from collections import Counter
from pathlib import Path

log_path = Path(sys.argv[1])
armed = int(sys.argv[2])
raw = log_path.read_bytes()[armed:].decode("utf-8", errors="replace")
lines = raw.splitlines()

def harness_noise(ln: str) -> bool:
    if "[HARNESS]" not in ln and "[ASSERT]" not in ln:
        return False
    return "action=" in ln or "batch done" in ln or "inbox reset" in ln

watching = []
pairs = []
drops = []
bads = []
scenes = []
states = []
hitch_details = []
hitch_summaries = []
first_active_line = -1
last = None

for line_index, ln in enumerate(lines):
    if harness_noise(ln):
        continue
    if "IdleSpectator" not in ln:
        continue
    if "Watching:" in ln:
        tip = ln.split("Watching:", 1)[1].strip()
        tip = re.sub(r"^\[\d+\]\s*", "", tip)
        watching.append(tip)
        last = {"tip": tip, "unit": None, "caption": None}
        pairs.append(last)
    elif "[CAPTION]" in ln and last is not None:
        last["caption"] = ln.split("[CAPTION]", 1)[1].strip()
    elif "[DROP]" in ln:
        drops.append(ln.split("[DROP]", 1)[1].strip())
    elif "[BAD]" in ln:
        bads.append(ln.split("[BAD]", 1)[1].strip())
    elif "Scene end" in ln:
        scenes.append(ln.split("Scene end", 1)[1].strip())
    elif "[STATE]" in ln:
        states.append(ln)
        if first_active_line < 0 and re.search(r"idle=True", ln):
            first_active_line = line_index
        if last is not None and last.get("unit") is None and "unit=" in ln:
            last["unit"] = ln.split("unit=", 1)[1].strip()
    elif "[HITCH] spike" in ln:
        hitch_details.append(ln)
    elif "[HITCH] summary" in ln:
        hitch_summaries.append(ln)

drop_kinds = Counter()
for d in drops:
    drop_kinds[d.split(":", 1)[0].strip()] += 1

focus_true = focus_false = 0
idle_true = idle_false = 0
for s in states:
    m = re.search(r"focus=(True|False)", s)
    if not m:
        continue
    if m.group(1) == "False":
        focus_false += 1
    else:
        focus_true += 1
    idle = re.search(r"idle=(True|False)", s)
    if idle:
        if idle.group(1) == "True":
            idle_true += 1
        else:
            idle_false += 1

def bucket(t: str) -> str:
    tl = t.lower()
    # Combat scale first (before generic fight / vs).
    if tl.startswith("duel") or " duel " in f" {tl} " or tl.startswith("duel -"):
        return "combat_duel"
    if any(tl.startswith(p) for p in ("skirmish", "battle", "mass")) or " mass -" in f" {tl} ":
        return "combat_multi"
    if any(x in tl for x in ("fighting", "in a fight", " vs ")) and "war -" not in tl and "plot -" not in tl:
        return "combat_other"
    if "decides to start a new civilization" in tl or "decides to found" in tl:
        return "decision_genesis_intent"
    if any(x in tl for x in ("new city", "new kingdom", "founds a", "founded")):
        return "meta_genesis"
    if any(x in tl for x in ("war -", "kingdom", "rebellion")):
        return "politics"
    if any(x in tl for x in ("love", "smitten", "child", "parenthood", "mourns", "lover")):
        return "relationship"
    if any(x in tl for x in ("curs", "possess", "dream", "nightmare", "enchant", "stun")):
        return "status"
    if "new species" in tl or "appear" in tl or "hatch" in tl:
        return "discovery"
    if "plot" in tl or "decides to" in tl:
        return "plot_or_decision"
    if "fall" in tl and any(x in tl for x in ("tree", "plant", "bush", "flower", "maple")):
        return "object_fall"
    return "other"

buckets = Counter(bucket(t) for t in watching)
bucket_sequence = [bucket(t) for t in watching]
scene_reasons = Counter()
for s in scenes:
    m = re.match(r"\(([^)]+)\)", s)
    if m:
        scene_reasons[m.group(1)] += 1

identity = sum(1 for d in drops if "identity_filter" in d)
unpresentable = sum(1 for d in drops if "unpresentable" in d)
placeholder = sum(1 for t in watching if "something interesting" in t.lower())
veg = [t for t in watching if bucket(t) == "object_fall"]
no_focus_bads = sum(1 for b in bads if "no focus" in b.lower())

mismatches = []
sleep_lag = []
for p in pairs:
    tip = p["tip"]
    unit = (p.get("unit") or "").strip()
    cap = p.get("caption") or ""
    if "fighting" in tip.lower() and "Sleeping" in cap:
        sleep_lag.append((tip, cap))
    if not tip or not unit:
        continue
    if "fighting" not in tip.lower() and "fight of" not in tip.lower():
        continue
    subj = tip.split(" is ", 1)[0].split(" · ", 1)[0].strip()
    u0 = unit.split()[0]
    if u0 and u0.lower() not in subj.lower():
        mismatches.append((tip, unit, cap[:72]))

print(f"Player.log soak audit")
print(f"  log={log_path}")
print(f"  since_bytes={armed}  chunk_lines={len(lines)}")
print()
print(f"Watching cuts:     {len(watching)}")
print(f"Focus BADs:        {no_focus_bads}  (all BADs={len(bads)})")
print(f"focus True/False:  {focus_true}/{focus_false}")
print(f"idle True/False:   {idle_true}/{idle_false}")
if first_active_line >= 0:
    print(f"first active state: line {first_active_line + 1}/{len(lines)}")
print(f"identity_filter:   {identity}")
print(f"unpresentable:     {unpresentable}")
print(f"placeholder tips:  {placeholder}")
print(f"object falls:      {len(veg)}")
print(f"fight tip/focus mismatches: {len(mismatches)}")
print(f"fighting+Sleeping lag:      {len(sleep_lag)}")
active_hitches = [h for h in hitch_details if "idle=on" in h]

def metric_max(rows, name):
    values = []
    pattern = re.compile(rf"\b{re.escape(name)}=([0-9.]+)ms")
    for row in rows:
        match = pattern.search(row)
        if match:
            values.append(float(match.group(1)))
    return max(values, default=0.0)

summary_spikes = 0
summary_max_dt = 0.0
summary_max_dir = 0.0
summary_max_disc = 0.0
summary_max_cap = 0.0
for row in hitch_summaries:
    if "idle=on" not in row:
        continue
    spike = re.search(r"\bspikes=(\d+)", row)
    dt = re.search(r"\bmaxDt=([0-9.]+)ms", row)
    direct = re.search(r"\bmaxDir=([0-9.]+)ms", row)
    discovery = re.search(r"\bmaxDisc=([0-9.]+)ms", row)
    caption = re.search(r"\bmaxCap=([0-9.]+)ms", row)
    if spike:
        summary_spikes += int(spike.group(1))
    if dt:
        summary_max_dt = max(summary_max_dt, float(dt.group(1)))
    if direct:
        summary_max_dir = max(summary_max_dir, float(direct.group(1)))
    if discovery:
        summary_max_disc = max(summary_max_disc, float(discovery.group(1)))
    if caption:
        summary_max_cap = max(summary_max_cap, float(caption.group(1)))

print(
    "Hitches active:     "
    f"detail={len(active_hitches)} summary_spikes={summary_spikes} "
    f"maxDt={max(summary_max_dt, metric_max(active_hitches, 'dt')):.1f}ms "
    f"dir={max(summary_max_dir, metric_max(active_hitches, 'dir')):.1f}ms "
    f"disc={max(summary_max_disc, metric_max(active_hitches, 'disc')):.1f}ms "
    f"cap={max(summary_max_cap, metric_max(active_hitches, 'cap')):.1f}ms "
    f"scan={metric_max(active_hitches, 'scanMs'):.1f}ms "
    f"soft={metric_max(active_hitches, 'softMs'):.1f}ms "
    f"scheduler={metric_max(active_hitches, 'schedulerMs'):.1f}ms"
)
print()
if buckets:
    print("Buckets:")
    for k, v in buckets.most_common():
        print(f"  {k:16} {v}")
    print()
if drop_kinds:
    print("Drop kinds:")
    for k, v in drop_kinds.most_common(12):
        print(f"  {k:24} {v}")
    print()
if scene_reasons:
    print("Scene ends:")
    for k, v in scene_reasons.most_common():
        print(f"  {k:16} {v}")
    print()
if watching:
    print("Tips:")
    for t in watching:
        print(f"  - {t}")
    print()
if mismatches:
    print("Fight tip/focus mismatches:")
    for tip, unit, cap in mismatches:
        print(f"  tip={tip!r} focus={unit!r} caption={cap!r}")
    print()
if sleep_lag:
    print("Fight tip + Sleeping caption:")
    for tip, cap in sleep_lag:
        print(f"  tip={tip!r} caption={cap!r}")
    print()

genesis_intent = buckets.get("decision_genesis_intent", 0)
duel_n = buckets.get("combat_duel", 0)
multi_n = buckets.get("combat_multi", 0)
combat_total = duel_n + multi_n + buckets.get("combat_other", 0)
combat_share = combat_total / len(watching) if watching else 0.0
max_combat_run = 0
combat_run = 0
for kind in bucket_sequence:
    if kind.startswith("combat_"):
        combat_run += 1
        max_combat_run = max(max_combat_run, combat_run)
    else:
        combat_run = 0
relationship_n = buckets.get("relationship", 0)
unique_tips = len(set(watching))
print(
    f"Variety: duel={duel_n} multi={multi_n} combat_total={combat_total} "
    f"combat_share={combat_share:.1%} max_combat_run={max_combat_run} "
    f"relationship={relationship_n} unique_tips={unique_tips}/{len(watching)} "
    f"genesis_intent={genesis_intent}"
)
if genesis_intent:
    print("  NOTE: decision_genesis_intent tips should be 0 after 0.28.28 (meta outcomes only).")
if combat_total >= 4 and multi_n == 0 and duel_n >= 3:
    print("  NOTE: combat tips are Duel-heavy; multi scrap may be scarce in this world.")
if first_active_line >= 0 and len(lines) > 0 and first_active_line > len(lines) * 0.25:
    print("  NOTE: Idle Spectator activated late; most of this audit window is not a directed soak.")
if len(watching) >= 20 and combat_share > 0.35:
    print("  NOTE: combat exceeds the story-first release target of 35%.")
if max_combat_run > 3:
    print("  NOTE: more than three consecutive combat cuts; inspect critical bypasses and episode boundaries.")
print()

editorial_pacing_ok = len(watching) < 20 or combat_share <= 0.35
sample_valid = bool(watching) and idle_true > 0 and first_active_line >= 0
ok = (
    sample_valid
    and no_focus_bads == 0
    and focus_false == 0
    and idle_false == 0
    and identity == 0
    and placeholder == 0
    and len(veg) == 0
    and len(mismatches) == 0
    and len(sleep_lag) == 0
    and genesis_intent == 0
    and editorial_pacing_ok
)
if not sample_valid:
    print("  NOTE: no valid active spectator sample was captured.")
print("VERDICT:", "PASS" if ok else "REVIEW")
sys.exit(0 if ok else 1)
PY