diff options
| author | salmonik <salmonik@tuta.io> | 2026-08-17 14:53:52 +0200 |
|---|---|---|
| committer | salmonik <salmonik@tuta.io> | 2026-08-17 14:53:52 +0200 |
| commit | be868a43185826b02bf6d091019bb779678525bb (patch) | |
| tree | 586988c15f1d700b1621c7f0208584b30878a56c /DEBUG_NOTES.md | |
| parent | v0.5.10: change em-dashes to dashes (diff) | |
| download | rs-dos-be868a43185826b02bf6d091019bb779678525bb.tar.gz rs-dos-be868a43185826b02bf6d091019bb779678525bb.zip | |
USB2/1.1 (EHCI/UHCI) drivers + real-hardware bring-up hardening
- Add polled EHCI (USB2) and UHCI (USB1.1) host-controller drivers with
HID boot mouse support, wired into cursor polling and the 'usb' shell cmd
- Add USB Legacy ownership handoff (claim_usb_legacy) plus config_write_byte
- Harden boot: verify the PIT/timer ticks before shell entry, EOI stray
interrupts in the LAPIC to stop interrupt storms, bound PS/2 controller
waits, and INTx-disable AHCI (polled driver)
- Add boot stage markers, klog screen echo, and QR lock; scheduler
mark_shell_running; NO_USB stopgap to keep BIOS USB-Legacy input alive
- alloc_pages_above for DMA buffers that must avoid low conventional memory
- Expand DEBUG_NOTES with EHCI/QEMU bring-up findings
Diffstat (limited to 'DEBUG_NOTES.md')
| -rw-r--r-- | DEBUG_NOTES.md | 207 |
1 files changed, 206 insertions, 1 deletions
diff --git a/DEBUG_NOTES.md b/DEBUG_NOTES.md index 19fe5cf..5730ca5 100644 --- a/DEBUG_NOTES.md +++ b/DEBUG_NOTES.md | |||
| @@ -284,6 +284,165 @@ sequence clean. `0x00AAAAAA` = gray text colour; shadow far rows stay 0.) | |||
| 284 | 284 | ||
| 285 | --- | 285 | --- |
| 286 | 286 | ||
| 287 | ## π EHCI driver debug β in progress (`rsnix/src/ehci.rs`) | ||
| 288 | |||
| 289 | ### Background | ||
| 290 | |||
| 291 | The USB mouse attaches to the **EHCI** (USB2) controllers on the real | ||
| 292 | OptiPlex (`00:1a.0`, `00:1d.0`), NOT the xHCI (`00:14.0` = USB3 only). | ||
| 293 | A full EHCI driver was written in `rsnix/src/ehci.rs` (~26 KB), wired | ||
| 294 | into `lib.rs`, `main.rs`, `cursor.rs`, `shell/src/lib.rs` (`usb` cmd). | ||
| 295 | |||
| 296 | ### What works | ||
| 297 | |||
| 298 | - PCI discovery, MMIO probe, HC reset, async+periodic list init. | ||
| 299 | - Port reset + device detection: FS device found on port 0. | ||
| 300 | - `ctl_xfer` builds SETUP/DATA/STATUS qtd chain; async list is | ||
| 301 | circular (head β xfer_qh β head). | ||
| 302 | - QEMU EHCI bench: async schedule processes our control QH correctly. | ||
| 303 | |||
| 304 | ### The bug: QTD DMA reads return all-zeros | ||
| 305 | |||
| 306 | The async schedule fetches our XFER_QH at `0x01b6e7c0` and reads its | ||
| 307 | `next_qtd` field correctly (`0x01b6e7f0`). Then `ADVANCEQUEUE` sets | ||
| 308 | `q->qtdaddr = 0x01b6e7f0`. But `FETCHQTD` reads from `0x01b6e7e0` | ||
| 309 | (**16 bytes BEFORE** the expected QTD address) and gets all-zeros. | ||
| 310 | |||
| 311 | ``` | ||
| 312 | FETCHQH @ 0x01b6e7c0: next_qtd=0x01b6e7f0 β correct | ||
| 313 | ADVANCEQUEUE β qtdaddr=0x01b6e7f0 β correct | ||
| 314 | FETCHQTD @ 0x01b6e7e0: all zeros β WRONG address + zeros | ||
| 315 | ``` | ||
| 316 | |||
| 317 | The QH's buffer pointer area (offset 28β44) is at `0x01b6e7dcβ0x01b6e7ec`. | ||
| 318 | `0x01b6e7e0` falls inside the QH's `bufptr[1]` field β which we zeroed. | ||
| 319 | So the DMA is reading from inside our own QH structure, not the QTD that | ||
| 320 | follows it. | ||
| 321 | |||
| 322 | ### Root cause hypothesis: DMA address β CPU address | ||
| 323 | |||
| 324 | `dma_alloc` uses `alloc::alloc::alloc()` (the Rust global heap allocator). | ||
| 325 | This returns a **virtual address**. On UEFI, the page tables from | ||
| 326 | `adopt_tables()` copy the firmware's identity map β so virt == phys for | ||
| 327 | most RAM. BUT: | ||
| 328 | |||
| 329 | 1. The heap pages allocated by the page allocator may have been remapped | ||
| 330 | or the identity map may not cover all heap pages. | ||
| 331 | 2. The EHCI controller does DMA to/from the address we write to | ||
| 332 | `ASYNCLISTADDR`. If the heap allocation's physical address differs | ||
| 333 | from the virtual address the CPU sees, DMA reads will fetch zeros | ||
| 334 | (unmapped or wrong page). | ||
| 335 | |||
| 336 | **Evidence**: CPU can read back `*st.add(2) = 0x80e80` (the SETUP token) | ||
| 337 | via `read_volatile`, but QEMU's EHCI DMA engine reads 0 from the same | ||
| 338 | address. The CPU sees the data; the DMA engine does not. | ||
| 339 | |||
| 340 | ### What's NOT the problem | ||
| 341 | |||
| 342 | - **USBCMD bits**: Fixed (PSE=bit4, ASE=bit5, RUN=bit0). | ||
| 343 | - **Async list linkage**: Fixed (headβxferβhead circular, Q_TYPE_QH tags). | ||
| 344 | - **QH/QTD struct layout**: Matches QEMU's `EHCIqh`/`EHCIqtd` exactly. | ||
| 345 | - **Periodic schedule interference**: Disabled (no PSE). OVMF's stale | ||
| 346 | periodic entries caused crashes; now avoided. | ||
| 347 | - **Build cache**: Full `cargo clean` done; binary matches source. | ||
| 348 | - **Identity mapping**: `adopt_tables` copies UEFI page tables β should | ||
| 349 | be identity-mapped. But the evidence says otherwise for our DMA buffers. | ||
| 350 | |||
| 351 | ### Debug QEMU command | ||
| 352 | |||
| 353 | ```bash | ||
| 354 | qemu-system-x86_64 \ | ||
| 355 | -bios /usr/share/edk2/x64/OVMF.4m.fd \ | ||
| 356 | -drive file=fat:rw:esp,format=raw \ | ||
| 357 | -serial file:/tmp/rsdos_q.log \ | ||
| 358 | -monitor unix:/tmp/rsdos_mon.sock,server,nowait \ | ||
| 359 | -m 256M -machine q35 -cpu qemu64 -no-reboot \ | ||
| 360 | -device ich9-usb-ehci1 -device usb-mouse \ | ||
| 361 | -trace "usb_ehci*" >/tmp/rsdos_trace.txt 2>&1 | ||
| 362 | ``` | ||
| 363 | |||
| 364 | ### Key QEMU EHCI facts | ||
| 365 | |||
| 366 | - **Register layout**: `CAPLEN +0, HCSPARAMS +4, HCCPARAMS +8`; | ||
| 367 | operational base = `base + CAPLEN`. `USBCMD=+0, USBSTS=+4, | ||
| 368 | ASYNCLISTADDR=+0x18, CONFIGFLAG=+0x40, PORTSC#1=+0x44`. | ||
| 369 | - **USBCMD bits**: `RUNSTOP=bit0, HCRESET=bit1, FLS=bits2-3 (2-bit), | ||
| 370 | PSE=bit4, ASE=bit5, IAAD=bit6, ITC=bits16-23`. | ||
| 371 | - **QEMU async BH**: triggered by USBCMD writes (bit-change detection) | ||
| 372 | and frame timer. `ehci_work_bh` processes periodic frames first, then | ||
| 373 | advances async schedule. | ||
| 374 | - **QEMU strips FLS** if guest sets it (FCR register). | ||
| 375 | - **Port reset**: deassert PR; PED stays 0 for FS (no HS speed mask). | ||
| 376 | - **`ehci_find_queue_by_qh`** reuses queue objects; `q->seen > 1` stops | ||
| 377 | re-processing the same QH (reclamation detection). | ||
| 378 | |||
| 379 | ### Key QEMU EHCI structs (from `h110.h` / `hw/usb/hcd-ehci.h`) | ||
| 380 | |||
| 381 | ```c | ||
| 382 | // QH: 12 dwords (48 bytes) | ||
| 383 | typedef struct EHCIqh { | ||
| 384 | uint32_t next; // dword0: horizontal link pointer | ||
| 385 | uint32_t epchar; // dword1: dev(0-6), i(7), ep(8-10), eps(12-13), dtc(14), h(15), mps(16-26) | ||
| 386 | uint32_t epcap; // dword2 | ||
| 387 | uint32_t current_qtd; // dword3 | ||
| 388 | uint32_t next_qtd; // dword4 | ||
| 389 | uint32_t altnext_qtd; // dword5 | ||
| 390 | uint32_t token; // dword6: tbytes(16-30), cerr(10-11), pid(8-9), ioc(16), active(7), halt(6) | ||
| 391 | uint32_t bufptr[5]; // dword7-11 | ||
| 392 | } EHCIqh; | ||
| 393 | |||
| 394 | // QTD: 8 dwords (32 bytes) | ||
| 395 | typedef struct EHCIqtd { | ||
| 396 | uint32_t next; // dword0 | ||
| 397 | uint32_t altnext; // dword1 | ||
| 398 | uint32_t token; // dword2: tbytes(16-30), cpage(12-15), cerr(10-11), pid(8-9), ioc(16), active(7) | ||
| 399 | uint32_t bufptr[5]; // dword3-7 | ||
| 400 | } EHCIqtd; | ||
| 401 | |||
| 402 | #define NLPTR_GET(x) ((x) & ~0xf) | ||
| 403 | #define NLPTR_TBIT(x) ((x) & 1) | ||
| 404 | #define NLPTR_TYPE_GET(x) (((x) >> 1) & 3) | ||
| 405 | #define Q_TYPE_QH 1 // NLPTR_TYPE value for QH links | ||
| 406 | ``` | ||
| 407 | |||
| 408 | ### What to try next | ||
| 409 | |||
| 410 | 1. **Allocate DMA buffers from a known-safe region**: Instead of | ||
| 411 | `alloc::alloc`, use a dedicated DMA pool at a known physical address | ||
| 412 | (e.g., the first page allocator pages, or a statically allocated | ||
| 413 | buffer). Verify the physical address matches the virtual address by | ||
| 414 | reading the PML4/PDPT/PD/PT entries for the buffer's page. | ||
| 415 | |||
| 416 | 2. **Add a page-table walk diagnostic**: Walk the 4-level page tables for | ||
| 417 | the DMA buffer address and print the physical address. If virt β phys, | ||
| 418 | that's the bug. Add this to `ehci.rs` init or to `paging.rs`. | ||
| 419 | |||
| 420 | 3. **Use the page allocator directly** (which returns physical addresses | ||
| 421 | that are identity-mapped by construction) instead of the heap allocator. | ||
| 422 | `alloc_pages(n)` in `memory.rs` returns a `*mut u8` β verify this is | ||
| 423 | identity-mapped by checking a known page table entry. | ||
| 424 | |||
| 425 | 4. **Check if the heap allocator's pages lose identity mapping**: The heap | ||
| 426 | is built from the UEFI memory map. `adopt_tables` copies the firmware | ||
| 427 | page tables. But if the heap allocator later allocates pages that were | ||
| 428 | NOT in the firmware's map (e.g., from a free region), those pages | ||
| 429 | might not have identity-mapped PTEs. | ||
| 430 | |||
| 431 | 5. **Simpler test**: Allocate a small buffer (e.g., 64 bytes) with | ||
| 432 | `dma_alloc`, write a known pattern, and check if the EHCI controller | ||
| 433 | can DMA-read it. If even a small buffer fails, the problem is | ||
| 434 | fundamental (identity mapping broken for heap pages). | ||
| 435 | |||
| 436 | ### Key code locations | ||
| 437 | |||
| 438 | - `rsnix/src/ehci.rs:751` β `dma_alloc()` (uses `alloc::alloc`) | ||
| 439 | - `rsnix/src/ehci.rs:420` β `init()` (sets up ASYNCLISTADDR, head QH, XFER_QH) | ||
| 440 | - `rsnix/src/ehci.rs:230` β `ctl_xfer()` (builds QH + QTD chain, enables schedule) | ||
| 441 | - `rsnix/src/paging.rs:48` β `adopt_tables()` (copies UEFI page tables) | ||
| 442 | - `rsnix/src/memory.rs` β `alloc_pages()` (page allocator) | ||
| 443 | |||
| 444 | --- | ||
| 445 | |||
| 287 | ## β v0.5.10 β USB HID mouse driver (polled xHCI, `rsnix/src/usb.rs`) | 446 | ## β v0.5.10 β USB HID mouse driver (polled xHCI, `rsnix/src/usb.rs`) |
| 288 | 447 | ||
| 289 | Handoff: HEAD = `v0.5.10` (workspace Cargo.toml + boot banner). Adds a | 448 | Handoff: HEAD = `v0.5.10` (workspace Cargo.toml + boot banner). Adds a |
| @@ -292,6 +451,7 @@ polled xHCI controller driver (mouse-only) announced via `usb: xHCI at | |||
| 292 | so a USB mouse supersedes PS/2. New shell cmd: `usb` (diagnose), `usb rescan`. | 451 | so a USB mouse supersedes PS/2. New shell cmd: `usb` (diagnose), `usb rescan`. |
| 293 | 452 | ||
| 294 | ### How it works | 453 | ### How it works |
| 454 | |||
| 295 | - Bring up controller (`OPC=0`, set `RCS`+`CRR`, `CNR`β0), discover a | 455 | - Bring up controller (`OPC=0`, set `RCS`+`CRR`, `CNR`β0), discover a |
| 296 | mouse asynchronously from the cursor task (`maybe_discover`), reset the | 456 | mouse asynchronously from the cursor task (`maybe_discover`), reset the |
| 297 | port, enable slot, address device, read device + config descriptors, | 457 | port, enable slot, address device, read device + config descriptors, |
| @@ -301,6 +461,7 @@ so a USB mouse supersedes PS/2. New shell cmd: `usb` (diagnose), `usb rescan`. | |||
| 301 | heap pointers; no IRQ β keep one IN report armed and drain on each poll. | 461 | heap pointers; no IRQ β keep one IN report armed and drain on each poll. |
| 302 | 462 | ||
| 303 | ### QEMU bring-up observations / gotchas that bit us | 463 | ### QEMU bring-up observations / gotchas that bit us |
| 464 | |||
| 304 | - **MaxPorts = bits 31:24 of `HCSPARAMS1`**, not 16:23 (`MaxIntrs`). Using | 465 | - **MaxPorts = bits 31:24 of `HCSPARAMS1`**, not 16:23 (`MaxIntrs`). Using |
| 305 | the wrong nibble silently yielded 0 ports ("ports=0", every PORTSC read 0). | 466 | the wrong nibble silently yielded 0 ports ("ports=0", every PORTSC read 0). |
| 306 | - **Operational registers** (xHCI >=1.1, matches QEMU/Linux): `CRCR=0x18`, | 467 | - **Operational registers** (xHCI >=1.1, matches QEMU/Linux): `CRCR=0x18`, |
| @@ -321,9 +482,10 @@ so a USB mouse supersedes PS/2. New shell cmd: `usb` (diagnose), `usb rescan`. | |||
| 321 | - A long-lived QEMU session sometimes stopped forwarding `mouse_move` | 482 | - A long-lived QEMU session sometimes stopped forwarding `mouse_move` |
| 322 | after heavy use; a fresh relaunch always revived it β not a driver bug. | 483 | after heavy use; a fresh relaunch always revived it β not a driver bug. |
| 323 | - Diagnose cmd `usb` prints `xhci mmio=β¦ mapped=β¦ ports=β¦ mouse=β¦ slot=β¦` | 484 | - Diagnose cmd `usb` prints `xhci mmio=β¦ mapped=β¦ ports=β¦ mouse=β¦ slot=β¦` |
| 324 | plus per-port `PORTS` dwords and a ` hid ep-index=β¦ mps=β¦ armed=true` line. | 485 | plus per-port `PORTS` dwords and a `hid ep-index=β¦ mps=β¦ armed=true` line. |
| 325 | 486 | ||
| 326 | ### Boot log (good path) | 487 | ### Boot log (good path) |
| 488 | |||
| 327 | ``` | 489 | ``` |
| 328 | usb: xHCI at 00:03.0 | 490 | usb: xHCI at 00:03.0 |
| 329 | usb: controller up (8 ports) β mouse discovery deferred to cursor task | 491 | usb: controller up (8 ports) β mouse discovery deferred to cursor task |
| @@ -334,5 +496,48 @@ usb: HID boot mouse armed (slot 1) | |||
| 334 | ``` | 496 | ``` |
| 335 | 497 | ||
| 336 | ### Known limitations | 498 | ### Known limitations |
| 499 | |||
| 337 | - Mouse-only, no HID descriptor protocol selection (`SET_PROTOCOL` boot), | 500 | - Mouse-only, no HID descriptor protocol selection (`SET_PROTOCOL` boot), |
| 338 | no high-rate intervals, no keyboard/tablet, no hot-unplug handling, no MSI. | 501 | no high-rate intervals, no keyboard/tablet, no hot-unplug handling, no MSI. |
| 502 | |||
| 503 | ### EHCI (usb2) bring-up β QEMU quirks that bit us (all now fixed) | ||
| 504 | |||
| 505 | - **QTDs must be 32-byte aligned.** QEMU's `NLPTR_GET(x) = x & 0xffffffe0` | ||
| 506 | masks the LOW 5 bits, so a qtd at QH+0x30 (e.g. `0x01b6e7f0`) gets rounded | ||
| 507 | down to `0x01b6e7e0` and the transfer executes at the wrong address | ||
| 508 | (seen as a 16-byte jump in the FETCHQTD trace). Control qtds now live at | ||
| 509 | QH+0x40/0x60/0x80; the HID report qtd at HID_QH+0x40. | ||
| 510 | - **Unlink must self-loop WITH the QH type bit**: `link_of(head)` (addr|0x02). | ||
| 511 | A bare `head as u32` self-loop is parsed by QEMU as an iTD β | ||
| 512 | "non queue head request in async schedule" β HC reset. | ||
| 513 | - **DATA qtd altnext must be `1` (terminate)**, not 0. On a short IN | ||
| 514 | (e.g. config descriptor < 256 bytes) TBYTES stays != 0 so ADVANCEQUEUE | ||
| 515 | follows altnext; QEMU treats altnext=0 as a *valid* address β jump to 0. | ||
| 516 | - **Periodic HID QH must set the EP number (epchar bits 8-11).** The QH was | ||
| 517 | built with devaddr|EPS|MPS but EP=0, so every periodic IN went to the | ||
| 518 | control endpoint: the first transfer "completed" oddly, then the qtd | ||
| 519 | HALTed every frame (`usb_ehci_qtd_bits` showed `halt 1`, packet on ep 0). | ||
| 520 | Fix: `| ((epnum & 0x0f) << 8)`. | ||
| 521 | - **Idle periodic qtd with correct EP just NAKs** (device has no report) β | ||
| 522 | that is correct; don't mistake "no reports" for a broken schedule. | ||
| 523 | - Headless QEMU 11 **cannot inject input into `usb-mouse`**: it has no | ||
| 524 | `display=` property (only usb-tablet/usb-kbd do), so it is never bound to | ||
| 525 | a display and `input-send-event`/`send-key` events (traced as `con -1`) | ||
| 526 | never reach it. First-report delivery was verified with `usb-kbd` + | ||
| 527 | `send-key` instead (b2 carried the real HID keycode, e.g. `0x04` for 'a'). | ||
| 528 | - **Controller halt+reset before init** is required to clear OVMF's stale | ||
| 529 | async schedule left in the controller. | ||
| 530 | |||
| 531 | ### EHCI boot log (good path, usb-mouse) | ||
| 532 | |||
| 533 | ``` | ||
| 534 | ehci: USB2 EHCI at 00:04.0 | ||
| 535 | ehci: mmio=0x81060000 caplen=0x20 ports=6 64-bit-caps=false | ||
| 536 | ehci: controller up (6 ports) | ||
| 537 | > ehci: port 0 resolved (full/low β TT path) | ||
| 538 | ehci: dev 2706:0100 class=0x0 mps0=64 | ||
| 539 | ehci: HID mouse IN ep1(0x81) mps=4 interval=7 | ||
| 540 | ehci: HID boot mouse armed (device 1) | ||
| 541 | ``` | ||
| 542 | |||
| 543 | Periodic schedule: 2200+ EXECUTEs/frame with 0 qtd halts; idle mouse NAKs. | ||
