summaryrefslogtreecommitdiffstats
path: root/DEBUG_NOTES.md
diff options
context:
space:
mode:
Diffstat (limited to 'DEBUG_NOTES.md')
-rw-r--r--DEBUG_NOTES.md177
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 @@
3Handoff state: **HEAD = `ab633ce`**; the mystery below is SOLVED and the 3Handoff state: **HEAD = `ab633ce`**; the mystery below is SOLVED and the
4verify rework is committed on top (see git log). 4verify 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
101. `capture_memory_map` (main.rs, pre-EBS) → `init_heap` builds the free
11 list from the raw map; `map_key` stashed.
122. `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.
153. `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.
204. 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
28a FRESH EBS key WITHOUT rebuilding the free list (`refresh_map_key`, the
29free list is the authoritative live-allocation state). Verified in QEMU
30with a forced EBS failure: `verify: ok`, `probe free=false`, `flhead
31in_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
311. **(A) scroll-crash family** — heap allocator returns an in-heap block whose 651. **(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.
332. **(B) 0xAA family** — freed garbage pointer `0xaaaaaa00aaaaaa`; the memory at 672. **(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```
206heapdbg: probe@+0x443e0 free=YES w0=203a7476 w1=78302063
207heapdbg: 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
156New image puts on screen (markers are **bottom-anchored** now — they survive 226New image puts on screen (markers are **bottom-anchored** now — they survive
157the banner rows 0–1, the prompt row 2, AND a stale crash.log replay at rows 227the banner rows 0–1, the prompt row 2, AND a stale crash.log replay at rows
1582+; use `gop::bottom_row(off)` to place any future ones): 2282+; use `gop::bottom_row(off)` to place any future ones):
159 229
1601. **Last row (bottom_row(0))**: `gop: shadow {ptr:#x} {MiB}` vs 2301. **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
1642. **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). 2362. **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 2383. **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)?
1703. If it crashes: the full guard band (`hdr:` + all four `mem:` lines, 16 stack 2404. **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 2425. Also: `vt: c {ptr} cap=… ok|GARBAGE | r {ptr} ok` marker (was
173Serial-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`?
175the `klog` shell command. 2456. If it crashes: the full guard band (`hdr:` + all four `mem:` lines, 16
246 stack words) plus the bottom markers if still visible.
247
248Serial-side (QEMU only): the boot heapdbg values are mirrored to serial
249(`heapdbg: probe free=… shadow=… freed=… fb_in_heap=… flhead=… in_shadow=…`)
250and captured in the klog ring — a healthy OptiPlex boot can also dump them
251with 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
1971. **Flash to OptiPlex** and relay the two bottom markers: shadow state (last 2731. **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.
2012. Reattach the window-manager milestone once the crash family is resolved. 2772. 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.
2793. 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:
204no further QEMU-side investigation is needed.) 282`verify: ok`, probe NOT free, shadow base NOT in free list, full shell
283sequence clean. `0x00AAAAAA` = gray text colour; shadow far rows stay 0.)