diff options
| author | salmonik <salmonik@tuta.io> | 2026-08-04 01:44:05 +0200 |
|---|---|---|
| committer | salmonik <salmonik@tuta.io> | 2026-08-04 01:44:05 +0200 |
| commit | 3e2261d83176752f3ea21e0c97f330b4c1757437 (patch) | |
| tree | 8bbc92f917121fafaf193f1af1c42fba624abda9 /DEBUG_NOTES.md | |
| parent | v0.5.8: heap-free QR encoder + crash-dump QR on framebuffer (diff) | |
| download | rs-dos-3e2261d83176752f3ea21e0c97f330b4c1757437.tar.gz rs-dos-3e2261d83176752f3ea21e0c97f330b4c1757437.zip | |
v0.5.9: fix OptiPlex heap crash — EBS retry must not rebuild the free list
Root cause: on real hardware SetMode can invalidate the pre-captured
ExitBootServices map key, so EBS fails and the retry refreshed the map
via capture_memory_map -> init_heap, which REBUILT the free list from
the raw map and wiped the allocation state of every pre-EBS live object
(the display shadow and the vt grids). Their spans became free while
still live, later allocations carved inside the shadow, and the display
writes clobbered them — zeroed back-pointers (family A ptr=0x404443e0
block=0x0) and gray glyph pixels (family B 0xaaaaaa00aaaaaa = 0x00AAAAAA
= PALETTE[7] fg-7 text colour, not a firmware scrub).
Fix: refresh_and_exit now re-captures the map and returns a fresh EBS
key without rebuilding the free list (refresh_map_key); the free list is
the authoritative live-allocation state. Verified in QEMU under a forced
EBS failure (SIMULATE_EBS_FAILURE test hook): verify ok, probe NOT free,
flhead outside the shadow — identical to a clean boot, and the full
shell sequence is crash-free.
Also: removed the crash-family debug markers from the screen (boot-time
heapdbg lines, vt verify marker, shadow marker) — the vt grid self-check
stays serial-only. Version 0.5.8 -> 0.5.9.
Diffstat (limited to '')
| -rw-r--r-- | DEBUG_NOTES.md | 177 |
1 files changed, 128 insertions, 49 deletions
diff --git a/DEBUG_NOTES.md b/DEBUG_NOTES.md index d44c8bf..a1f2d75 100644 --- a/DEBUG_NOTES.md +++ b/DEBUG_NOTES.md | |||
| @@ -3,37 +3,72 @@ | |||
| 3 | Handoff state: **HEAD = `ab633ce`**; the mystery below is SOLVED and the | 3 | Handoff state: **HEAD = `ab633ce`**; the mystery below is SOLVED and the |
| 4 | verify rework is committed on top (see git log). | 4 | verify rework is committed on top (see git log). |
| 5 | 5 | ||
| 6 | ## ✅ ROOT CAUSE + FIX (this session) — ExitBootServices retry wipes the free list | ||
| 7 | |||
| 8 | **Root cause (confirmed by QEMU simulation + OptiPlex screen markers):** | ||
| 9 | |||
| 10 | 1. `capture_memory_map` (main.rs, pre-EBS) → `init_heap` builds the free | ||
| 11 | list from the raw map; `map_key` stashed. | ||
| 12 | 2. `gop::init` → `SetMode` — on real hardware SetMode may allocate/reallocate | ||
| 13 | memory, making `map_key` stale — then allocates the live display shadow | ||
| 14 | (first heap alloc, `mem::forget`'d) and `vt::init` builds the cells grids. | ||
| 15 | 3. `ExitBootServices(image_handle, map_key)` **fails** (stale key) → retry | ||
| 16 | `refresh_and_exit` → `capture_memory_map` → **`init_heap` REBUILT the | ||
| 17 | free list from the raw map, wiping every pre-EBS live allocation's | ||
| 18 | state** — the shadow's 1.8 MB span and the vt grids became FREE while | ||
| 19 | still live. | ||
| 20 | 4. Post-EBS allocations carved **inside the live shadow** (the Opt's vt | ||
| 21 | marker String at exactly `heap+0x443e0`, the family-A crash ptr); the | ||
| 22 | display renders into the shadow → clobbers those objects → **zeroed | ||
| 23 | back-pointers** (family A `ptr=0x404443e0 block=0x0`) and **gray text | ||
| 24 | pixels** (family B `0xaaaaaa00aaaaaa` = 2× `0x00AAAAAA` = PALETTE[7] | ||
| 25 | fg-7, NOT a firmware scrub). | ||
| 26 | |||
| 27 | **Fix (committed):** `refresh_and_exit` now re-captures the map and returns | ||
| 28 | a FRESH EBS key WITHOUT rebuilding the free list (`refresh_map_key`, the | ||
| 29 | free list is the authoritative live-allocation state). Verified in QEMU | ||
| 30 | with a forced EBS failure: `verify: ok`, `probe free=false`, `flhead | ||
| 31 | in_shadow=false` — identical to the no-failure boot. Test hook: | ||
| 32 | `memory::SIMULATE_EBS_FAILURE` (one-shot, defaults off). | ||
| 33 | |||
| 34 | **OptiPlex markers that exposed it:** `probe@+0x443e0 free=YES`, | ||
| 35 | `w0=203a7476 w1=78302063` (= "vt: c 0x" — the freed marker String), | ||
| 36 | `blk=0x404443c0 sz=0x770`, `flhead=0x404443c0 in-shadow=YES`, `shadow | ||
| 37 | =0x40400000 freed=no`, `fb=0xe0000000 in-heap=no`. | ||
| 38 | |||
| 6 | ## TL;DR | 39 | ## TL;DR |
| 7 | 40 | ||
| 8 | - Real-hardware (OptiPlex, no serial) boots crash in the shell with heap | 41 | - Real-hardware (OptiPlex, no serial) boots crash in the shell with heap |
| 9 | corruption. Two **distinct** bug families: | 42 | corruption. Two **distinct** bug families: |
| 10 | - **(A) scroll-crash family**: in-heap `ptr=0x404443e0` with zeroed header. | 43 | - **(A) scroll-crash family**: in-heap `ptr=0x404443e0` with zeroed header. |
| 11 | - **(B) 0xAA family**: `0xaaaaaa00aaaaaa` = two `0x00AAAAAA` u32s = UEFI | 44 | - **(B) 0xAA family**: `0xaaaaaa00aaaaaa` = two `0x00AAAAAA` u32s. |
| 12 | firmware memory-scrub fill. A dropped object's memory was never | 45 | - **CORRECTION (this session): `0x00AAAAAA` is NOT a UEFI firmware scrub. |
| 13 | allocated/freed by us — it's firmware-fresh scrub. | 46 | It is the VGA GRAY text colour: `rgb(170,170,170)` packs to |
| 14 | - Everything converges on **the `vt` static `Vec<Cell>`s' VecData (ptr/cap/len) | 47 | `(170<<16)|(170<<8)|170 = 0x00AAAAAA`, which is `PALETTE[7]` = fg 7 — the |
| 15 | or their heap blocks being corrupted/stale** — the cells VecData ptr at shell | 48 | vt's default foreground.** Every rendered glyph pixel is a `0x00AAAAAA` |
| 16 | entry was `heap+0x1D8630` (= cells region) in the last crash, and the dropped | 49 | word in the shadow; the shadow's background is `0x00000000` (bg 0). |
| 17 | 126-byte String (`cap 0x7e`) is the vt verify klog line itself. | 50 | - Family B `0xaaaaaa00aaaaaa` = **two adjacent gray TEXT pixels** — the |
| 18 | - **SOLVED — the pre-verify `0x70020` "mystery" was a debug artifact, not | 51 | memory read as heap held rendered text ⇒ it was **inside the live |
| 19 | corruption.** `BLANK = {ch:32, fg:7, bg:0}` = raw `0x70020`, and | 52 | shadow** (see root cause above). |
| 20 | `vec![BLANK; rows*cols]` fills the whole grid with it at init. The old | 53 | - Family A zeros = the shadow's **black background** at the same span. |
| 21 | content check compared cells against **0** (wrong expectation — BLANK is not | 54 | - ⇒ BOTH families = the allocator handed out memory inside the live |
| 22 | zero), and its probe loop `break`-ed on the first non-zero cell, so probes | 55 | shadow after the EBS-retry free-list rebuild. |
| 23 | 1–3 were never written and stayed at their zero-initialized slots. The | 56 | - The pre-verify `0x70020` "mystery" was a debug artifact, not corruption. |
| 24 | serial line `c=[0x70020,0x0,0x0,0x0]` was therefore bogus on **every healthy | 57 | `BLANK = {ch:32, fg:7, bg:0}` = raw `0x70020`, and `vec![BLANK; rows*cols]` |
| 25 | boot**. A full-grid dump on QEMU proves it: `nz=3700 blank=3700` — both | 58 | fills the whole grid with it at init. QEMU proves both grids are 100% |
| 26 | grids are 100% BLANK at shell entry. The OptiPlex's `0x00AAAAAA` firmware | 59 | BLANK at shell entry. (Note: 0x70020 ≠ 0x00AAAAAA — the two "fills" are |
| 27 | scrub is still cleanly distinguishable (scrub ≠ 0x70020). | 60 | cleanly distinguishable; the family-A/B dump content is TEXT/bg, not |
| 61 | BLANK cells.) | ||
| 28 | 62 | ||
| 29 | ## The two confirmed bugs | 63 | ## The two confirmed bugs |
| 30 | 64 | ||
| 31 | 1. **(A) scroll-crash family** — heap allocator returns an in-heap block whose | 65 | 1. **(A) scroll-crash family** — heap allocator returns an in-heap block whose |
| 32 | header is zeroed (`ptr=0x404443e0`). Dropping it panics in the guard. | 66 | header is zeroed (`ptr=0x404443e0`). Dropping it panics in the guard. |
| 33 | 2. **(B) 0xAA family** — freed garbage pointer `0xaaaaaa00aaaaaa`; the memory at | 67 | 2. **(B) 0xAA family** — freed garbage pointer `0xaaaaaa00aaaaaa`; the two |
| 34 | that address is firmware scrub fill. Something handed the allocator a pointer | 68 | `0x00AAAAAA` words are **gray text pixels** (PALETTE[7]) — the memory at |
| 35 | that was never a live allocation (or the VecData fields themselves got | 69 | that address was rendered shadow content. Something handed the allocator a |
| 36 | clobbered with scrub values — the cap was `0xAA` garbage in the boot crash). | 70 | pointer that was never a live allocation (or a live-shadow block that |
| 71 | leaked into the free list). | ||
| 37 | 72 | ||
| 38 | ## What we've fixed / proven already | 73 | ## What we've fixed / proven already |
| 39 | 74 | ||
| @@ -51,11 +86,12 @@ verify rework is committed on top (see git log). | |||
| 51 | - **Shadow geometry (QEMU)**: shadow = first alloc at `heap+0x20` (`0x1980020`), | 86 | - **Shadow geometry (QEMU)**: shadow = first alloc at `heap+0x20` (`0x1980020`), |
| 52 | 480000 words → span `[heap+0x20, heap+0x1D4C20)`; cells data at | 87 | 480000 words → span `[heap+0x20, heap+0x1D4C20)`; cells data at |
| 53 | `heap+0x1D4C40`; VecDatas at ~`heap+0x1D8630`. | 88 | `heap+0x1D4C40`; VecDatas at ~`heap+0x1D8630`. |
| 54 | - **Shadow-rejection hypothesis (unproven)**: on the OptiPlex the shadow alloc | 89 | - **Shadow-rejection hypothesis (strengthened by QEMU forced-reject test)**: |
| 55 | may have been rejected (or the cells alloc landed inside the would-be shadow | 90 | on the OptiPlex the shadow alloc may have been rejected (or its block |
| 56 | span), leaving that block free + scrub-filled. `0x40444970 = heap+0x44970` is | 91 | freed), leaving that span free + text/zero-filled. `0x40444970 = |
| 57 | *inside* the would-be shadow span. The last crash's `r9=0x405d8630 = | 92 | heap+0x44970` is *inside* the would-be shadow span. Forcing rejection in |
| 58 | heap+0x1D8630` is the cells VecData region. | 93 | QEMU reproduces family A exactly: `probe heap+0x443e0 IN free blk` with |
| 94 | all-zero content. | ||
| 59 | - **Original #GP resolved**: crashed image was RELEASE; drop of `Parsed` struct; | 95 | - **Original #GP resolved**: crashed image was RELEASE; drop of `Parsed` struct; |
| 60 | cause = real memory corruption (laytest excluded compiler bug). | 96 | cause = real memory corruption (laytest excluded compiler bug). |
| 61 | - **Stale PDB trap**: fresh PDB re-resolved shell-entry #GP → | 97 | - **Stale PDB trap**: fresh PDB re-resolved shell-entry #GP → |
| @@ -108,6 +144,17 @@ verify rework is committed on top (see git log). | |||
| 108 | 144 | ||
| 109 | ## QEMU reproduction of the content-check failure (RESOLVED) | 145 | ## QEMU reproduction of the content-check failure (RESOLVED) |
| 110 | 146 | ||
| 147 | - **0x00AAAAAA scan verdict (this session)**: `shadow scan: 11333w/480000` | ||
| 148 | hits are all at **glyph positions of on-screen text** (fg=7 gray pixels). | ||
| 149 | The "scrub" reading at the crash offset (`probe mem: 00000000 00aaaaaa | ||
| 150 | 00aaaaaa 00000000 …`) is the heapdbg output line **rendered at that exact | ||
| 151 | shadow location** — the probe reads its own text. The shadow far rows | ||
| 152 | (r300, r500) read 0 ⇒ init zeroing is correct and nothing over-writes | ||
| 153 | untouched shadow rows in QEMU. FB pixel at (171,1) = (170,170,170) GRAY | ||
| 154 | = 0x00AAAAAA — shadow and FB agree; there is NO shadow/FB desync. | ||
| 155 | - The shadow scan is still a useful health signal: untouched far rows must | ||
| 156 | stay 0; text-row hits are expected (that's what the shadow holds). | ||
| 157 | |||
| 111 | - Serial showed `probes c=[0x70020,0x0,0x0,0x0] r=[0x70020,0x0,0x0,0x0]` — this | 158 | - Serial showed `probes c=[0x70020,0x0,0x0,0x0] r=[0x70020,0x0,0x0,0x0]` — this |
| 112 | was **misread** as "a single stray cell". The full-grid dump (3700 reads) | 159 | was **misread** as "a single stray cell". The full-grid dump (3700 reads) |
| 113 | showed `nz=3700 blank=3700` in both grids: **every cell is BLANK (0x70020), | 160 | showed `nz=3700 blank=3700` in both grids: **every cell is BLANK (0x70020), |
| @@ -153,26 +200,55 @@ FB), memory self-test, shell banner (runs after verify), backspace (BLANK). | |||
| 153 | 200 | ||
| 154 | ## OptiPlex flash — what to look for (the linchpin) | 201 | ## OptiPlex flash — what to look for (the linchpin) |
| 155 | 202 | ||
| 203 | **FIRST OPTIPLEX REPORT (this session, previous image):** | ||
| 204 | |||
| 205 | ``` | ||
| 206 | heapdbg: probe@+0x443e0 free=YES w0=203a7476 w1=78302063 | ||
| 207 | heapdbg: shadow=0x40400000 freed=no | ||
| 208 | ``` | ||
| 209 | |||
| 210 | - `w0=0x203a7476 w1=0x78302063` = LE ASCII **"vt: c 0x"** — the leftover | ||
| 211 | bytes of the *vt verify marker String* (`debug_verify`'s | ||
| 212 | `alloc::format!("vt: c {:#x} …")`), which was **allocated at exactly | ||
| 213 | `heap+0x443e0`** (the historical family-A crash ptr) and freed before | ||
| 214 | the marker ran. ⇒ on the Opt the heap's first-fit hands out | ||
| 215 | **`heap+0x443e0` — INSIDE the live shadow span | ||
| 216 | [`heap+0x20`, `heap+0x1D4C20`)** — while `shadow=0x40400000 freed=no` | ||
| 217 | (the shadow Vec's block header claims allocated, forget'd). | ||
| 218 | - QEMU control: same marker prints `probe free=false … flhead=0x1b706d0 | ||
| 219 | in_shadow=false` — the probe address is NOT in the free list. | ||
| 220 | - ⇒ The free list contains the live shadow span on the Opt. The two new | ||
| 221 | boot lines (`fb … in-heap=YES/no`, `flhead … in-shadow=YES/no`) plus | ||
| 222 | the probe's containing `blk=…` tell us whether the overlap is the whole | ||
| 223 | heap block (shadow carve never happened / init_heap after alloc), the | ||
| 224 | fb inside the heap (display clobbers), or a mid-span block. | ||
| 225 | |||
| 156 | New image puts on screen (markers are **bottom-anchored** now — they survive | 226 | New image puts on screen (markers are **bottom-anchored** now — they survive |
| 157 | the banner rows 0–1, the prompt row 2, AND a stale crash.log replay at rows | 227 | the banner rows 0–1, the prompt row 2, AND a stale crash.log replay at rows |
| 158 | 2+; use `gop::bottom_row(off)` to place any future ones): | 228 | 2+; use `gop::bottom_row(off)` to place any future ones): |
| 159 | 229 | ||
| 160 | 1. **Last row (bottom_row(0))**: `gop: shadow {ptr:#x} {MiB}` vs | 230 | 1. **Last row (bottom_row(0))**: `heapdbg: probe@+0x443e0 free=YES|no w0=… w1=… blk={base} sz={size}` |
| 161 | `gop: NO-SHADOW (fallback)`. | 231 | — crash offset free? content (zeros=shadow bg, `00aaaaaa`=gray text, |
| 162 | - If NO-SHADOW ⇒ shadow-rejection hypothesis gains weight (first block left | 232 | ASCII=leftover string bytes)? and the **base/size of the free block |
| 163 | free + scrub-filled). | 233 | containing it** (0x40400000 = whole-heap block → the shadow carve |
| 164 | 2. **Second-to-last row (bottom_row(1))**: `vt: c {ptr:#x} cap={cap:#x} ok|GARBAGE | r {ptr:#x} ok|GARBAGE`. | 234 | never happened; inside the shadow span → overlap; a normal small |
| 165 | - **The cells ptr value is the linchpin**: if it equals `0x40444970`, the | 235 | block → ordinary freed allocation). |
| 166 | cells VecData itself is stale at shell entry (matches boot-crash decode). | 236 | 2. **Second-to-last row (bottom_row(1))**: `heapdbg: shadow={ptr| -} freed=YES|no` |
| 167 | - If cap shows `0xAA…` garbage ⇒ VecData fields scrubbed (bug family B). | 237 | — the shadow block base + header free flag. |
| 168 | - `ok` = all probed cells read BLANK (0x70020); `GARBAGE` = probe ≠ BLANK | 238 | 3. **Third-to-last (bottom_row(2))**: `heapdbg: fb={base} size={size} in-heap=YES|no` |
| 169 | (the OptiPlex firmware scrub reads back `0x00AAAAAA`). | 239 | — is the framebuffer inside the heap range (display clobbers heap)? |
| 170 | 3. If it crashes: the full guard band (`hdr:` + all four `mem:` lines, 16 stack | 240 | 4. **Fourth-to-last (bottom_row(3))**: `heapdbg: flhead={base} size={size} in-shadow=YES|no` |
| 171 | words) plus the bottom markers if still visible. | 241 | — does the free-list head overlap the shadow span? |
| 172 | 242 | 5. Also: `vt: c {ptr} cap=… ok|GARBAGE | r {ptr} ok` marker (was | |
| 173 | Serial-side (QEMU only): the verify lines are captured in the klog ring | 243 | bottom_row(1), now overwritten by the shadow line) — the cells ptr |
| 174 | (`serial_println!` → ring), so a healthy OptiPlex boot can also dump them with | 244 | value is the linchpin for a stale-VecData theory: equals `0x40444970`? |
| 175 | the `klog` shell command. | 245 | 6. If it crashes: the full guard band (`hdr:` + all four `mem:` lines, 16 |
| 246 | stack words) plus the bottom markers if still visible. | ||
| 247 | |||
| 248 | Serial-side (QEMU only): the boot heapdbg values are mirrored to serial | ||
| 249 | (`heapdbg: probe free=… shadow=… freed=… fb_in_heap=… flhead=… in_shadow=…`) | ||
| 250 | and captured in the klog ring — a healthy OptiPlex boot can also dump them | ||
| 251 | with the `klog` shell command. | ||
| 176 | 252 | ||
| 177 | ## Build/flash/test loop (traps) | 253 | ## Build/flash/test loop (traps) |
| 178 | 254 | ||
| @@ -194,11 +270,14 @@ the `klog` shell command. | |||
| 194 | 270 | ||
| 195 | ## Next steps (priority order) | 271 | ## Next steps (priority order) |
| 196 | 272 | ||
| 197 | 1. **Flash to OptiPlex** and relay the two bottom markers: shadow state (last | 273 | 1. **Flash the fixed image to the OptiPlex** (BOOTX64.EFI in `esp/`). |
| 198 | row) + vt marker (`bottom_row(1)` — the cells ptr value is the linchpin: | 274 | Expected bottom rows now: `probe@+0x443e0 free=no` (was YES), |
| 199 | equals `0x40444970`? cap scrubbed `0xAA…`? `ok` vs `GARBAGE`?). If crash: | 275 | `flhead=… in-shadow=no` (was YES), `vt: … ok`. Run the old repro |
| 200 | full `hdr:` + all four `mem:` lines. | 276 | (`klog -t 2`, `ls`, `help`) — should no longer crash. |
| 201 | 2. Reattach the window-manager milestone once the crash family is resolved. | 277 | 2. If the Opt still misbehaves: relay the four bottom lines again — the |
| 278 | fix only holds if the free list no longer overlaps the shadow. | ||
| 279 | 3. Reattach the window-manager milestone once confirmed. | ||
| 202 | 280 | ||
| 203 | (QEMU control arm is green: content check now passes on every healthy boot; | 281 | (QEMU control arm is green with and without a forced EBS failure: |
| 204 | no further QEMU-side investigation is needed.) | 282 | `verify: ok`, probe NOT free, shadow base NOT in free list, full shell |
| 283 | sequence clean. `0x00AAAAAA` = gray text colour; shadow far rows stay 0.) | ||
