44ff5454f9
Chasing the title-screen crash into the emulator's own diagnostics turned it from a mystery into a controlled experiment, and knocked over two things this corpus said yesterday. Withdrawn #1: "the fault address 0x1_0000000C is a pointer with a stale high word". The crash dump prints r25 = 0x0000000C, clean. Xenia maps the guest's 4 GiB at host 0x1_00000000, so that IS guest address 12. The guest dereferenced the small integer 12. Withdrawn #2: "with --mem_watch=false the crash does not happen at all", which named the crash-oracle handoff's suspect #1 as measured. It was confounded — every --mem_watch=false run had also had a warm cache. Held cold, the throw happens with the probe off (2 437 crash dumps). mem_watch is eliminated for this crash. What it actually is: the access violation is the guest's own `throw` RETURNING, because this build logs guest C++ exceptions and continues rather than unwinding. So the event is the throw, and with --cache_throw_diag=true the guest names it: std::out_of_range, from the cache-manager flush, with a deque of 38 entries (37 distinct, one duplicated) against a 37-key map, every one of them absent from the flush's snapshot but present in the live map — the TOCTOU race the logger's own message describes. And the new, useful part: the trigger is the on-disc cache. Complete cache, no throw (2 runs). Directory moved aside or half-rebuilt, throw ~100 s into the boot (3 runs, including one that threw with NO access violation behind it — which is why crash dialogs are the wrong thing to count). A suspect in that bisection plan now costs a `mv` and two minutes instead of a mission.
192 lines
9.0 KiB
Markdown
192 lines
9.0 KiB
Markdown
# The title-screen crash is an STL `map`/`set` erase on a bad iterator
|
||
|
||
**Status:** ✅ `CONFIRMED` — the guest throws `std::out_of_range` from an STL
|
||
`map`/`set` erase during its cache flush, and an **incomplete on-disc cache**
|
||
triggers it about 100 s into a boot (4 runs, 2 each way). 🟡 `PROBABLE` that this
|
||
is the same defect as the Ready-Room crash — same exception type, same
|
||
subsystem, same TOCTOU shape — but ❌ **the `mem_watch` probe that handoff ranks
|
||
as suspect #1 is eliminated here**: with the cache cold, the throw happens with
|
||
the probe off. ⚠️
|
||
**two readings in the first version of this note are withdrawn** (see the
|
||
correction below): the fault address is not a corrupt pointer, and the access
|
||
violation is not the bug.
|
||
|
||
Found while trying to get past the title screen for a second UI screen's paint
|
||
order ([`canary-scripted-input-traps.md`](canary-scripted-input-traps.md)). It is
|
||
worth a page of its own because it turns a crash that cost a whole mission to
|
||
reproduce into one that costs a `mv` and 100 seconds.
|
||
|
||
## The reproduction
|
||
|
||
Move the game's cache directory aside and boot with `--cache_throw_diag=true`:
|
||
|
||
```bash
|
||
mv ~/.local/share/Xenia/cache/aab216c3 /tmp/ # reversible; the game rebuilds it
|
||
run-canary --mem_watch=true --cache_throw_diag=true \
|
||
--logged_profile_slot_0_xuid=B13EBABEBABEBABE
|
||
grep GUEST-THROW <log> # ~100 s in
|
||
```
|
||
|
||
With the cache complete, the same boot produces no throw at all. The original
|
||
symptom — what this note was opened for — looks like this:
|
||
|
||
```
|
||
Access Violation: read at 0x000000010000000C
|
||
PC: 0x82307128 guest thread 9
|
||
… preceded by HostPathDevice::ResolvePath(\aab216c3\5\c10eae6)
|
||
and RtlRaiseException(702DF7F0(E06D7363), ContextArg)
|
||
"Guest attempted to throw a C++ exception!"
|
||
```
|
||
|
||
Xenia pauses itself and stacks crash dialogs — 991 in one run, 2 437 in another.
|
||
|
||
## What the code is
|
||
|
||
`0x82307128` is inside `sub_823070B0` (`0x823070B0..0x823074D0`, has EH), and the
|
||
function identifies itself: it references the string
|
||
`'invalid map/set<T> iterator'` at `0x82062A8C`, builds it with the string
|
||
helpers at `0x8216E7E8` / `0x8216E5C8`, and throws it through `0x825F23D8`.
|
||
|
||
The node layout in the prologue is MSVC's `std::_Tree_node` exactly:
|
||
|
||
```
|
||
823070C8 lbz r10, 25(r5) ; iterator->_Ptr->_Isnil (offset 25)
|
||
… ; if set -> build the string and THROW
|
||
82307124 bl 0x8244E2A8 ; (iterator helper)
|
||
82307128 lwz r11, 0(r25) ; node->_Left (offset 0) <-- FAULT
|
||
8230713C lwz r27, 8(r25) ; node->_Right (offset 8)
|
||
```
|
||
|
||
`_Left` 0, `_Parent` 4, `_Right` 8, `_Color` 24, `_Isnil` 25 — that is the MSVC
|
||
red-black tree node, so this is a `std::map`/`std::set` **erase** (it validates
|
||
the iterator, then walks the node). The crash is the very first dereference
|
||
after the validation.
|
||
|
||
## Correction: the fault address is not a corrupt pointer, and the AV is not the bug
|
||
|
||
The first version of this note read `0x00000001_0000000C` as "a 32-bit pointer
|
||
with a stale high word" and offered an emulator register bug as one of two
|
||
readings. **Both readings were wrong, and the crash dump itself says so** — it
|
||
prints the registers, and
|
||
|
||
```
|
||
r25 = 000000000000000C
|
||
```
|
||
|
||
is clean. Xenia maps the 4 GiB guest address space at host `0x1_00000000`, so
|
||
"read at `0x1_0000000C`" is the *host* address of guest address `0x0000000C`.
|
||
The guest simply dereferenced the small integer **12**.
|
||
|
||
**And the access violation is a consequence of the throw, not an independent
|
||
fault.** `sub_823070B0` validates the iterator, and on failure builds the string
|
||
and calls the throw at `0x82307118`; a throw does not return — except here.
|
||
`RtlRaiseException_entry` in this build handles `0xE06D7363` by logging
|
||
"Guest attempted to throw a C++ exception!" and **returning** (guest EH is only
|
||
dispatched under `--eh_dispatch`, which its own cvar help records as disproven
|
||
for this crash). So execution falls out of the throw into the code that assumed
|
||
it would never run:
|
||
|
||
```
|
||
82307118 bl 0x825F23D8 ; throw std::out_of_range("invalid map/set<T> iterator")
|
||
8230711C addi r3, r31, 276 ; <- execution RESUMES here, in this build
|
||
82307120 or r25, r5, r5 ; r5 has been clobbered by the throw call: 0x0C
|
||
82307124 bl 0x8244E2A8
|
||
82307128 lwz r11, 0(r25) ; <- AV, on 12
|
||
```
|
||
|
||
That means the 1 895 stacked crash dialogs are noise from one guest throw, and
|
||
**the event to study is the throw**.
|
||
|
||
## The throw, with the guest's own diagnosis
|
||
|
||
Run with `--cache_throw_diag=true` (a cvar this fork already carries) and the
|
||
guest says everything — the full record is committed as
|
||
[`captures/cache-flush-throw-cold-cache.log`](captures/cache-flush-throw-cold-cache.log):
|
||
|
||
```
|
||
GUEST-THROW type=.?AVout_of_range@std@@ object=702DF950 lr=82612B50
|
||
GUEST-THROW guest stack: 825F2444 8230711C 8245A1BC 8245A86C 824AFFC4
|
||
CACHE-DUMP deque_count=38 list_count=37 map_size=24
|
||
CACHE-DUMP deque hashpairs: [0]D4EA4615:E46EE8CA [1]69D8E45C:E534FFEA … [37]AAB216C3:A2C8C185
|
||
CACHE-DUMP flush_sp=702DF9D0 snapshot_keys=1 deque_NOT_in_snapshot=38
|
||
(these are what map::at throws on; in_live_map=1 => added during the flush's
|
||
UNLOCKED window = the TOCTOU race)
|
||
```
|
||
|
||
* The thrown type is **`std::out_of_range`** — the same type the Ready-Room crash
|
||
handoff names, from the same subsystem.
|
||
* The stack is `throw ← sub_823070B0 ← sub_8245A098+0x124 ← sub_8245A5E0+0x28C ←
|
||
sub_824AFF88+0x3C`.
|
||
* The keys are `<container hash>:<entry hash>` pairs, and they are the on-disc
|
||
cache files: `AAB216C3:5C10EAE6` is `\aab216c3\5\c10eae6`, the very path the
|
||
log resolves one line before the crash.
|
||
* **The deque holds a duplicate**: 38 entries, 37 distinct, with
|
||
`AAB216C3:A2C8C185` twice, against a map of 37 keys.
|
||
|
||
The mechanism itself was already worked out by whoever wrote this logger — the
|
||
flush snapshots the map, then walks a deque every entry of which is missing from
|
||
the snapshot but present in the live map, i.e. added inside the flush's unlocked
|
||
window. This note adds no new theory there.
|
||
|
||
## What is new: a 100-second, on-demand trigger
|
||
|
||
The throw is not random. It follows the state of the game's **on-disc cache**
|
||
(`~/.local/share/Xenia/cache/<container>/…`, the `\aab216c3\…` device):
|
||
|
||
| run | cache state | `GUEST-THROW` | crash dumps |
|
||
|---|---|---|---|
|
||
| A | complete (6 files) | **0** | 0 |
|
||
| B | directory moved aside — cold | **1** | 1 895 |
|
||
| C | partially rebuilt (1 file + a `.tmp`) | **1** | 0 |
|
||
| D | the original 6-file cache restored | **0** | 0 |
|
||
| E | cold **and** `--mem_watch=false` | **1** | 2 437 |
|
||
|
||
All four reached the same boot stage (each resolves the same `87719002` /
|
||
`aab216c3` cache entries; the warm runs went *further*, so this is not "warm runs
|
||
stopped early"). Runs B and C throw at the same point in the boot, around 100 s
|
||
in, long before anything a player would call gameplay.
|
||
|
||
Run E is the important one, and it **withdraws a claim this note made yesterday**.
|
||
The earlier version said "with `--mem_watch=false` the crash does not happen at
|
||
all", which named the handoff's suspect #1 as measured. That comparison was
|
||
confounded: every `--mem_watch=false` run so far had also had a *warm* cache.
|
||
Holding the cache cold and turning the probe off, the guest throws anyway — so
|
||
**`mem_watch` is not the trigger for this crash**, and the variable that is, is
|
||
the cache.
|
||
|
||
So a suspect in the handoff's bisection plan no longer costs "one build plus one
|
||
Ready-Room run": move the cache directory aside and boot. Note run C — the throw
|
||
happened with **no** access violation behind it, which is why counting crash
|
||
dialogs is the wrong signal and `grep GUEST-THROW` is the right one.
|
||
|
||
**Stated as not settled:** n = 2 on the warm side, n = 3 on the incomplete side,
|
||
one box, one build; and the elimination of `mem_watch` is for *this* throw, not
|
||
necessarily for the Ready-Room one, which nothing here has re-run. And this says
|
||
nothing about *why* the deque grows during the flush — whether that race is
|
||
reachable on hardware or is an artifact of emulator timing (the handoff's
|
||
position) is exactly the open question, and a cheap trigger is only a tool for
|
||
answering it.
|
||
|
||
## The other crash PC, for completeness
|
||
|
||
The one unreproduced crash after an Ⓐ press was at `0x824578A0`, in
|
||
`sub_82457780` (`0x82457780..0x82457958`, one caller, `sub_82457038`). It is an
|
||
unrolled **4 × 16-bit copy loop**:
|
||
|
||
```
|
||
82457890 lhz r6, 0(r10) 82457898 lhz r4, 4(r10)
|
||
82457894 lhz r5, 2(r10) 8245789C lhz r10, 6(r10)
|
||
824578A0 sth r6, 0(r9) <-- FAULT (a STORE, not a load)
|
||
```
|
||
|
||
so a bad *destination*, in what looks like a small block copy — a different
|
||
failure from the tree erase above, and with one observation it stays at that.
|
||
|
||
## Why this matters beyond the blocker
|
||
|
||
The Ready-Room crash costs a full mission to reproduce, which is why its
|
||
bisection plan in the handoff is written as "one build + one Ready-Room run" per
|
||
suspect. If this title-screen crash is the same defect, each suspect costs **40
|
||
seconds** instead, and suspect #1 (`--mem_watch=false`) is already measured here:
|
||
it removes the crash.
|