16 When it does not boot: debugging a kernel

The first edition of this book ended Part III with a list of chapter titles, and the mail it received over the years was not about the chapters that existed. It was about kernels that did not boot. Readers had understood the GDT, the IDT and paging perfectly well; what stopped them was a QEMU window that flickered, or a serial console that stayed empty, or a program that died at its first instruction, with nothing to tell them why. A hosted program that crashes leaves a core dump, a message from the C library, at worst a Segmentation fault. A kernel leaves nothing. It is the lowest layer of software, and when it faults there is no layer below to print an error message: the processor either runs a handler the kernel installed, or it resets.

That is the whole difficulty, and it is not a difficulty of knowledge. Every reader who wrote to us could have found their bug in a few minutes with the right question asked in the right order. This chapter is about the order. It gives a method, cheapest step first; a table that maps what you see to what is probably wrong and to the one command that confirms it; and three bugs that we introduced on purpose in the kernel of chapter 14, File system, and hunted down for real, with the transcripts. Nothing here is new: every tool was used at least once in chapters 7 to 14. What is new is putting them together into a procedure that you can follow when the machine says nothing.

Running this chapter’s code

This chapter adds no code. Its experiments are made on copies of the chapter 13 and 14 directories, so that the originals stay known-good, which is the point of section 16.1.5 below. Copy a chapter next to a copy of the tools/ directory, so that the relative path to the test scripts in the Makefiles still works, and mount the copy in the container as a second volume:

$ mkdir -p /path/to/scratch/code
$ cp -r code/chapter14 /path/to/scratch/code/
$ cp -r tools /path/to/scratch/
$ docker run --rm -it --user "$(id -u):$(id -g)" --security-opt seccomp=unconfined \
      -v "$PWD":/work -v /path/to/scratch:/scratch -w /scratch/code/chapter14/os os01

Inside, make, make qemu, make gdb and make test work as in chapter 14. Every transcript below was produced this way; the QEMU command lines are the chapter 14 ones, with options added as explained.

16.1 A method, in order of cost

The order matters more than the tools. Each step below is cheaper than the next, in time and in the amount of machinery you must understand to read its output, and each one answers a question that the next one would otherwise have to answer too. Start at the top, stop as soon as you know where the kernel dies; the symptom table and the worked cases take it from there.

16.1.1 Print first: the serial port is the kernel’s printf

The cheapest instrument is the one you have had since chapter 10, Talking to devices: the serial port and the VGA text console. serial_putc depends on nothing, no interrupts, no paging, no heap, no stack beyond one call, and QEMU writes what it receives into a file on the host. A kprintf is therefore the first thing to add when a kernel dies silently, and the question it answers is the only one that matters at that point: how far did we get?

The technique is bracketing. Put a line before and after each step of kmain and look at which one is the last to appear:

    kprintf("init: paging\n");
    paging_init();
    kprintf("init: heap\n");
    heap_init();
    kprintf("init: tss\n");
    tss_init();

If init: heap is the last line, the bug is in heap_init or in something that heap_init is the first to rely on, and the next round of prints goes inside it. Three rounds usually narrow a silent death to a dozen lines. Then print the values: a pointer, a selector, an entry of the page directory, the status byte a device returned. The kernel of chapter 14 prints the LBA of a failed read and the status that came with it, the error code of a page fault with its bits decoded, the vector and registers of an unhandled exception; those lines are the residue of exactly this process, left in the code because they cost nothing and because the next bug will need them.

Two habits make the prints useful. Capture the port to a file, -serial file:serial.txt, rather than watching the terminal: a kernel that reboots in a loop scrolls the evidence off the screen, a file keeps it. And put the serial driver first in kmain, before the GDT, before the console: in chapter 10 we explained why serial_init can run before anything else, and a kernel that cannot print cannot be debugged by printing.

Why not the VGA screen? Three reasons. It scrolls: 25 lines, and the message you need is the twenty-sixth. It is erased by a reset: a triple fault clears it before you can read it, and in the make test configuration there is no screen at all. And after chapter 12 it is memory that must be mapped before a store to 0xB8000 works, so the one bug that unmaps it also silences it. The serial port is a port, it is never unmapped, and its output outlives the machine.

A print has one limit: it needs the kernel to be running C code with a valid stack. The bugs that strike between an event and the first line of C, in the processor’s own handling of an interrupt, or in the bootloader before there is a kernel, print nothing. For those we need the machine itself to talk.

16.1.2 Make the machine tell you: QEMU’s logs and monitor

QEMU knows everything the processor does, and will say it if asked. The options that matter, all of them already met in chapter 11, Interrupts, and chapter 12, Memory management:

• -d int logs every interrupt and exception with the full register state, -D file sends the log to a file instead of the terminal. The two lines to look for are v=, one per delivered interrupt, and check_exception, which appears when an exception is raised while another is being delivered. The sequence check_exception old: 0xd new 0xd followed by v=08 is a double fault; check_exception old: 0x8 followed by Triple fault is the end.

• -d cpu_reset adds a CPU Reset block with the registers at the moment of each reset: after a triple fault, EIP in that block is the instruction that could not be interrupted. With both categories, -d int,cpu_reset, the log of a rebooting kernel is a loop of the same few entries, and one pass through it is enough.

• -d guest_errors reports accesses that QEMU itself considers wrong: a write to a register that does not exist, a read from unassigned physical memory. A clean boot of the chapter 14 kernel logs nothing under it, which is what makes it useful: anything it prints is suspect.

• -no-reboot stops QEMU at the first triple fault instead of resetting, and -no-shutdown keeps the process alive, paused, so that gdb or the monitor can look at the frozen registers. Without them the state you need is gone a microsecond after the fault. Both go on every debugging command line from now on.

The monitor is QEMU’s own console, reachable with -monitor stdio or, from gdb, with the monitor prefix. Four of its commands cover most of a kernel’s needs, and each prints something gdb cannot know:

• info registers: the register dump of the -d int log, on demand, with the hidden parts of the segment registers, GDT=, IDT=, TR= and the control registers. Chapter 9 read the GDTR with it, chapter 11 the IDTR, chapter 13 the TSS; in case 1 below it names the bug outright.
• info mem: the ranges mapped by the current page directory, with u for pages that ring 3 may touch and rw for writable ones. One line per contiguous range, so a missing page or a missing bit shows as a gap or a changed letter.
• info tlb: the same information one page at a time, for when a single page is in question. The output is long; pipe it through grep on the host, or use info mem first.
• x/ with a physical address (xp/) and i /b port: read guest memory and I/O ports from outside. monitor i /b 0x1f7 reads the ATA status register without the kernel’s help, monitor i /b 0x3fd the serial line status; the device’s view of the world, compared with the kernel’s, is often the whole diagnosis.
• info pic and info irq: the two 8259As with their request, mask and in-service registers, and a count of how many times each line was raised. Section 16.3.4 shows what they say about a forgotten end-of-interrupt.

Here is what a clean run of the chapter 14 kernel looks like through -d int, booted headless for eight seconds and then interrupted; it is the baseline against which every log in this chapter is read:

$ qemu-system-i386 -machine q35 -device piix3-ide,id=ide \
      -drive id=disk,format=raw,file=build/disk.img,if=none -device ide-hd,drive=disk,bus=ide.0 \
      -display none -serial file:serial.txt -d int,guest_errors -D qemu.log -no-reboot
$ grep -o "v=[0-9a-f]*" qemu.log | sort | uniq -c
    792 v=20
     14 v=80
$ grep -c check_exception qemu.log
0

Seven hundred and ninety-two timer ticks, one every ten milliseconds, fourteen system calls (hello makes three: getpid, write, exit; count makes eleven) and not one exception: a correct kernel of this size never faults, and a v=0d or v=0e in the log of a boot that looks fine is a bug waiting to be understood. The first system call entry shows what the log says about a ring 3 event:

$ grep -n -m1 -A3 "v=80" qemu.log
619:    10: v=80 e=0000 i=1 cpl=3 IP=001b:080480a3 pc=080480a3 SP=0023:7fffffa4 env->regs[R_EAX]=00000004
620-EAX=00000004 EBX=00000000 ECX=00000000 EDX=00000000
621-ESI=00000000 EDI=00000000 EBP=7fffffb8 ESP=7fffffa4
622-EIP=080480a3 EFL=00000202 [-------] CPL=3 II=0 A20=1 SMM=0 HLT=0

i=1 for a software interrupt, cpl=3, CS = 0x1b, the user stack at 0x7fffffa4 and EAX = 4, SYS_GETPID: everything chapter 13 said about the system call path, in one line, for free.

16.1.3 gdb on a frozen machine

When the prints and the log have told you where, gdb tells you what. make qemu and make gdb as in every chapter since 7; the recipes below are the ones that matter when the kernel is broken rather than being studied.

Attach after the fact. gdb does not have to be there from the start. With -no-reboot -no-shutdown on the QEMU command line and the gdb stub enabled (-gdb tcp::26000 without -S), you can let the kernel run, crash or hang, and then run make gdb: the .gdbinit connects, and the first thing gdb prints is where the processor stopped. For a hang it is the instruction being executed, usually a hlt or a jmp to itself; for a triple fault it is the instruction the processor was trying to interrupt. Case 1 does exactly this.

Break on the handlers, not on the bug. You rarely know where the bug is; you always know where its consequence arrives. b isr_dispatch catches every interrupt and exception, b page_fault_handler every page fault, b panic every panic, and b isr13 or b isr14, the assembly stubs, catch the exception before the kernel has touched anything. The stubs are the place to read the raw frame the processor pushed. At isr14 for a fault from ring 3 (taken from case 2 below):

(gdb) b isr14
Breakpoint 2 at 0x10194: file isr_stubs.asm, line 37.
(gdb) c

Breakpoint 2, isr14 () at isr_stubs.asm:37
37      push    dword %1
(gdb) x/6wx $esp
0xc0001ff8: 0x00000007  0x08048080  0x0000001b  0x00010202
0xc0002008: 0x80000000  0x00000023
(gdb) p/x $cr2
$1 = 0x7ffffffc

Six words, exactly the figure “Stack Usage on Transfers to Interrupt and Exception-Handling Routines” of Intel SDM Volume 3A, section 7.12.1, read bottom-up: the error code 7, the saved EIP 0x08048080, CS 0x1b, EFLAGS 0x10202, and, because the fault came from ring 3, the user ESP 0x80000000 and SS 0x23. Note where ESP itself is: 0xc0001ff8, at the top of a kernel stack in the heap, which is the stack switch of chapter 13 having happened. For a fault from ring 0 the last two words are absent: an exception that pushes an error code leaves four words at the stub, and $esp is where the interrupted kernel code had it, minus 16. The same frame reached through the C structure, once isr_common has run, is p/x *regs at a breakpoint on isr_dispatch, as in chapter 11.

Decode the error code before anything else. Two formats, both in Volume 3A. For #GP, #NP, #TS and #SS (section 7.13 “Error Code”): bit 0 EXT, bit 1 IDT, bit 2 TI, bits 15:3 the index of the descriptor at fault. 0x102 is 1 0000 0010 in binary: IDT set, index 32, “gate 32 is bad”. 0x402 is index 128, gate 0x80. A zero error code with #GP means the fault was not about a descriptor: a privileged instruction in ring 3, a bad iret frame, a segment limit. For #PF (section 5.7 “Page-Fault Exceptions”): bit 0 P, bit 1 W/R, bit 2 U/S, bit 4 I/D, and CR2 holds the address. 0x7 is “the page is present, the access was a write, from ring 3”, which can only mean a permission bit; 0x6 is the same access to a page that is not there at all. Chapter 12’s handler prints the decoding, chapter 11’s example 11.1 does it by hand; do it by hand once more each time, it takes ten seconds and it is where most wrong guesses are avoided.

Look at the instruction, then at the backtrace, then doubt the backtrace. x/i $pc or x/i regs->eip shows the faulting instruction; x/5i regs->eip - 12 the ones before it, which is where the operands were computed. bt is the next step, and chapter 11 warned you about it: the assembly stubs have no frame pointer, so gdb’s unwinder invents a frame or two (#3 0xc0001fc4 in ?? ()) and may stop with Backtrace stopped: previous frame inner to this frame (corrupt stack?). Read a backtrace up to the first isr_common and ignore what follows; across iret, across context_switch, and in a user program whose _start has no frame, gdb cannot see, and that is not a bug in your kernel. When you need the real caller, read the return address off the stack yourself, info symbol *(uint32_t *)($esp + 20), as chapter 13 did for context_switch.

Change the machine from gdb. set $pc = address makes the processor continue somewhere else, set var x = 0 changes a variable, jump *address combines both; the use is to skip a faulting instruction to see whether the rest works, or to force a code path. finish runs to the end of the current function and prints its return value, which is the fastest way to see what a driver returned without adding a print.

Hardware breakpoints and watchpoints. hbreak sets a breakpoint through the processor’s debug registers instead of QEMU’s address list; the two behave the same under QEMU, but hbreak is what you will need on real hardware and under hypervisors that patch memory. watch variable stops when a variable changes, and tells you the old and new value and the line that wrote it. On the chapter 14 kernel:

(gdb) watch current_task
Hardware watchpoint 2: current_task
(gdb) c

Hardware watchpoint 2: current_task

Old value = (struct task *) 0x0
New value = (struct task *) 0x1e060 <idle_task>
task_init () at task.c:49
49  }
(gdb) c

Hardware watchpoint 2: current_task

Old value = (struct task *) 0x1e060 <idle_task>
New value = (struct task *) 0xc0000010
schedule () at task.c:146
146     tss_set_kernel_stack((uint32_t)next->kernel_stack + KERNEL_STACK_SIZE);
(gdb) p current_task->name
$1 = 0x15ab2 "/bin/hello"

Two writes, from task_init and from schedule, each reported with the line that did it. This is the instrument for “who corrupted this”: a watchpoint on the word that changes by itself finds the writer, however far away it is. The processor has four debug registers, which bounds the number of hardware watchpoints on real hardware; watch *(uint32_t *)0x1d000 works on a raw address when there is no variable.

The 16-bit quirk. Chapters 7 and 9 explained it and it is worth one more line: with QEMU 10 and gdb 16, gdb disassembles real-mode code as 32-bit even after set architecture i8086, because the stub describes the processor as an i386. Breakpoints, stepping and registers are right; only the mnemonics are wrong. Read bytes with x/8xb $cs*16+$eip and compare with nasm -l when debugging the bootloader, and trust the disassembly again from the far jump on.

16.1.4 From an address to a line

Every tool above hands you addresses. Three programs of binutils turn them back into source, and all three read the DWARF information that -g and nasm -g put in the kernel ELF, which is why the file is 124772 bytes for 20 KiB of code.

addr2line is the direct one. The EIP at which the kernel of case 1 died was 0x1313b:

$ addr2line -e build/os/os 0x1313b
/scratch/code/chapter14/os/os/kernel.c:100
$ addr2line -f -p -e build/os/os 0x1313b 0x134ca 0x8048080
kmain at /scratch/code/chapter14/os/os/kernel.c:100
page_fault_handler at /scratch/code/chapter14/os/os/paging.c:104
?? ??:0

-f adds the function, -p makes it one line per address. The third address is a user-space one, which the kernel’s ELF knows nothing about: ask the right file,

$ addr2line -f -p -e build/user/hello 0x8048080
_start at /scratch/code/chapter14/os/user//crt0.asm:17

and remember that with several address spaces the same number means a different line in each.

nm -n lists symbols sorted by address, and finds which function an address falls in when there is no line information (an address in the middle of an assembly stub, or a kernel built without -g): the last symbol below the address is the function,

$ nm -n build/os/os | awk '$1 <= "0001313b"' | tail -2
00012f91 t log_boot
00013108 T kmain

so 0x1313b is kmain + 0x33. gdb’s info symbol 0x1313b does the same from inside a session. nm -n is also the quickest answer to “where is this variable”: the chapter 12 listing of __bss_start, kernel_directory and bitmap was made with it, and nm -n build/os/os | grep ticks tells you what address to watch.

objdump -d with --start-address and --stop-address disassembles a window around the address without dumping the whole kernel:

$ objdump -d -M intel --start-address=0x13137 --stop-address=0x13145 build/os/os | tail -4
   13137:   fb                      sti
   13138:   83 ec 0c                sub    esp,0xc
   1313b:   68 da 59 01 00          push   0x159da
   13140:   e8 04 0f 00 00          call   14049 <kprintf>

The faulting instruction is the push of the first kprintf argument, right after sti. That is the one-instruction delay of chapter 11: the interrupt that sti let through was delivered after the next instruction, and EIP is where the processor would have resumed. Finally, readelf -S and readelf -l tell you where things were linked, which is the question when an address is in no function at all: an EIP of 0x18000 in the chapter 14 kernel is in .bss, so the processor is executing data, and the return address it popped was overwritten; an EIP below 0x10100 is before .text, in the ELF headers.

16.1.5 Bisect: the last known-good kernel

The method so far assumes one bug in a kernel that mostly works. When everything is broken, or when you do not know what you changed, the cheapest instrument is a copy that works. The repository gives you one per chapter, each a superset of the previous, and diff shows exactly what a chapter added:

$ diff -rq chapter13/os/os chapter14/os/os
Only in chapter14/os/os: ata.c
Only in chapter14/os/os: ata.h
Only in chapter14/os/os: elf.c
Only in chapter14/os/os: elf.h
Only in chapter14/os/os: ext2.c
Only in chapter14/os/os: ext2.h
Files chapter13/os/os/io.h and chapter14/os/os/io.h differ
Files chapter13/os/os/kernel.c and chapter14/os/os/kernel.c differ
Files chapter13/os/os/paging.c and chapter14/os/os/paging.c differ
Files chapter13/os/os/paging.h and chapter14/os/os/paging.h differ
Files chapter13/os/os/string.c and chapter14/os/os/string.c differ
Files chapter13/os/os/string.h and chapter14/os/os/string.h differ
Files chapter13/os/os/syscall.c and chapter14/os/os/syscall.c differ
Files chapter13/os/os/syscall.h and chapter14/os/os/syscall.h differ
Files chapter13/os/os/task.c and chapter14/os/os/task.c differ
Files chapter13/os/os/task.h and chapter14/os/os/task.h differ

Your own kernel deserves the same: commit it every time make test passes. Then a regression is a search over commits rather than over code, and git bisect automates the search: git bisect start, git bisect bad on the broken revision, git bisect good on the last one that booted, and git checks out the middle one; make test says good or bad, and after log₂(n) rounds git names the commit that introduced the bug. The test scripts in tools/ are what make this mechanical: serial-test.sh boots headless and waits for a string, boot-test.sh waits for an address under gdb, and a one-line make test target with the right expected string is a regression test for every chapter’s feature. Run it after every change, not only before a commit; the ten seconds it takes are cheaper than any step above.

When the bug is in a single change, diff -u between the copy and the original is the bisection, and a diff of one line is the usual outcome. All three cases below start with one.

16.2 A symptom table

The table below is the method applied in reverse: from what you see to what is probably wrong, with the command that confirms it before you change anything. The chapter column says where the mechanism is explained. Confirm first; most hours lost on a kernel were spent fixing the wrong bug.

16.3 Three worked cases

Each case starts from a clean copy of the chapter 14 kernel, introduces one small bug of the kind readers reported, and shows the hunt as it happened, transcripts included. The bugs are shown as diffs against the chapter’s code; the hunts use only the tools above.

16.3.1 Case 1: the machine reboots at the first tick

The bug is in idt.c. The limit of the IDTR is the size of the table minus one, and the chapter 11 code says so; this copy says the size of an entry minus one, the kind of slip that happens when a * IDT_ENTRIES is lost in an edit:

--- chapter14/os/os/idt.c
+++ i_limit/os/os/idt.c
@@ -38,7 +38,7 @@
         idt_set_gate(i, (uint32_t)isr_stub_table[i], GDT_KERNEL_CODE,
                      IDT_INTERRUPT_GATE_RING0);
 
-    idt_pointer.limit = sizeof(idt) - 1;
+    idt_pointer.limit = sizeof(struct idt_entry) - 1;
     idt_pointer.base  = (uint32_t)&idt;
     asm volatile("lidt %0" : : "m"(idt_pointer));
 }

It compiles without a warning, and make qemu shows a window that flickers. The serial output is empty, which is itself a clue: the kernel dies before its first kprintf, and kmain executes sti just before it. Step one, print, has nothing to add here, so we go to step two and ask QEMU:

$ qemu-system-i386 -machine q35 -device piix3-ide,id=ide \
      -drive id=disk,format=raw,file=build/disk.img,if=none -device ide-hd,drive=disk,bus=ide.0 \
      -display none -serial file:serial.txt -d int,cpu_reset -D qemu.log -no-reboot -no-shutdown

QEMU stops at the triple fault and waits; after a few seconds we interrupt it with Ctrl-C and read:

$ wc -c serial.txt
0 serial.txt
$ grep -n "check_exception\|v=\|Triple" qemu.log
476:     0: v=20 e=0000 i=0 cpl=0 IP=0008:0001313b pc=0001313b SP=0010:0008ffc4 env->regs[R_EAX]=000000fc
495:check_exception old: 0xffffffff new 0xd
496:     1: v=0d e=0102 i=0 cpl=0 IP=0008:0001313b pc=0001313b SP=0010:0008ffc4 env->regs[R_EAX]=000000fc
515:check_exception old: 0xd new 0xd
516:     2: v=08 e=0000 i=0 cpl=0 IP=0008:0001313b pc=0001313b SP=0010:0008ffc4 env->regs[R_EAX]=000000fc
535:check_exception old: 0x8 new 0xd
536:Triple fault

Read it as chapter 11 read its log. The first interrupt the kernel ever receives is v=20, IRQ 0, the timer, a hardware interrupt (i=0) in ring 0 at EIP = 0x1313b. Delivering it raises #GP (new 0xd) with error code 0x102. Delivering the #GP raises #GP again, which is a double fault, v=08; delivering the double fault raises a third, and that is the triple fault. The error code says which descriptor was refused: 0x102 is binary 1 0000 0010, IDT bit set, index 0x20: “gate 32 is bad”. And the processor could not deliver #GP through gate 13 either, nor #DF through gate 8, so the whole table is unusable, not one entry. A table whose entries were filled by the loop we can read in idt.c and that is unusable as a whole has a wrong base or a wrong limit.

Without -no-reboot the same log is a loop. We let it run for three seconds:

$ grep -c "Triple fault" qemu.log
22
$ grep -A3 "Triple fault" qemu.log | head -5
Triple fault
CPU Reset (CPU 0)
EAX=000000fc EBX=00000000 ECX=00000001 EDX=00000021
ESI=00007cd8 EDI=0001e110 EBP=0008fff8 ESP=0008ffc4
--

Twenty-two boots in three seconds, each ending at the same place; -d cpu_reset records the registers at each reset and EIP is 0x1313b in the block that follows every Triple fault. That is the flicker.

Step three, gdb, confirms the diagnosis without guessing. We start QEMU as above, with -gdb tcp::26000 added and no -S, wait for the fault, and attach:

$ make gdb
...output omitted...
0x0001313b in kmain () at kernel.c:100
100     kprintf("Hello World from the kernel!\n");
Breakpoint 1 at 0x13111: file kernel.c, line 92.
(gdb) info registers eip esp eflags
eip            0x1313b             0x1313b <kmain+51>
esp            0x8ffc4             0x8ffc4
eflags         0x212               [ IOPL=0 IF AF ]
(gdb) x/i $pc
=> 0x1313b <kmain+51>:  push   0x159da
(gdb) monitor info registers
...output omitted...
GDT=     000194e0 0000002f
IDT=     00019520 00000007
CR0=00000011 CR2=00000000 CR3=00000000 CR4=00000000
...output omitted...
(gdb) p idt_pointer
$1 = {limit = 7, base = 103712}
(gdb) p sizeof(idt)
$2 = 2048
(gdb) p/x 0x20 * 8 + 7
$3 = 0x107

The processor is frozen on the push after sti, with IF set: the first instruction at which an interrupt could be taken, and the one at which it was. monitor info registers shows the IDTR: base 0x19520, which nm -n confirms is idt, and limit 7. One entry. Gate 32 ends at byte 0x107, far outside; so does gate 13 at 0x6f and gate 8 at 0x47, which is why the fault escalated instead of being reported. p idt_pointer shows the C variable with the same 7, and sizeof(idt) shows what it should have been. The fix is the line in the diff, reversed. make test passes, and the log of the fixed kernel is the clean baseline of section 16.1.2.

Two close relatives of this bug deserve a look, because they produce different symptoms from almost the same mistake. The first is the limit counted in entries rather than bytes, IDT_ENTRIES - 1 = 255. Entries 0 to 31 then fit in the limit, entry 32 does not, and the kernel halts with a message instead of rebooting:

Exception 13: General Protection (error code 0x102)
eax=0x000000fc ebx=0x00000000 ecx=0x00000001 edx=0x00000021
esi=0x00007cd8 edi=0x0001e110 ebp=0x0008fff8 esp=0x0008ffc4
eip=0x0001313b cs=8 ds=10 eflags=0x00010212
System halted.

Same error code, same EIP, but gate 13 was reachable, so the processor could report. Under gdb with a breakpoint on the stub, the raw frame of a ring 0 fault is four words:

(gdb) b isr13
Breakpoint 2 at 0x1018d: file isr_stubs.asm, line 37.
(gdb) c

Breakpoint 2, isr13 () at isr_stubs.asm:37
37      push    dword %1
(gdb) x/4wx $esp
0x8ffb4:    0x00000102  0x0001313b  0x00000008  0x00010212
(gdb) x/i *(uint32_t *)($esp + 4)
   0x1313b <kmain+51>:  push   0x159da
(gdb) p/x $eflags
$1 = 0x12
(gdb) p *(uint32_t *)$esp >> 3
$2 = 32
(gdb) p idt_pointer
$3 = {limit = 255, base = 103712}

Error code, EIP, CS, EFLAGS with RF set; $eflags inside the stub is 0x12, IF clear, because the gate is an interrupt gate; and the error code shifted right by three is the vector of the offending gate. The second relative is the unremapped PIC, pic_init() left out. The IDT is fine; the timer arrives on vector 8, which has a handler, and the kernel reports a double fault that is not one:

Exception 8: Double Fault (error code 0x13136)
eax=0x000000b8 ebx=0x00000000 ecx=0x00000001 edx=0x00000021
esi=0x00007cd8 edi=0x0001e110 ebp=0x0008fff8 esp=0x0008ffc8
eip=0x00000008 cs=212 ds=10 eflags=0x000000c0
System halted.

Everything in the last two lines is shifted by one word. A real #DF pushes an error code, so isr8 is an ISR_ERRCODE stub and pushes no dummy one; a hardware interrupt on vector 8 pushes no error code either, so struct registers is read four bytes off: the “error code” 0x13136 is the saved EIP, eip=8 is the saved CS, cs=212 is the saved EFLAGS. An error code that looks like an address is the signature of this bug, and -d int settles it, v=08 e=0000 i=0 cpl=0 IP=0008:00013136: a hardware interrupt, i=0, with no error code, at the same push after sti. addr2line -e build/os/os 0x13136 says kernel.c:100 again. Whenever the first interrupt after sti goes wrong, the IDT limit, the PIC offsets and the gate for 0x20 are the three suspects, in that order.

16.3.2 Case 2: the user program dies at its first instruction

The bug is in task.c, where the user stack of a new task is mapped. One flag is missing:

--- chapter14/os/os/task.c
+++ ii_nouser/os/os/task.c
@@ -101,7 +101,7 @@
     frame = pmm_alloc_frame();
     if (frame == 0)
         panic("task_create_user: out of frames");
-    paging_map_in(dir, USER_STACK_TOP - USER_STACK_SIZE, frame, PAGE_WRITE | PAGE_USER);
+    paging_map_in(dir, USER_STACK_TOP - USER_STACK_SIZE, frame, PAGE_WRITE);
 
     t = task_alloc(name, (void (*)(void))entry, user_task_start, dir);
     t->user_stack_top = USER_STACK_TOP;

This kernel boots, mounts the disk, lists the directories and loads both programs; then:

exec /bin/hello: segment 0 at 0x08048000, 343 bytes in file, 343 in memory
exec /bin/count: segment 0 at 0x08048000, 331 bytes in file, 331 in memory

Page fault at 0x7ffffffc: protection violation, write, user mode, eip=0x08048080 (error code 0x7)
killing task 1 (/bin/hello)

Page fault at 0x7ffffffc: protection violation, write, user mode, eip=0x08048080 (error code 0x7)
killing task 2 (/bin/count)
all processes finished, 32443 frames free

The kernel survives, because chapter 13 taught the page-fault handler to kill a ring 3 task instead of panicking, and its message is step one already done for us. Decode it before touching anything. 0x7ffffffc is four bytes below USER_STACK_TOP: the first word of the user stack. eip=0x08048080 is _start, the first instruction of the program, call main, which pushes a return address, and that is the write. Error code 0x7: P = 1, the page is present; W/R = 1, a write; U/S = 1, from ring 3. A present page that ring 3 may not write to, when the stack is supposed to be writable by ring 3, is a permission bit, and there are only two: PAGE_WRITE and PAGE_USER. Had the stack not been mapped at all, the code would have been 0x6; we tried that variant too, by mapping the page one page too high, and the handler printed page not present, write, user mode ... (error code 0x6): the low bit separates “not there” from “not allowed”.

gdb confirms it in the page tables themselves. We saw the raw frame at isr14 in section 16.1.3; here is the rest of the session, from the handler:

(gdb) b page_fault_handler
Breakpoint 3 at 0x134ca: file paging.c, line 104.
(gdb) c

Breakpoint 3, page_fault_handler (regs=0xc0001fc4) at paging.c:104
104     asm volatile("mov %%cr2, %0" : "=r"(cr2));
(gdb) p/x regs->err_code
$2 = 0x7
(gdb) x/i regs->eip
   0x8048080:   call   0x80480fc
(gdb) p/x current_task->page_directory[0x7ffffffc >> 22]
$3 = 0x125023
(gdb) set $pt = (uint32_t *)(current_task->page_directory[0x7ffffffc >> 22] & 0xfffff000)
(gdb) p/x $pt[(0x7ffffffc >> 12) & 0x3ff]
$4 = 0x124003
(gdb) set $pt2 = (uint32_t *)(current_task->page_directory[0x08048000 >> 22] & 0xfffff000)
(gdb) p/x $pt2[(0x08048000 >> 12) & 0x3ff]
$5 = 0x122027
(gdb) monitor info mem
0000000000000000-0000000007fe0000 0000000007fe0000 -rw
0000000008048000-0000000008049000 0000000000001000 urw
000000007ffff000-0000000080000000 0000000000001000 -rw
00000000c0000000-00000000c0005000 0000000000005000 -rw
(gdb) bt
#0  page_fault_handler (regs=0xc0001fc4) at paging.c:104
#1  0x00012de1 in isr_dispatch (regs=0xc0001fc4) at isr.c:73
#2  0x000102a6 in isr_common () at isr_stubs.asm:115
#3  0xc0001fc4 in ?? ()
#4  0x00000fe0 in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

The walk is the one of chapter 12, done by hand on the task’s directory. The directory entry for 0x7ffffffc is 0x125023: present, writable, not user, which is already wrong (get_table adds the USER bit to the directory entry only when asked for a user page, and nobody asked). The page table entry is 0x124003: frame 0x124000, flags 0x003, present and writable, no 4. Compare with the code page at 0x08048000, 0x122027: 0x027, present, writable, user, accessed. monitor info mem says it in one glance: the program’s page is urw, the stack’s page is -rw. Ring 3 may run the code and may not touch its own stack. The backtrace is the expected garbage past isr_common.

The fix is the flag. Two remarks for your own kernel. First, the kernel’s own test for a user pointer, paging_user_accessible in paging.c, which syscall.c calls on every buffer a program hands the kernel, checks exactly the bits we just read, at both levels; a kernel that has such a function can call it from the page-fault handler to print which level refused. Second, the symptom “program dies at its first instruction” has four causes with four different signatures, all visible in the raw frame: a bad entry address gives an EIP that is not _start; a missing crt0 gives a fault inside main’s epilogue when it rets to nowhere; a stack problem gives CR2 just below the stack top with EIP at the first push or call; wrong data selectors give #GP with error code 0 at the first memory access through DS. Read x/6wx $esp at the stub and you have told them apart before gdb has finished printing.

16.3.3 Case 3: the disk is read without error and everything is wrong

The bug is in ext2.c, in the one function that turns a filesystem block number into a disk address:

--- chapter14/os/os/ext2.c
+++ iii_lba/os/os/ext2.c
@@ -22,7 +22,7 @@
 
 static int read_block(uint32_t block, void *buf)
 {
-    return ata_read_sectors(EXT2_PARTITION_LBA + block * sectors_per_block,
+    return ata_read_sectors(EXT2_PARTITION_LBA + (block + 1) * sectors_per_block,
                             sectors_per_block, buf);
 }

An off-by-one of the kind that appears when someone remembers that “block 0 is the boot record, so data starts at block 1” and corrects for it in the wrong place. The serial output:

Hello World from the kernel!
CPU: GenuineIntel, QEMU Virtual CPU version 2.5+ (family 6, model 6, stepping 3)
ata: primary master "QEMU HARDDISK", 16384 sectors (8192 KiB)
ext2: volume "os01", block size 1024, 1792 inodes, 7168 blocks, revision 1
/: not a directory
/bin: not a directory
/etc/motd: not found
/log.txt: no such directory
ext2: wrote -1 bytes to /log.txt
/log.txt: not found
/: not a directory
exec /bin/hello: no such file
exec /bin/count: no such file
all processes finished, 32447 frames free

Nothing faults, nothing panics, the disk driver reports no error and the superblock is perfect: the right label, the right counts. Then the root directory is “not a directory”. This is the hardest kind of bug, the one where every component says it is fine, and the table’s advice is: when a device returns success and the data is wrong, print what you asked for, not what you got. One line in read_block:

    kprintf("read_block(%u): LBA %u\n", block,
            EXT2_PARTITION_LBA + (block + 1) * sectors_per_block);

and the output becomes:

ata: primary master "QEMU HARDDISK", 16384 sectors (8192 KiB)
read_block(2): LBA 2054
ext2: volume "os01", block size 1024, 1792 inodes, 7168 blocks, revision 1
read_block(0): LBA 2050
/: not a directory
read_block(0): LBA 2050
/bin: not a directory

Two things are visible at once. The superblock was never read through read_block, it has its own EXT2_PARTITION_LBA + 2 in ext2_mount, which is why the mount succeeded: the bug is below the first thing that uses read_block. And every inode is read from block 0. Block 0 is the boot record, never an inode table; the inode table of group 0 comes from the group descriptor, and the group descriptor was read by read_block(2) at LBA 2054. With 1 KiB blocks, two sectors per block and the filesystem starting at sector 2048, block 2 is sectors 2052 and 2053. We asked for 2054.

The host has the same disk image and better tools, and this is the moment to use them. xxd at the two addresses:

$ xxd -s $((2052*512)) -l 32 build/disk.img
00100800: 1e00 0000 1f00 0000 2000 0000 081a ef06  ........ .......
00100810: 0400 0400 0000 0000 0000 0000 0000 0000  ................
$ xxd -s $((2054*512)) -l 32 build/disk.img
00100c00: 0000 0000 0000 0000 0000 0000 0000 0000  ................
00100c10: 0000 0000 0000 0000 0000 0000 0000 0000  ................

At 2052 there is a group descriptor as chapter 14 described it: block bitmap at 0x1e = 30, inode bitmap at 31, inode table at 32. At 2054 there are zeros, which the kernel read as “inode table at block 0” and never complained about, since 0 is a valid number. debugfs from e2fsprogs agrees about what should have been found, reading the image at the partition offset:

$ debugfs -R stats "build/disk.img?offset=1048576" | grep "Group  0"
 Group  0: block bitmap at 30, inode bitmap at 31, inode table at 32

Under gdb the same picture, from the kernel’s side, with a breakpoint on the driver and finish to see what came back:

(gdb) b ata_read_sectors
Breakpoint 2 at 0x10699: file ata.c, line 155.
(gdb) c

Breakpoint 2, ata_read_sectors (lba=2050, count=2 '\002', buf=0x170a0 <sb_raw>) at ata.c:155
155     uint8_t *p = buf;
(gdb) c

Breakpoint 2, ata_read_sectors (lba=2054, count=2 '\002', buf=0x174c0 <group_table>) at ata.c:155
155     uint8_t *p = buf;
(gdb) bt
#0  ata_read_sectors (lba=2054, count=2 '\002', buf=0x174c0 <group_table>) at ata.c:155
#1  0x0001134b in read_block (block=2, buf=0x174c0 <group_table>) at ext2.c:25
#2  0x00011467 in ext2_mount () at ext2.c:60
#3  0x0001318b in kmain () at kernel.c:112
#4  0x0001011b in _start () at entry.asm:30
(gdb) p sb.s_first_data_block
$1 = 1
(gdb) p sectors_per_block
$2 = 2
(gdb) finish
0x0001134b in read_block (block=2, buf=0x174c0 <group_table>) at ext2.c:25
25      return ata_read_sectors(EXT2_PARTITION_LBA + (block + 1) * sectors_per_block,
Value returned is $3 = 0
(gdb) x/8wx group_table
0x174c0 <group_table>:  0x00000000  0x00000000  0x00000000  0x00000000
0x174d0 <group_table+16>:   0x00000000  0x00000000  0x00000000  0x00000000

The first read is the superblock at 2050, correct; the second, block=2 for the group descriptor table, asks for 2054 where 2048 + 2 × 2 = 2052 was meant; the driver returns 0, success, and group_table is all zeros. The fix removes the + 1. Note what the driver’s success means: the ATA command was executed and sectors were transferred. The disk did exactly what it was told. Every layer that reports “fine” is only telling you that its input made sense, and the bug is always in the layer that computed that input.

Two neighbors of this bug belong in the same case. The first is the sector count rather than the LBA: outb(ATA_SECTOR_COUNT, count - 1) makes the drive prepare one sector fewer than the loop reads, and the loop then polls a drive that has nothing to give; chapter 14’s driver gives up after a million polls and prints ata: read error at LBA 2051 (status 0x50, error 0x0), status 0x50 being RDY and DSC with no DRQ, the picture of an idle drive, and ext2_mount then panics with no ext2 filesystem at sector 2048, which is the wrong diagnosis. Read the first error, not the last. A driver written from the usual examples, with an unbounded while (!(inb(ATA_STATUS) & DRQ)), hangs there silently instead, and the frozen-machine recipe applies: attach gdb, x/i $pc shows the in instruction inside the wait loop, and monitor i /b 0x1f7 shows the 0x50. The second neighbor is the controller itself. Run the chapter 14 image with the chapter 13 command line, -drive format=raw,file=build/disk.img,if=ide and no -device piix3-ide, and every register reads 0xff:

(gdb) monitor i /b 0x1f7
portb[0x01f7] = 0xff
(gdb) monitor i /b 0x1f6
portb[0x01f6] = 0xff

Chapter 14 explained why: on q35 the disk went to the AHCI controller, and nothing answers at 0x1F0. The kernel’s ata_identify recognizes 0xff as a floating bus and reports no drive, and kmain panics with a message that names the Makefile; a driver that does not check would wait for BSY to clear, forever, since 0xff has BSY set. The monitor’s i /b is the instrument for this whole family of bugs: it reads the port the kernel is polling, from outside, and either confirms that the device is where the kernel thinks it is or shows that it is not.

16.3.4 The case we did not need: a hang with no fault at all

One symptom deserves a transcript even though it fits no fault: the kernel simply stops, in the middle of its output, with interrupts enabled and no exception in the log. We removed the end-of-interrupt from isr_dispatch, two lines, and the chapter 14 kernel printed everything up to the two exec lines and went quiet. gdb attached to the running machine:

$ make gdb
...output omitted...
kmain () at kernel.c:133
133         if (task_reap() == 0)
Breakpoint 1 at 0x130e3: file kernel.c, line 92.
(gdb) info registers eip eflags
eip            0x13221             0x13221 <kmain+327>
eflags         0x202               [ IOPL=0 IF ]
(gdb) x/i $pc
=> 0x13221 <kmain+327>: jmp    0x13217 <kmain+317>
(gdb) p ticks
$1 = 1
(gdb) p current_task->name
$2 = 0x15e2c "idle"
(gdb) monitor info pic
pic0: irr=01 imr=fc isr=01 hprio=0 irq_base=20 rr_sel=0 elcr=00 fnm=0
pic1: irr=40 imr=ff isr=00 hprio=0 irq_base=28 rr_sel=0 elcr=0c fnm=0
...output omitted...
(gdb) monitor info irq
IRQ statistics for isa-i8259:
 0: 397
 4: 1
14: 133
IRQ statistics for ioapic:
 0: 397
 4: 1
14: 133

The idle loop of kmain, IF set, so interrupts are allowed, and ticks is 1: exactly one timer interrupt was ever delivered. The PIC says why. irr=01: IRQ 0 is requested again. imr=fc: IRQ 0 and 1 are unmasked. isr=01: IRQ 0 is still in service; the controller is waiting for the EOI of the first tick before it raises the second, and it has been waiting through 397 ticks of the timer. The scheduler runs on the timer, so no task ever ran, and the idle task reaps nothing forever. A kernel that works for one keystroke and then ignores the keyboard is the same bug with isr=02. info pic costs one command and answers the question that -d int cannot, because the interrupts that were never delivered are not in the log.

16.4 Exercises

16.5 Check your understanding

1. The serial output of a crashed kernel ends in the middle of a line. What does that tell you, and what does it not tell you?

2. Why is the first interrupt after sti delivered at the instruction after the one following sti, and why does this matter when you read the EIP of a triple fault?

3. -d int shows v=0d e=0000 from ring 3 just after a v=80. The error code is zero. Is the gate for 0x80 the problem? What else could raise this?

4. A page fault reports error code 0x5 with CR2 = 0x1d000, the address of ticks. Decode it. What kind of code touched the address, and should the kernel panic? What would an error code of 0x0 at the same address mean instead?

5. Why does bt stop or print nonsense after isr_common, and why would the same happen in a user program compiled with -fomit-frame-pointer?

6. A kernel prints the right message, then reboots. -d int shows nothing after the last v=20. What kind of bug produces a reset without any exception in the log, and how would you confirm it?

7. Case 3’s driver returned success for a read that produced zeros. What would it have to check to return an error instead, and why is it reasonable that it does not?

8. Why does the chapter recommend committing every version that passes make test, rather than every version that compiles?