tools: fix four boot-harness bugs; find the swallowed-keystroke cause and refute it

Chasing why (A) does not advance the title turned up four harness bugs, one real
root cause, and a refutation of that root cause as the explanation.

FIXED, each verified:
  * boot_menu.sh sent the emulator stdout to /dev/null, which is why none of the
    rest was visible. It now keeps a log and prints its path.
  * skip_intro.sh probed pixel (625,618) for the green (A) glyph - a 1280x720
    coordinate. screenshot returns the 1279x675 game surface, where that point
    is on the copyright line and reads (8,17,31). Symptom: a 600s TIMEOUT with
    the title on screen. Now classified with screen_id.py; next boot printed
    "TITLE at 239s -> A".
  * skip_intro.sh no longer taps through the movies. Making that press real (the
    vgamepad fix) was a REGRESSION: the boot then reached the title in 90s and
    that title accepted nothing. menu_draw_capture.sh records the same finding
    independently.
  * boot_menu.sh signs in whichever profile exists instead of a hard-coded XUID.

ROOT CAUSE FOUND: naming a XUID with no profile behind it opens a sign-in
dialog, xam_dialogs_shown_ goes to 1, and IsUIActive() then discards every
XamInputGetKeystrokeEx. Measured 8,388,601 swallowed calls in one boot with the
pad log showing presses arriving normally throughout. Only B13EBABEBABEBABE
exists on disc; the script asked for E0300000EFBEA3D4. Signing in the real
profile takes the swallow count 8,388,601 -> 0.

AND REFUTED: that is not why the title is stuck. With a valid profile and zero
swallowed keystrokes, a single (A) on the title that ends the boot still does
nothing. The dialog bug was real and worth fixing; it is not the explanation.

Next probe is specific: --log_mask=13 records no kernel calls, so it is not even
known whether the game polls at the title. A log on the SUCCESSFUL
XamInputGetKeystrokeEx return, mirroring the one already on the swallow path,
answers it in one boot.

docs/re/ui-paint-order-third-permutation.md

@@ -77,33 +77,93 @@ about half the time" note. **It does not.** See below.
 
 With the pad verified end to end — `pad.py` writes `/tmp/xenia_pad.txt`, the
 emulator was launched with `--hid=file --pad_file=/tmp/xenia_pad.txt`, and the
-file's mtime updates on every press — the title screen does not advance:
+log shows `[file-pad] keystroke vk=5800 down/up` for every press — the title
+screen does not advance. Holds of 0.10 s, 0.25 s and 0.40 s, Ⓐ and START, on a
+screen that unambiguously renders PRESS Ⓐ BUTTON
+([capture](captures/title-with-press-a-live.png)).
 
-| press | hold | result |
-|---|---|---|
-| Ⓐ ×2 | 0.10 s | still title |
-| Ⓐ | 0.25 s | still title |
-| Ⓐ ×5 | 0.40 s | still title |
-| START | 0.30 s | still title |
+### ✅ A root cause found, measured, and fixed — a sign-in dialog
 
-The screen is unambiguously the interactive one — PRESS Ⓐ BUTTON is rendered
-([capture](captures/title-with-press-a-live.png)). So the input path is wired and
-the game is waiting for a press it never sees.
+Keeping the emulator's stdout (see below) produced the line immediately:
 
-The most likely suspect is already instrumented but was not captured this run:
-the `[RE-INPUT] XamInputGetKeystrokeEx swallowed by IsUIActive` log added to
-`xam_input.cc` on the canary branch. `boot_menu.sh` sends the emulator's stdout
-to `/dev/null`, so nothing was recorded. **That is the first step next time:**
-boot with stdout kept and check whether the keystroke is being swallowed, which
-would make this an emulator-side bug rather than a game-side one.
+```
+w> [RE-INPUT] XamInputGetKeystrokeEx swallowed by IsUIActive (dialogs=1 nui=0, 8388601 so far)
+```
+
+`xam_dialogs_shown_` is **1**, so `XamState::IsUIActive()` returns true and
+`xam_input.cc` discards every keystroke — **8 388 601 of them in one boot**,
+while the pad log shows presses arriving normally the whole time.
+
+The dialog is a **sign-in UI opened because the requested profile does not
+exist**. `boot_menu.sh` passed `--logged_profile_slot_0_xuid=E0300000EFBEA3D4`;
+the only profile on disc is `B13EBABEBABEBABE`, and the boot log says so at line
+309: `FindProfiles: Adding profile B13EBABEBABEBABE to profile list`,
+`ProfileManager: Found 1 Profiles`. Naming a XUID with nothing behind it is not
+a harmless no-op.
+
+Fixed — `boot_menu.sh` now signs in whichever profile exists. **Swallowed
+keystrokes: 8 388 601 → 0.**
+
+### 🔴 Refuted: that was not sufficient
+
+Fixing the swallow does **not** make the title accept Ⓐ. With a valid profile
+signed in and **zero** swallowed calls, the title still does not advance. So the
+dialog bug was real and worth fixing, and it is not the explanation.
+
+That also means `menu_draw_capture.sh`'s note — "the title that ends the boot
+sequence accepts a single (A) (2 of 2 runs)" — no longer reproduces. The run
+here reached the title at 239 s, pressed once, and stayed.
+
+## Three more harness bugs, all of which read as the game misbehaving
+
+**`--audio` is not a cvar**, and eight boot scripts passed it. Xenia calls
+`ShowSimpleMessageBox` from `ParseLaunchArguments`, *before* logging is
+initialised, so the symptom is a 10×10 window, an empty log, no guest memory and
+a dialog blocking on `XIfEvent` forever — a hang deep in the emulator, to look
+at. `run-canary`'s own header documents this trap; the scripts predate it.
+
+**`vgamepad` no longer exists.** `skip_intro.sh` still called
+`vgamepad tap A 250`, and without `set -e` the call failed silently: the branch
+pressed **nothing** and still `exit 0`. The boot log states it outright —
+
+```
+movie (rmse 1662) at 434s -> skip A
+tools/re-capture/skip_intro.sh: line 44: vgamepad: command not found
+```
+
+— so every "→ skip A" and "TITLE → A" this harness ever printed pressed nothing,
+and the intro ran to 434 s because it was never skipped.
+
+**Do not tap through the movies.** Making that press real for the first time was
+a *regression*: the boot then reached the title in 90 s and that title accepted
+nothing at all. `menu_draw_capture.sh` records the same thing independently —
+"a run that tapped (A) every 4 s through the boot delivered 88 presses and ended
+on a black screen that never came back", and "the title the attract loop returns
+to accepts nothing at all, and 40 taps at 1/s do not change that". `skip_intro.sh`
+now waits the intro out and spends its single press on the title that ends the
+boot.
+
+**The title probe sampled a dead pixel.** `skip_intro.sh` tested `p{625,618}` for
+the green Ⓐ glyph — a coordinate from a 1280×720 grab. `screenshot` returns the
+**1279×675 game surface**, where that point is on the copyright line and reads
+`(8,17,31)`. The symptom was a 600 s `TIMEOUT` with the title on screen the whole
+time. Now classified with `screen_id.py`, which called those same frames "title";
+the next boot printed `TITLE at 239s -> A`.
+
+**And `boot_menu.sh` sent the emulator's stdout to `/dev/null`** — which is why
+none of this was visible. A boot harness that discards the emulator's own account
+of itself can only ever report symptoms. It now keeps a log and prints its path.
 
 ## What is not settled
 
-* 🔴 The third permutation itself. The tool is ready; the screen is not reachable.
-* ❔ Whether Ⓐ ever worked at this title screen, or whether the "half the time"
-  note was always the silent `vgamepad` failure plus chance. The `vgamepad` bug
-  is now excluded, and the title still does not advance, so something else is
-  wrong.
-* ❔ Only **one** screen object was resident at the moment the main menu was
-  believed to be up (the splash), where the title has seven. Unexplained, and
-  possibly a symptom of the same thing — the menu may never have loaded.
+* 🔴 The third permutation. The reader is ready and validated; the screen is not
+  reachable.
+* 🔴 **Why the title does not advance.** The sign-in dialog is excluded, the
+  `vgamepad` no-op is excluded, and the pad is confirmed delivering. The next
+  probe needs a log level that records kernel *calls* — at `--log_mask=13` the
+  only mentions of `XamInputGetKeystrokeEx` in an 84 KB log are import-table
+  entries, so it is not even known whether the game polls at the title. A
+  targeted log on the **successful** return path (mirroring the existing one on
+  the swallow path) would answer it in one boot.
+* ❔ Only **one** screen object was resident when the harness believed the main
+  menu was up, where the title has seven.

tools/re-capture/boot_menu.sh

@@ -37,10 +37,26 @@ ensure_display(){
 rm -f /dev/shm/xenia_memory_* /dev/shm/xenia_code_cache_* 2>/dev/null
 ensure_display
 cd /sylph-home/re
+# KEEP the emulator's stdout. It used to go to /dev/null, which cost a session:
+# the pad appeared dead at the title and the one log line that would have said
+# why — "[RE-INPUT] XamInputGetKeystrokeEx swallowed by IsUIActive" — was being
+# discarded. A boot harness that throws away the emulator's own account of
+# itself can only ever report symptoms.
+LOG="${BOOT_MENU_LOG:-$SHOTS/$TAG-canary.stdout}"
+# Sign in the profile that EXISTS. Naming a XUID with no profile behind it is
+# not a no-op: the title opens a sign-in dialog, xam_dialogs_shown_ goes to 1,
+# and IsUIActive() then swallows every XamInputGetKeystrokeEx for the rest of
+# the run — a pad that delivers keystrokes to an emulator that discards them.
+# Measured: 8.4 MILLION swallowed calls in one boot, with the pad log showing
+# `vk=5800 down/up` arriving normally the whole time.
+XUID="${SYLPH_XUID:-$(ls "${XENIA_CONTENT:-$HOME/.local/share/Xenia/content}" 2>/dev/null | head -1)}"
+[ -n "$XUID" ] || { echo "NO PROFILE — run once with --create_profile_if_none=Tag"; exit 2; }
+echo "signing in profile $XUID"
 nohup run-canary --apu=sdl --log_mask=13 \
-  --logged_profile_slot_0_xuid=E0300000EFBEA3D4 </dev/null >/dev/null 2>&1 &
+  --logged_profile_slot_0_xuid="$XUID" </dev/null >"$LOG" 2>&1 &
 sleep 5
 "$SD/skip_intro.sh" 600 || { echo "BOOT FAILED (skip_intro exit $?)"; exit 1; }
 sleep 14
 screenshot "$SHOTS/$TAG-menu.png" >/dev/null 2>&1
 echo "AT MAIN MENU (cursor on NEW GAME); LOAD GAME is one d-pad step down"
+echo "emulator log: $LOG"

tools/re-capture/skip_intro.sh

@@ -43,12 +43,29 @@ while [ $SECONDS -lt $deadline ]; do
   [ -n "$(alive)" ] || { echo "EMULATOR GONE at ${SECONDS}s"; exit 4; }
   d=$(compare -metric RMSE /tmp/f1.png /tmp/f2.png null: 2>&1 | sed 's/ .*//' | cut -d. -f1)
   d=${d:-0}
-  read -r r g b < <(convert /tmp/f2.png -format "%[fx:int(255*p{625,618}.r)] %[fx:int(255*p{625,618}.g)] %[fx:int(255*p{625,618}.b)]" info:)
-  if [ "$g" -gt 130 ] && [ $((g - r)) -gt 45 ] && [ $((g - b)) -gt 45 ]; then
+  # Classify the whole frame, do NOT probe one absolute pixel. The old test
+  # sampled (625,618) for the green (A) glyph, which is a coordinate from a
+  # 1280x720 grab; `screenshot` now returns the 1279x675 GAME SURFACE, where
+  # that point lands on the copyright line and reads (8,17,31). The symptom was
+  # a 600s TIMEOUT with the title sitting on screen the entire time — measured
+  # 2026-08-19, with screen_id.py calling it "title" on the same frames.
+  if [ "$(python3 "$SD_SI/screen_id.py" /tmp/f2.png | awk '{print $1}')" = "title" ]; then
     echo "TITLE at ${SECONDS}s -> A"; tapA; exit 0
   fi
+  # DO NOT tap through the movies. This branch used to, and for a long time it
+  # was harmless only because `vgamepad` did not exist and the call failed
+  # silently. Once the press became real, the boot reached the title in 90s
+  # instead of 434s — and that title accepts NOTHING. menu_draw_capture.sh
+  # records the same thing from the other direction: "a run that tapped (A)
+  # every 4s through the boot delivered 88 presses and ended on a black screen
+  # that never came back", and "the title the attract loop returns to accepts
+  # nothing at all, and 40 taps at 1/s do not change that".
+  #
+  # So: wait the intro out (~3.5 min) and spend the single press on the title
+  # that ends the boot sequence, which is the one that accepts it.
   if [ "$d" -gt 1500 ]; then
-    echo "movie (rmse $d) at ${SECONDS}s -> skip A"; tapA; sleep 3
+    echo "movie (rmse $d) at ${SECONDS}s -> waiting it out (tapping breaks the title)"
+    sleep 3
   fi
   sleep 1
 done