HowToDebugVKernels
Introduction
The purpose of this document is to introduce the reader with vkernel debugging. The vkernel architecture allows us to run DragonFly kernels in userland. These virtual kernels can be paniced or otherwise abused, without affecting the host operating system.
To make things a bit more interesting, we will use a real life example.
Once upon a time
... I wrote a simple program that used the AIO interface. As it turned out we don't support this feature, but at that point I didn't know.
$ gcc t_aio.c -o t_aio -Wall -ansi -pedantic
$ ./t_aio
aio_read: Function not implemented
$
$
Ktrace'ing the process and seeing with my own eyes what was going on, seemed like a good idea. Here comes the fun. I misread the ktrace(1) man page and typed:
$ ktrace -c ./t_aio
And the system hang.
My intention was to track the system calls of t_aio, but what I typed would actually disable all traces from all processes to ktrace.out, the default tracing file. Out of pure luck, a bug has been discovered.
Setup a vkernel
To setup a vkernel, please consult this man page. It's very straightforward.
Reproduce the problem
We boot into our vkernel:
# cd /var/kernel
# ./boot/kernel -m 64m -r rootimg.01 -I auto:bridge0
[...]
login: root
#
And then try to reproduce the system freeze:
# ktrace -c ./t_aio
Fatal trap 12: page fault while in kernel mode
mp_lock = 00000001; cpuid = 1
fault virtual address = 0x0
fault code = supervisor read, page not present
instruction pointer = 0x1f:0x80aca52
stack pointer = 0x10:0x5709d914
frame pointer = 0x10:0x5709dbe0
processor eflags = interrupt enabled, resume, IOPL = 0
current process = 692 (ktrace)
current thread = pri 6
<- SMP: XXX
kernel: type 12 trap, code=4
CPU1 stopping CPUs: 0x00000001
stopped
Stopped at 0x80aca52: movl 0(%eax),%eax
db>
This db> prompt is from ddb(4), the interactive kernel debugger. The
fault virtual address = 0x0
field is indicative of a NULL pointer dereference inside the kernel.
Let's get a trace of what went wrong:
db> trace
ktrdestroy(57082700,5709dc5c,0,57082700,5709dca0) at 0x80aca52
allproc_scan(80aca14,5709dc5c,be,2,0) at 0x80b2e91
sys_ktrace(5709dca0,6,0,0,57082700) at 0x80acffe
syscall2(5709dd40,6,57082700,0,0) at 0x8214b6d
user_trap(5709dd40,570940e8,8214185,0,8215462) at 0x8214d9c
go_user(5709dd38,0,0,7b,0) at 0x82151ac
db>
Here sys_ktrace, allproc_scan, etc represent function names. Functions are listed in the reverse order they were called. Thus, in this particular example, the last function which was called is ktrdestroy(). The hex values in parentheses are the first five items on the stack. Since ddb doesn't really know how many arguments a function takes, it always prints five. The last hex value is the instruction address.
Gdb
Quoting from vkernel(7):
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 andhandle SIGUSR1 noprint' to ignore signals used for simulating inter-processor interrupts (SMP build only).
You can add these two commands in your ~/.gdbinit to save yourself from typing them again and again.
$ cat ~/.gdbinit
handle SIGSEGV noprint
handle SIGUSR1 noprint
So we are going to attach to the vkernel process:
# ps aux | grep kernel
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
# gdb kernel 25408
GNU gdb 6.7.1
[...]
Let's get a trace from inside gdb:
(gdb) bt
#0 0x282d60d0 in read () from /usr/lib/libc.so.6
#1 0x2828389f in read () from /usr/lib/libthread_xu.so.2
#2 0x0821cd86 in vconsgetc (private=0x56758168) at /usr/src/sys/platform/vkernel/platform/console.c:373
#3 0x080e431d in cngetc () at /usr/src/sys/kern/tty_cons.c:482
#4 0x080813d0 in db_readline (lstart=0x82806a0 "", lsize=120) at /usr/src/sys/ddb/db_input.c:314
#5 0x08081c43 in db_read_line () at /usr/src/sys/ddb/db_lex.c:55
#6 0x080804ff in db_command_loop () at /usr/src/sys/ddb/db_command.c:467
#7 0x08082ef8 in db_trap (type=12, code=4) at /usr/src/sys/ddb/db_trap.c:71
#8 0x082125aa in kdb_trap (type=12, code=4, regs=0x5746c8cc) at /usr/src/sys/platform/vkernel/i386/db_interface.c:151
#9 0x082143e1 in trap_fatal (frame=0x5746c8cc, usermode=<value optimized out>, eva=0)
at /usr/src/sys/platform/vkernel/i386/trap.c:1031
#10 0x0821453e in trap_pfault (frame=0x5746c8cc, usermode=0, eva=0) at /usr/src/sys/platform/vkernel/i386/trap.c:948
#11 0x0821468d in kern_trap (frame=0x5746c8cc) at /usr/src/sys/platform/vkernel/i386/trap.c:709
#12 0x0821528c in exc_segfault (signo=11, info=0x5746cb98, ctxp=0x5746c8b8)
at /usr/src/sys/platform/vkernel/i386/exception.c:181
#13 <signal handler called>
#14 0x080aca52 in ktrace_clear_callback (p=0x567480c0, data=0x5746cc5c) at /usr/src/sys/kern/kern_ktrace.c:347
#15 0x080b2e91 in allproc_scan (callback=0x80aca14 <ktrace_clear_callback>, data=0x5746cc5c)
at /usr/src/sys/kern/kern_proc.c:533
#16 0x080acffe in sys_ktrace (uap=0x5746cca0) at /usr/src/sys/kern/kern_ktrace.c:276
#17 0x08214b6d in syscall2 (frame=0x5746cd40) at /usr/src/sys/platform/vkernel/i386/trap.c:1273
#18 0x08214d9c in user_trap (frame=0x5746cd40) at /usr/src/sys/platform/vkernel/i386/trap.c:413
#19 0x082151ac in go_user (frame=0x5746cd38) at /usr/src/sys/platform/vkernel/i386/trap.c:1473
#20 0x08215462 in pmsg4 () at /usr/src/sys/platform/vkernel/i386/fork_tramp.s:103
(gdb)
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.:
(gdb) print ((struct proc *)0x567480c0)->p_pid
$6 = 690
(gdb)
Let's try this time to break into the kernel before it crashes. sys_ktrace() seems like a good candidate. We stop the old vkernel and fire off a new one. Once we are logged in, we attach to it as before:
# gdb kernel 25532
GNU gdb 6.7.1
[...]
(gdb) break sys_ktrace
Breakpoint 1 at 0x80acf43: file ./machine/thread.h, line 83.
(gdb)
Next we type 'c' in the gdb prompt to resume vkernel execution:
(gdb) c
Continuing.
We switch now to our vkernel and type in the offending command:
# ktrace -c
Gdb stops the execution of vkernel and a message pops up in gdb buffer:
Breakpoint 1, sys_ktrace (uap=0x573e2ca0) at ./machine/thread.h:83
83 __asm ("movl %%fs:globaldata,%0" : "=r" (gd) : "m"(__mycpu__dummy));
(gdb)
At this point, kernel hasn't paniced yet, because we are inside sys_ktrace(). 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:
276 allproc_scan(ktrace_clear_callback, &info);
we 'step' inside it. The alloproc_scan() function, iterates through the process list and calls ktrace_clear_callback() for each one of them. Later we see this:
347 if (p->p_tracenode->kn_vp == info->tracenode->kn_vp) {
Here p is a pointer to the current process:
(gdb) print p
$1 = (struct proc *) 0x57098c00
Let's see if this process is traced (if it is, the p->p_tracenode->kn_vp shall point to a vnode where all logs are directed):
(gdb) print p->p_tracenode
$2 = (struct ktrace_node *) 0x0
(gdb)
Oops. There is no trace to any vnode for this process. The code will try to access p->p_tracenode->kn_vp and is bound to crash. This is the zero virtual address we saw before. It seems that the kernel tries to disable tracing of all processes indiscriminately, even of those that aren't traced. Now that we know the root of problem we write a patch and poke someone to review/commit it.
Possible places of confusion
(gdb) bt
#0 0x282d4c10 in sigsuspend () from /usr/lib/libc.so.6
#1 0x28287eb2 in sigsuspend () from /usr/lib/libthread_xu.so.2
#2 0x0821530a in stopsig (nada=24, info=0x40407d2c, ctxp=0x40407a4c) at /usr/src/sys/platform/vkernel/i386/exception.c:112
#3 <signal handler called>
#4 0x282d4690 in umtx_sleep () from /usr/lib/libc.so.6
#5 0x08213bde in cpu_idle () at /usr/src/sys/platform/vkernel/i386/cpu_regs.c:722
#6 0x00000000 in ?? ()
(gdb)
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.
Additional notes
Accessing Vkernels memory
For those using HEAD, some changes in libkvm have been introduced so vkernel's memory can be accessed directly now on /proc/$pid/mem.
Among other things, you can have a look at vkernel's process list using ps:
# ps axl -M /proc/829/mem -N /var/vkernel/boot/kernel
UID PID PPID CPU PRI NI VSZ RSS WCHAN STAT TT TIME COMMAND
0 0 -1 1 152 0 0 3068 nowork DL ?? 0:00.00 (swapper)
0 1 0 0 152 0 760 3068 wait IL ?? 0:00.00 (init)
77 212 1 0 152 0 788 3068 poll S ?? 0:00.00 (dhclient)
0 323 1 0 152 0 1288 3068 select S ?? 0:00.00 (syslogd)
0 627 1 115 222 0 3332 3068 select I ?? 0:00.00 (sshd)
0 641 1 0 152 0 3772 3068 select S ?? 0:00.00 (sendmail)
25 645 1 22 165 0 3668 3068 pause I ?? 0:00.00 (sendmail)
0 0 0 0 0 -52 0 0 - ? con- 0:00.00 ()
0 0 0 0 0 -52 0 0 - ? con- 0:00.00 ()
0 0 0 0 0 -52 0 0 - ? con- 0:00.00 ()
0 188 1 2 153 0 788 3068 poll I v0- 0:00.00 (dhclient)
Bugs
Gdb + vkernel issues
gdb and vkernel (SMP or not) don't play well together anymore. It is possible to get into a state where the vkernel is in state "stop" and the vkernel is in "wait", and nothing moves on. The only help is to kill gdb, which either makes the vkernel run again, or kills it as well.
See also bugs.dragonflybsd.org/issues/1301.
Experience has shown that running vkernel with -n1, that is telling it to emulate only 1 CPU, alleviates the issue.
Bug noted above appears to have been closed, however, this does not appear to work on current STABLE.
[...] 4.4-RELEASE DragonFly v4.4.3.9.ge5cb2-RELEASE #0: Fri Jul 15 03:04:52 UTC 2016 [...]/X86_64_GENERIC x86_64See bugs.dragonflybsd.org/issues/2931 for details.
-- tofergus