Minor fix in link
[ikiwiki.git] / docs / howtos / HowToDebugVKernels / index.mdwn
1 # Introduction
2 The purpose of this document is to introduce the reader with vkernel debugging.
3 The vkernel architecture allows us to run DragonFly kernels in userland. These virtual
4 kernels can be paniced or otherwise abused, without affecting the host operating system.
5
6 To make things a bit more interesting, we will use a real life example.
7
8 # Once upon a time
9 ... I wrote a simple program that used the AIO interface. As it turned out we don't support
10 this feature, but at that point I didn't know.
11
12     $ gcc t_aio.c -o t_aio -Wall -ansi -pedantic
13     $ ./t_aio 
14     aio_read: Function not implemented
15     $ 
16
17 Ktrace'ing the process and seeing with my own eyes what was going on, seemed like a good idea.
18 Here comes the fun. I misread the [ktrace(1)](http://leaf.dragonflybsd.org/cgi/web-man?command=ktrace&section=1) man page and typed:
19
20     $ ktrace -c ./t_aio
21
22 And the system hang.
23
24 (My intention was to track the system calls of t_aio, but what I typed would actually disable all traces from all process to the t_aio file.)
25
26 # Setup a vkernel
27 To setup a vkernel, please consult [this man page](http://leaf.dragonflybsd.org/cgi/web-man?command=vkernel&section=ANY).
28 It's very straightforward.
29
30
31 # Reproduce the problem
32 We boot into our vkernel:
33
34     # cd /var/kernel
35     # ./boot/kernel -m 64m -r rootimg.01 -I auto:bridge0
36     [...]
37     login: root
38     #
39 And then try to reproduce the system freeze:
40
41     # ktrace -c ./t_aio
42
43     Fatal trap 12: page fault while in kernel mode
44     mp_lock = 00000001; cpuid = 1
45     fault virtual address   = 0x0
46     fault code              = supervisor read, page not present
47     instruction pointer     = 0x1f:0x80aca52
48     stack pointer           = 0x10:0x5709d914
49     frame pointer           = 0x10:0x5709dbe0
50     processor eflags        = interrupt enabled, resume, IOPL = 0
51     current process         = 692 (ktrace)
52     current thread          = pri 6 
53      <- SMP: XXX
54     kernel: type 12 trap, code=4
55     
56     CPU1 stopping CPUs: 0x00000001
57      stopped
58     Stopped at      0x80aca52:      movl    0(%eax),%eax
59     db> 
60
61 This db> prompt is from [ddb(4)](http://leaf.dragonflybsd.org/cgi/web-man?command=ddb&section=4), the interactive kernel debugger.
62 The
63
64     fault virtual address   = 0x0
65
66 field is indicative of a NULL pointer dereference inside the kernel.
67
68 Let's get a trace of what went wrong:
69
70     db> trace
71     ktrdestroy(57082700,5709dc5c,0,57082700,5709dca0) at 0x80aca52
72     allproc_scan(80aca14,5709dc5c,be,2,0) at 0x80b2e91
73     sys_ktrace(5709dca0,6,0,0,57082700) at 0x80acffe
74     syscall2(5709dd40,6,57082700,0,0) at 0x8214b6d
75     user_trap(5709dd40,570940e8,8214185,0,8215462) at 0x8214d9c
76     go_user(5709dd38,0,0,7b,0) at 0x82151ac
77     db> 
78
79 sys_ktrace, allproc_scan, etc represent the function names. The hex values in parentheses are the first five items on the stack.
80 The last hex value is the instruction address. Since ddb doesn't really know how many arguments a function takes, it always prints five.
81
82 # Gdb
83
84 Quoting from [vkernel(7)](http://leaf.dragonflybsd.org/cgi/web-man?command=vkernel&section=7):
85
86 It is possible to directly gdb the virtual kernel's process.  It is recommended that you do a `handle SIGSEGV noprint' to ignore page faults processed by the virtual kernel itself and `handle SIGUSR1 noprint' to ignore signals used for simulating inter-processor interrupts (SMP build only).
87
88 You can add these two commands in your ~/.gdbinit to save yourself from typing them again and again.
89
90     $ cat ~/.gdbinit
91     handle SIGSEGV noprint
92     handle SIGUSR1 noprint
93
94 So we are going to attach to the vkernel process:
95
96     # ps aux | grep kernel
97     root  25408  0.0  2.3 1053376 17772  p0  IL+   8:32PM   0:06.51 ./boot/kernel -m 64m -r rootimg.01 -I auto:bridge0
98     # gdb kernel 25408
99     GNU gdb 6.7.1
100     [...]
101
102 Let's get a trace from inside gdb:
103
104     (gdb) bt
105     #0  0x282d60d0 in read () from /usr/lib/libc.so.6
106     #1  0x2828389f in read () from /usr/lib/libthread_xu.so.2
107     #2  0x0821cd86 in vconsgetc (private=0x56758168) at /usr/src/sys/platform/vkernel/platform/console.c:373
108     #3  0x080e431d in cngetc () at /usr/src/sys/kern/tty_cons.c:482
109     #4  0x080813d0 in db_readline (lstart=0x82806a0 "", lsize=120) at /usr/src/sys/ddb/db_input.c:314
110     #5  0x08081c43 in db_read_line () at /usr/src/sys/ddb/db_lex.c:55
111     #6  0x080804ff in db_command_loop () at /usr/src/sys/ddb/db_command.c:467
112     #7  0x08082ef8 in db_trap (type=12, code=4) at /usr/src/sys/ddb/db_trap.c:71
113     #8  0x082125aa in kdb_trap (type=12, code=4, regs=0x5746c8cc) at /usr/src/sys/platform/vkernel/i386/db_interface.c:151
114     #9  0x082143e1 in trap_fatal (frame=0x5746c8cc, usermode=<value optimized out>, eva=0)
115         at /usr/src/sys/platform/vkernel/i386/trap.c:1031
116     #10 0x0821453e in trap_pfault (frame=0x5746c8cc, usermode=0, eva=0) at /usr/src/sys/platform/vkernel/i386/trap.c:948
117     #11 0x0821468d in kern_trap (frame=0x5746c8cc) at /usr/src/sys/platform/vkernel/i386/trap.c:709
118     #12 0x0821528c in exc_segfault (signo=11, info=0x5746cb98, ctxp=0x5746c8b8)
119         at /usr/src/sys/platform/vkernel/i386/exception.c:181
120     #13 <signal handler called>
121     #14 0x080aca52 in ktrace_clear_callback (p=0x567480c0, data=0x5746cc5c) at /usr/src/sys/kern/kern_ktrace.c:347
122     #15 0x080b2e91 in allproc_scan (callback=0x80aca14 <ktrace_clear_callback>, data=0x5746cc5c)
123         at /usr/src/sys/kern/kern_proc.c:533
124     #16 0x080acffe in sys_ktrace (uap=0x5746cca0) at /usr/src/sys/kern/kern_ktrace.c:276
125     #17 0x08214b6d in syscall2 (frame=0x5746cd40) at /usr/src/sys/platform/vkernel/i386/trap.c:1273
126     #18 0x08214d9c in user_trap (frame=0x5746cd40) at /usr/src/sys/platform/vkernel/i386/trap.c:413
127     #19 0x082151ac in go_user (frame=0x5746cd38) at /usr/src/sys/platform/vkernel/i386/trap.c:1473
128     #20 0x08215462 in pmsg4 () at /usr/src/sys/platform/vkernel/i386/fork_tramp.s:103
129     (gdb) 
130
131 At this point we can examine the data of various variables. Keep in mind that bare addresses must be cast to the respective data type, prior to accessing. E.g.:
132
133     (gdb) print ((struct proc *)0x567480c0)->p_pid
134     $6 = 690
135     (gdb) 
136
137
138 Let's try this time to break into the kernel _before_ it crashes. sys_ktrace() seems like a good candidate.
139
140     # gdb kernel 25532
141     GNU gdb 6.7.1
142     [...]
143     (gdb) break sys_ktrace
144     Breakpoint 1 at 0x80acf43: file ./machine/thread.h, line 83.
145     (gdb) 
146
147 Next we type 'c' in the gdb prompt to resume vkernel execution:
148
149     (gdb) c
150     Continuing.
151
152 Now we go to our vkernel and type the offending command:
153
154     # ktrace -c 
155
156 Gdb stops the execution of vkernel and a message pops up in gdb buffer:
157
158     Breakpoint 1, sys_ktrace (uap=0x573e2ca0) at ./machine/thread.h:83
159     83          __asm ("movl %%fs:globaldata,%0" : "=r" (gd) : "m"(__mycpu__dummy));
160     (gdb) 
161
162 We navigate through source code with the 'step' and 'next' gdb commands. They are identical, except that 'step' follows function calls. When we meet this call:
163
164     276                     allproc_scan(ktrace_clear_callback, &info);
165
166 we 'step' inside it. alloproc_scan() iterates through the process list and applies the ktrace_clear_callback() to each one of them.
167 Later we see this:
168
169     347                     if (p->p_tracenode->kn_vp == info->tracenode->kn_vp) {
170
171 Here p is a pointer to the current process:
172
173     (gdb) print p
174     $1 = (struct proc *) 0x57098c00
175
176 Let's see if this process is traced:
177
178     (gdb) print p->p_tracenode
179     $2 = (struct ktrace_node *) 0x0
180     (gdb) 
181
182 Oops. There is no trace to a vnode for this process. The code will try to access p->p_tracenode and is bound to crash. This is the zero virtual address we saw before.
183
184 # Possible errors
185
186     (gdb) bt
187     #0  0x282d4c10 in sigsuspend () from /usr/lib/libc.so.6
188     #1  0x28287eb2 in sigsuspend () from /usr/lib/libthread_xu.so.2
189     #2  0x0821530a in stopsig (nada=24, info=0x40407d2c, ctxp=0x40407a4c) at /usr/src/sys/platform/vkernel/i386/exception.c:112
190     #3  <signal handler called>
191     #4  0x282d4690 in umtx_sleep () from /usr/lib/libc.so.6
192     #5  0x08213bde in cpu_idle () at /usr/src/sys/platform/vkernel/i386/cpu_regs.c:722
193     #6  0x00000000 in ?? ()
194     (gdb) 
195
196 Why does it differ from the ddb's trace ?
197 Well, when the vkernel is sitting at a db> prompt all vkernel threads representing virtual cpu's except the one handling the db> prompt itself will be suspended in stopsig(). The backtrace only sees one of the N threads.