From d5f41d6e057300c82b83653b4afadeffb45a9f19 Mon Sep 17 00:00:00 2001 From: salmonik Date: Mon, 3 Aug 2026 01:34:31 +0200 Subject: v0.5.7: fix vt verify content check — expect BLANK (0x70020), not zero MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pre-verify 0x70020 'mystery' was a debug artifact, not corruption: BLANK = {ch:32, fg:7, bg:0} = raw 0x70020, and vec![BLANK; n] fills both grids with it at init. The old check compared cells against 0 and its probe loop break-ed on the first non-zero cell, so probes 1-3 stayed at their zero-initialized slots — c=[0x70020,0,0,0] was bogus on every healthy boot. A full-grid dump proves QEMU grids are 100% BLANK at shell entry (nz=3700 blank=3700). Fix: probes compare against blank_raw (0x70020), record all four values (no early break), probe both cells and rendered, and add a full-grid nz/blank summary line. The OptiPlex firmware 0x00AAAAAA scrub remains cleanly distinguishable (scrub != blank). Markers: the shell banner occupies grid rows 0-1 and the prompt row 2 (proven by screendump), and a stale crash.log replays at rows 2+, so the shadow and vt markers moved to the bottom of the screen via the new gop::text_rows()/bottom_row(off) helpers instead of rows 1-2. QEMU verified: verify: ok every boot; test-msg + test-fault PASS; debug and release builds 0 warnings. --- DEBUG_NOTES.md | 204 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ rsnix/src/gop.rs | 44 +++++++++--- rsnix/src/vt.rs | 132 +++++++++++++++++++++++++++-------- 3 files changed, 344 insertions(+), 36 deletions(-) create mode 100644 DEBUG_NOTES.md diff --git a/DEBUG_NOTES.md b/DEBUG_NOTES.md new file mode 100644 index 0000000..d44c8bf --- /dev/null +++ b/DEBUG_NOTES.md @@ -0,0 +1,204 @@ +# rsdos Debug Notes — heap/cells corruption family (v0.5.7) + +Handoff state: **HEAD = `ab633ce`**; the mystery below is SOLVED and the +verify rework is committed on top (see git log). + +## TL;DR + +- Real-hardware (OptiPlex, no serial) boots crash in the shell with heap + corruption. Two **distinct** bug families: + - **(A) scroll-crash family**: in-heap `ptr=0x404443e0` with zeroed header. + - **(B) 0xAA family**: `0xaaaaaa00aaaaaa` = two `0x00AAAAAA` u32s = UEFI + firmware memory-scrub fill. A dropped object's memory was never + allocated/freed by us — it's firmware-fresh scrub. +- Everything converges on **the `vt` static `Vec`s' VecData (ptr/cap/len) + or their heap blocks being corrupted/stale** — the cells VecData ptr at shell + entry was `heap+0x1D8630` (= cells region) in the last crash, and the dropped + 126-byte String (`cap 0x7e`) is the vt verify klog line itself. +- **SOLVED — the pre-verify `0x70020` "mystery" was a debug artifact, not + corruption.** `BLANK = {ch:32, fg:7, bg:0}` = raw `0x70020`, and + `vec![BLANK; rows*cols]` fills the whole grid with it at init. The old + content check compared cells against **0** (wrong expectation — BLANK is not + zero), and its probe loop `break`-ed on the first non-zero cell, so probes + 1–3 were never written and stayed at their zero-initialized slots. The + serial line `c=[0x70020,0x0,0x0,0x0]` was therefore bogus on **every healthy + boot**. A full-grid dump on QEMU proves it: `nz=3700 blank=3700` — both + grids are 100% BLANK at shell entry. The OptiPlex's `0x00AAAAAA` firmware + scrub is still cleanly distinguishable (scrub ≠ 0x70020). + +## The two confirmed bugs + +1. **(A) scroll-crash family** — heap allocator returns an in-heap block whose + header is zeroed (`ptr=0x404443e0`). Dropping it panics in the guard. +2. **(B) 0xAA family** — freed garbage pointer `0xaaaaaa00aaaaaa`; the memory at + that address is firmware scrub fill. Something handed the allocator a pointer + that was never a live allocation (or the VecData fields themselves got + clobbered with scrub values — the cap was `0xAA` garbage in the boot crash). + +## What we've fixed / proven already + +- **IST=1 stack collision → ROOT CAUSE of ACTIVE_VOL corruption**: vec 14 ran on + `PF_STACK`, a 4 KiB `.bss` static overlapping FAT `ACTIVE_VOL`. Fixed in + `gdt.rs`: heap-allocated 32 KiB IST stacks. (Done, earlier.) +- **AHCI/DMA EXONERATED**: user removed all disks; crashes persisted. +- **All QEMU repro attempts were clean** (mem/klog/tail-crash) until the content + probe upgrade — which tripped the *content check only* on a healthy boot for + the reason above (expectation bug + break bug). Fixed: the check now expects + `blank_raw` (0x70020), records all four probe values, and adds a full-grid + nz/blank summary line. QEMU now reports `verify: ok` on every boot. +- **Clean heap geometry (OptiPlex)**: heap = `0x40400000..0xc7e34000` (~2.2 GB), + boot stack ~1 MiB above heap end. +- **Shadow geometry (QEMU)**: shadow = first alloc at `heap+0x20` (`0x1980020`), + 480000 words → span `[heap+0x20, heap+0x1D4C20)`; cells data at + `heap+0x1D4C40`; VecDatas at ~`heap+0x1D8630`. +- **Shadow-rejection hypothesis (unproven)**: on the OptiPlex the shadow alloc + may have been rejected (or the cells alloc landed inside the would-be shadow + span), leaving that block free + scrub-filled. `0x40444970 = heap+0x44970` is + *inside* the would-be shadow span. The last crash's `r9=0x405d8630 = + heap+0x1D8630` is the cells VecData region. +- **Original #GP resolved**: crashed image was RELEASE; drop of `Parsed` struct; + cause = real memory corruption (laytest excluded compiler bug). +- **Stale PDB trap**: fresh PDB re-resolved shell-entry #GP → + `rsnix::vt::put_byte+0x16a` (`mov %ax,(%rdx,%rcx,4)`) — u16 char at 4-byte + stride into cells buffer via garbage ptr from `r9=0x405d8630`. bt chain: + `shell::run → GopWriter::write_str → fmt::Formatter::pad_integral → + klog::LineBuf::write_str → core::fmt::write → Display(u32)`. +- **Crash decoded**: the dropped object in the last boot crash was a 126-byte + String (`cap 0x7e`) = the vt verify klog line (19-char prefix + 106-char text + + `\n`); `ptr=0x40444970` is STALE (inside the would-be shadow span, back-pointer + never written). + +## Allocator layout (verified, `memory.rs`) + +- `HEADER_SIZE=16`, `MINI_SIZE=8`, `MIN_BLOCK=32`, `MIN_ALIGN=16` +- payload = `align_up(block+24, align)` +- split: rewrites rem header + `free_list_insert` + back-pointer at `payload-8` +- `back_pointer_ok(ptr)` validates `[ptr-8]`; guard v0.5.7 (`0187b80`) reports + + halts on failure; `corrupt` QEMU hook verified. + +## vt grid facts + +- `put_cell(r,c,ch)` sets `ch` + fg/bg from statics `SGR_FG=7`/`SGR_BG=0`. +- Cell raw encoding: `ch | fg<<16 | bg<<24`; BLANK = 0; cursor-inverse blank = + `0x07000000` (bg and fg swapped). **`0x70020` is NOT a cursor-inverse cell** — + it's a literal space with fg=7 (ch=0x20, fg=7, bg=0). +- `flush()` diffs cells vs rendered; cursor pass writes inverse colors into both + FB and `rendered`. +- `term_println(s)` = `gop_print!` + blank line + explicit `serial::write_line`. + Display mirror to serial is NOT automatic for `gop_println!`. +- Boot order after vt init: shadow → boot markers → memory self-test → page + allocator + self-tests → paging adopt + self-test → sched init → + rtc/pci/ahci/fat/fs → **cursor spawn** → **`debug_verify()`** → `shell::run()` + (first banner `rs-dos v0.5.7 …`, then `=====`, then crash-log read). + +## Current committed work (post-`ab633ce`) + +- `gop::boot_marker_at(msg, row)` + `gop::text_rows()` + `gop::bottom_row(off)` + — shadow marker now on the LAST text row, vt verify marker one above it + (both survive the banner, prompt, and crash.log replay). +- `debug_verify()` fixed: compares probes against `blank_raw` (0x70020), not + zero; records all four probe values (no early break); probes BOTH cells and + rendered; adds a full-grid `grids c nz=… blank=… r nz=… blank=…` summary + (serial). Marker format: + `vt: c {ptr:#x} cap={cap:#x} ok|GARBAGE | r {ptr:#x} ok|GARBAGE` at + `bottom_row(1)`. +- QEMU verified: `verify: ok` every boot; screendump shows the banner (gray), + prompt, and both bottom markers. test-msg + test-fault PASS; debug and + release builds 0 warnings. + +## QEMU reproduction of the content-check failure (RESOLVED) + +- Serial showed `probes c=[0x70020,0x0,0x0,0x0] r=[0x70020,0x0,0x0,0x0]` — this + was **misread** as "a single stray cell". The full-grid dump (3700 reads) + showed `nz=3700 blank=3700` in both grids: **every cell is BLANK (0x70020), + the grids are healthy**. The probe array's 1–3 slots were zero-initialized + leftovers from the early-`break` bug. +- Memory dump proves grids are fully healthy on QEMU: cells block base + `0x1b54c20` `{size=0x39f0, free=0}`, back-ptr written; rendered block base + `0x1b58650`; both grids contain the shell banner post-draw. **No heap + corruption on QEMU.** +- QEMU verify geometry: cells ptr `0x1b54c40` cap `0xe74` len `0xe74`; rendered + ptr `0x1b58670`. +- ⇒ `CONTENT-GARBAGE` was never evidence of OptiPlex corruption — the check was + comparing against the wrong expectation. Now: probes compare against + `blank_raw` (0x70020); every probe value is logged; a `grids c nz=… blank=…` + summary is the definitive health signal. + +## The pre-verify `0x70020` at grid(0,0) — MYSTERY SOLVED + +**There was no writer.** `0x70020` is the grid's own init fill: +`BLANK = Cell{ch:32, fg:7, bg:0}` encodes as `0x70020`, and `vt::init` builds +both grids with `vec![BLANK; rows*cols]`. The old content check expected +all-zero cells (wrong), and the probe loop's early `break` made probes 1–3 +look like zeros. Nothing writes a pre-banner space; the shell banner (gray +VGA-7 text, rows 0–1) and the `>` prompt (row 2) are the only vt writes +before the markers. + +Also learned while verifying with a screendump: + +- The shell banner occupies grid rows **0 and 1** (motd + `=====` line), and + the prompt sits at row 2 — so a marker at FB row 1 (the old shadow marker) + is **clobbered** by the banner, and row 2's first glyphs get eaten by the + prompt + cursor. Markers whose values matter now live at the **bottom** + (`gop::bottom_row(0)` = last row, `bottom_row(1)` = second-to-last), which + also survive a stale crash.log replay (~20 lines at grid rows 2+). +- Banner text renders VGA gray `0xAAAAAA` (fg 7), boot markers white `0xFFFFFF` + — a white-only pixel matcher misses the banner. QEMU screendump decode of + the bottom rows: `vt: c 0x1b54c40 cap=0xe74 ok | r 0x1b58670 ok` and + `gop: shadow 0x1980020 1.83 MiB`. + +**Excluded candidates (all still true, now moot):** cursor task (FB/shadow +only), flush cursor-inverse pass (0x07000000 ≠ 0x70020), boot markers (direct +FB), memory self-test, shell banner (runs after verify), backspace (BLANK). + +## OptiPlex flash — what to look for (the linchpin) + +New image puts on screen (markers are **bottom-anchored** now — they survive +the banner rows 0–1, the prompt row 2, AND a stale crash.log replay at rows +2+; use `gop::bottom_row(off)` to place any future ones): + +1. **Last row (bottom_row(0))**: `gop: shadow {ptr:#x} {MiB}` vs + `gop: NO-SHADOW (fallback)`. + - If NO-SHADOW ⇒ shadow-rejection hypothesis gains weight (first block left + free + scrub-filled). +2. **Second-to-last row (bottom_row(1))**: `vt: c {ptr:#x} cap={cap:#x} ok|GARBAGE | r {ptr:#x} ok|GARBAGE`. + - **The cells ptr value is the linchpin**: if it equals `0x40444970`, the + cells VecData itself is stale at shell entry (matches boot-crash decode). + - If cap shows `0xAA…` garbage ⇒ VecData fields scrubbed (bug family B). + - `ok` = all probed cells read BLANK (0x70020); `GARBAGE` = probe ≠ BLANK + (the OptiPlex firmware scrub reads back `0x00AAAAAA`). +3. If it crashes: the full guard band (`hdr:` + all four `mem:` lines, 16 stack + words) plus the bottom markers if still visible. + +Serial-side (QEMU only): the verify lines are captured in the klog ring +(`serial_println!` → ring), so a healthy OptiPlex boot can also dump them with +the `klog` shell command. + +## Build/flash/test loop (traps) + +- Build 0 warnings, edition 2024, `no_std`, `x86_64-unknown-uefi`, workspace + v0.5.7. Zero new deps. +- Real-hardware boot chain: rsboot at `EFI/BOOT/BOOTX64.EFI` → kernel at + `bzImage`. QEMU dev loop boots kernel as BOOTX64.EFI. +- CRASHLOG stick must be FAT32; `mdir` grep gotcha: match `crash` + case-insensitively. +- **Stale qemu holds flock** → `pkill -9 -f 'qemu[-]system'` in a SEPARATE + command; `rm -f esp/NvVars` between boots. +- Use repo `scripts/` infra: test-msg/test-fault/test-mouse; monitor socket; HMP + `mouse_move`. +- Fault-context serial rule: never `serial_println!` in ISR/fault code; use + `serial::write_raw`; guard report must not allocate (stack `FmtBuf`). +- Marker on row 0 gets overwritten by the shell MOTD — use `boot_marker_at(msg, row>0)`. +- Stale PDBs misname symbols — re-resolve with a fresh PDB per build (PDB math + is decimal); `r9` = struct base with Vec layout `{ptr@0, cap@8, len@16}`. + +## Next steps (priority order) + +1. **Flash to OptiPlex** and relay the two bottom markers: shadow state (last + row) + vt marker (`bottom_row(1)` — the cells ptr value is the linchpin: + equals `0x40444970`? cap scrubbed `0xAA…`? `ok` vs `GARBAGE`?). If crash: + full `hdr:` + all four `mem:` lines. +2. Reattach the window-manager milestone once the crash family is resolved. + +(QEMU control arm is green: content check now passes on every healthy boot; +no further QEMU-side investigation is needed.) diff --git a/rsnix/src/gop.rs b/rsnix/src/gop.rs index 8e804e5..012a9d0 100644 --- a/rsnix/src/gop.rs +++ b/rsnix/src/gop.rs @@ -293,13 +293,16 @@ pub fn init(gop: &mut GraphicsOutputProtocol) { .map(|c| core::str::from_utf8(c).unwrap_or("?")) .collect(); dump_lines(&lines); - crate::gop::boot_marker("gop: NO-SHADOW (fallback mode)"); + crate::gop::boot_marker_at("gop: NO-SHADOW (fallback)", bottom_row(0)); } else { - crate::gop::boot_marker(&alloc::format!( - "gop: shadow {:#x} {:.2} MiB", - SHADOW as usize, - swords as f64 * 4.0 / 1048576.0 - )); + crate::gop::boot_marker_at( + &alloc::format!( + "gop: shadow {:#x} {:.2} MiB", + SHADOW as usize, + swords as f64 * 4.0 / 1048576.0 + ), + bottom_row(0), + ); } } } @@ -313,6 +316,16 @@ pub fn init(gop: &mut GraphicsOutputProtocol) { /// direct-display glyph path (the shadow may not exist yet in early /// boot); the shell banner overwrites row 0 at first paint. pub fn boot_marker(msg: &str) { + boot_marker_at(msg, 0); +} + +/// boot_marker at an explicit text row. The shell's first paint +/// occupies grid rows 0 (motd) and 1 (=== banner) and the prompt sits +/// at row 2 — markers whose *values* matter after boot (shadow state, +/// vt grid pointers) are anchored to the bottom of the screen via +/// `bottom_row`, which also survives a stale crash.log replay (the +/// fault band is ~20 lines starting at grid row 2). +pub fn boot_marker_at(msg: &str, row: usize) { // Record the stage so a later panic band can show how far boot got. unsafe { let n = msg.len().min(STAGE_MAX); @@ -323,24 +336,39 @@ pub fn boot_marker(msg: &str) { let Some(fb) = fb().as_ref() else { return; }; + if row >= fb.height / 16 { + return; + } let cols = fb.width / 8; let white = (0xFFu8, 0xFFu8, 0xFFu8); let black = (0x00u8, 0x00u8, 0x00u8); let mut c = 0usize; for &b in msg.as_bytes().iter().take(cols) { if b < 0x80 { - blit_glyph(c, 0, b as u16, white, black); + blit_glyph(c, row, b as u16, white, black); c += 1; } } // Blank the rest of the row so a shorter message can't leave stale // glyphs behind. while c < cols { - blit_glyph(c, 0, b' ' as u16, white, black); + blit_glyph(c, row, b' ' as u16, white, black); c += 1; } } +/// Text-row count of the active framebuffer (each row is 16 px tall). +pub fn text_rows() -> usize { + fb().as_ref().map(|f| f.height / 16).unwrap_or(0) +} + +/// Row index of the `off`-th text row from the bottom (0 = last row). +/// Bottom-anchored markers survive the shell banner + prompt at the top +/// and a stale crash.log replay below it. +pub fn bottom_row(off: usize) -> usize { + text_rows().saturating_sub(1 + off) +} + // --------------------------------------------------------------------------- // Public text API — the text surface now lives in `crate::vt`; these wrappers // keep callers (shell, macros) unchanged. diff --git a/rsnix/src/vt.rs b/rsnix/src/vt.rs index 2906258..6e1f12f 100644 --- a/rsnix/src/vt.rs +++ b/rsnix/src/vt.rs @@ -173,48 +173,124 @@ pub fn debug_verify() { }) .unwrap_or(false); // Content check: at shell entry nothing has been printed yet, so - // every cell must still be BLANK (all-zero). A stale cells data - // pointer that happens to be in-heap still passes the range - // checks (len/cap look fine) but its "cells" read back as the - // underlying memory's leftover fill — the OptiPlex shows the - // firmware 0x00AAAAAA scrub there. This catches that. + // every cell must still hold the grid's init fill. NOTE: that + // fill is BLANK (space + fg 7 + bg 0 = raw 0x70020), NOT zero — + // `vec![BLANK; n]` fills the grid with BLANK, and all boot + // output to this point is serial-only (boot markers are a + // direct-FB blit, never the vt grid). The v0.5.7 check + // compared against 0 and therefore tripped on every healthy + // boot (the "0x70020 at grid(0,0)" mystery — the grid's own + // init value, with the probe loop's early `break` leaving the + // other three probe slots as zero-initialized). A stale cells + // data pointer that happens to be in-heap still passes the + // range checks (len/cap look fine) but its "cells" read back as + // the underlying memory's leftover fill — the OptiPlex shows + // the firmware 0x00AAAAAA scrub there. BLANK (0x70020) vs + // scrub (0x00AAAAAA) is cleanly distinguishable. + let blank_raw = BLANK.ch as u32 | ((BLANK.fg as u32) << 16) | ((BLANK.bg as u32) << 24); let mut content_ok = true; + let mut rcontent_ok = true; + let mut c_probes_raw: [u32; 4] = [0; 4]; + let mut r_probes_raw: [u32; 4] = [0; 4]; if heap_ok && c.len() == total && total > 0 { - let mut i = 0usize; - // Sample the first cell, the last cell, and a few interior + // Sample the first cell, the last cell, and two interior // cells — reading the whole grid here would be ~60 KiB of - // checks at every boot for no real benefit. + // checks at every boot for no real benefit. All four + // probes are recorded unconditionally (no early break) so + // a serial log shows every value. let probes = [0usize, total / 3, (2 * total) / 3, total - 1]; - for &p in probes.iter() { - if i >= probes.len() { - break; - } - i += 1; + for (pi, &p) in probes.iter().enumerate() { let cell = *c.as_ptr().add(p); let raw = cell.ch as u32 | ((cell.fg as u32) << 16) | ((cell.bg as u32) << 24); - if raw != 0 { + c_probes_raw[pi] = raw; + if raw != blank_raw { content_ok = false; - break; + } + } + // Same probe on the rendered grid: it is a *separate* + // allocation, so its content discriminates "only the cells + // VecData's ptr field is stale" (rendered ok) from "both + // grids' memory was clobbered / both VecData ptrs are + // stale" (rendered garbage too). + for (pi, &p) in probes.iter().enumerate() { + let cell = *r.as_ptr().add(p); + let raw = cell.ch as u32 | ((cell.fg as u32) << 16) | ((cell.bg as u32) << 24); + r_probes_raw[pi] = raw; + if raw != blank_raw { + rcontent_ok = false; + } + } + } + // Full-grid summary (cheap: a few thousand reads, serial-only). + // Definitive health signal on QEMU: healthy = every cell is + // BLANK (nz == blanks == total); the probes above are just the + // tripwire, this catches a partial clobber that the four + // samples happen to miss. + let (mut c_nz, mut c_blank) = (0usize, 0usize); + let (mut r_nz, mut r_blank) = (0usize, 0usize); + if heap_ok && c.len() == total && r.len() == total && total > 0 { + for i in 0..total { + let cell = *c.as_ptr().add(i); + let raw = cell.ch as u32 | ((cell.fg as u32) << 16) | ((cell.bg as u32) << 24); + if raw != 0 { + c_nz += 1; + } + if raw == blank_raw { + c_blank += 1; + } + let cell = *r.as_ptr().add(i); + let raw = cell.ch as u32 | ((cell.fg as u32) << 16) | ((cell.bg as u32) << 24); + if raw != 0 { + r_nz += 1; + } + if raw == blank_raw { + r_blank += 1; } } } - if c.len() != total || r.len() != total || !heap_ok || !content_ok { + msg(&alloc::format!( + "verify: grids c nz={} blank={} r nz={} blank={} (of {})", + c_nz, c_blank, r_nz, r_blank, total + )); + if c.len() != total || r.len() != total || !heap_ok || !content_ok || !rcontent_ok { msg("verify: FAILED — cells/rendered not sane at shell entry"); - crate::gop::boot_marker(&alloc::format!( - "vt: cells {:#x} {}/{} {}", - c.as_ptr() as usize, - c.len(), - total, - if content_ok { "range" } else { "CONTENT-GARBAGE" } + msg(&alloc::format!( + "verify: probes c=[{:#x},{:#x},{:#x},{:#x}] r=[{:#x},{:#x},{:#x},{:#x}]", + c_probes_raw[0], + c_probes_raw[1], + c_probes_raw[2], + c_probes_raw[3], + r_probes_raw[0], + r_probes_raw[1], + r_probes_raw[2], + r_probes_raw[3] )); + // Bottom-anchored: row 0-1 get overwritten by the shell + // banner, row 2 by the prompt (and a stale crash.log + // replays at rows 2+), so this marker must live at the very + // bottom to stay readable until the user can copy it. + crate::gop::boot_marker_at( + &alloc::format!( + "vt: c {:#x} cap={:#x} {} | r {:#x} {}", + c.as_ptr() as usize, + c.capacity(), + if content_ok { "ok" } else { "GARBAGE" }, + r.as_ptr() as usize, + if rcontent_ok { "ok" } else { "GARBAGE" } + ), + crate::gop::bottom_row(1), + ); } else { msg("verify: ok"); - crate::gop::boot_marker(&alloc::format!( - "vt: cells {:#x} {}/{} ok", - c.as_ptr() as usize, - c.len(), - total - )); + crate::gop::boot_marker_at( + &alloc::format!( + "vt: c {:#x} cap={:#x} ok | r {:#x} ok", + c.as_ptr() as usize, + c.capacity(), + r.as_ptr() as usize + ), + crate::gop::bottom_row(1), + ); } } } -- cgit v1.2.3