LinuxカーネルHack: gdbでICMPパケットの受信処理に割り込んでpingと戯れる
はじめに
UML上でネットワークに接続できるようになったので、ネットワークまわりで遊んでみる。
今回は、gdbでICMPパケット受信処理に人間が介入することで、pingの応答時間がインタラクティブに変わる様子を観察する。
失敗
gdbからlinuxプロセスを起動するやり方だと、ネットワークがうまくつながらない。
gdbからlinuxプロセスを起動しないと、ネットワークにつながるようだ。
linuxプロセスが起動し終わったら、gdbからlinuxにアタッチする作戦に切り替えよう。
以下に失敗の記録を残しておく。
% sudo gdb -args ~/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1
(gdb) handle SIGSEGV pass nostop noprint
Signal Stop Print Pass to program Description
SIGSEGV No No Yes Segmentation fault
(gdb) handle SIGUSR1 pass nostop noprint
Signal Stop Print Pass to program Description
SIGUSR1 No No Yes User defined signal 1
(gdb) b icmp_rcv
Breakpoint 1 at 0x819787a: file net/ipv4/icmp.c, line 975.
(gdb) r
[...]
仮想コンソールが立ち上がるタイミングで出る。
仮想コンソールが6枚立ち上がるので(gdb)cを残り5回実行。
>||
[New LWP 11016]
Executing new program: /usr/bin/xterm
(no debugging symbols found)
Error in re-setting breakpoint 1: Function "icmp_rcv" not defined.
Cannot access memory at address 0x83ff2847
(gdb) cここで固まった。ずっと待っても進まない。
* Starting basic networking...
諦めて、ホスト側でgdbを強制終了。xtermの残骸もついでに。
% sudo pkill -9 gdb % sudo pkill -9 xterm
起動しようとすると、起動しなくなった。。
% sudo ~/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1
[...]
F_SETLK failed, file already locked by pid 14597
Failed to lock 'uml-root-hardy.cow1', err = 11
Failed to open 'uml-root-hardy.cow1', errno = 11
ubda: Can't open "uml-root-hardy.cow1": errno = 11
Choosing a random ethernet address for device eth0
Netdevice 0 (fe:9b:fa:46:3a:dc) :
TUN/TAP backend -
F_SETLK failed, file already locked by pid 14597
Failed to lock 'uml-root-hardy.cow1', err = 11
Failed to open 'uml-root-hardy.cow1', errno = 11
ubda: Can't open "uml-root-hardy.cow1": errno = 11
VFS: Cannot open root device "98:0" or unknown-block(98,0)
Please append a correct "root=" boot option; here are the available partitions:
6200 4194308 ubda driver: uml-blkdev
Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(98,0)
09c5ced0: [<0805964a>] dump_stack+0x1c/0x22
09c5cee8: [<080714eb>] panic+0x50/0x13e
09c5cf20: [<080498fb>] mount_block_root+0x1f2/0x208
09c5cf78: [<0804995d>] mount_root+0x4c/0x54
09c5cf9c: [<08049a78>] prepare_namespace+0x113/0x13a
09c5cfa4: [<08049414>] kernel_init+0xf0/0xfc
09c5cfb4: [<08064e4f>] run_kernel_thread+0x37/0x3f
09c5cfe0: [<080588e7>] new_thread_handler+0x57/0x7e
09c5cffc: [<00000000>] 0x0
EIP: 0073:[<b80c6430>] CPU: 0 Not tainted ESP: 007b:bfcae9f8 EFLAGS: 00200246
Not tainted
EAX: 00000000 EBX: 000039ff ECX: 00000013 EDX: 000039ff
ESI: 000039fb EDI: b7f70aac EBP: bfcaea24 DS: 007b ES: 007b
09c5ce64: [<0806ac67>] show_regs+0xb4/0xb9
09c5ce90: [<0805a6be>] panic_exit+0x25/0x3b
09c5cea4: [<080874fe>] notifier_call_chain+0x27/0x4c
09c5cecc: [<0808753a>] __atomic_notifier_call_chain+0x17/0x19
09c5cedc: [<08087551>] atomic_notifier_call_chain+0x15/0x17
09c5cef8: [<08071506>] panic+0x6b/0x13e
09c5cf20: [<080498fb>] mount_block_root+0x1f2/0x208
09c5cf78: [<0804995d>] mount_root+0x4c/0x54
09c5cf9c: [<08049a78>] prepare_namespace+0x113/0x13a
09c5cfa4: [<08049414>] kernel_init+0xf0/0xfc
09c5cfb4: [<08064e4f>] run_kernel_thread+0x37/0x3f
09c5cfe0: [<080588e7>] new_thread_handler+0x57/0x7e
09c5cffc: [<00000000>] 0x0
Segmentation faultUMLのlinuxプロセスが生きたままになっていて、ロック状態になっているようなので、これも強制終了。
$ sudo pkill -9 linux
再度、起動。起動できるようになった。
% sudo ~/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1
仮想コンソール#1でログイン。
pingを打つと帰ってくる。
root@ubuntu-vm:~# ping 192.168.10.254 PING 192.168.10.254 (192.168.10.254) 56(84) bytes of data. 64 bytes from 192.168.10.254: icmp_seq=1 ttl=64 time=27.6 ms 64 bytes from 192.168.10.254: icmp_seq=2 ttl=64 time=0.171 ms 64 bytes from 192.168.10.254: icmp_seq=3 ttl=64 time=0.164 ms
pingと戯れる
gdbからlinuxにアタッチするためにlinuxプロセスのPIDを調べる。
なぜか、複数ヒットした。
linuxの起動処理のためにCPU時間を使っているもの(0:16)が親分か？
と考え、PIDが14911のプロセスにアタッチしてみる。
% ps aux | grep linux root 14911 1.4 2.1 37440 21504 pts/1 S+ 12:48 0:16 /home/xxx/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1 root 14918 0.0 2.1 37440 21504 pts/1 S+ 12:48 0:00 /home/xxx/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1 root 14919 0.0 2.1 37440 21504 pts/1 S+ 12:48 0:00 /home/xxx/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1 root 14920 0.0 2.1 37440 21504 pts/1 S+ 12:48 0:00 /home/xxx/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1 root 14921 0.0 0.0 788 592 pts/1 T+ 12:48 0:00 [linux] root 15168 0.1 0.0 672 436 pts/1 T+ 12:49 0:01 [linux] root 16091 0.0 0.0 632 624 pts/1 T+ 12:49 0:00 [linux] root 16133 0.0 0.0 844 844 pts/1 T+ 12:49 0:00 [linux] root 16134 0.0 0.0 508 504 pts/1 T+ 12:49 0:00 [linux] root 16175 0.0 0.1 37440 1912 pts/25 Ss+ 12:49 0:00 /home/xxx/linux-2.6/linux ubd0=uml-root-hardy.cow1,uml-root-hardy eth0=tuntap,tap0 umid=uml1 root 16180 0.0 0.0 1164 956 pts/1 T+ 12:50 0:00 [linux] root 16182 0.0 0.1 1544 1368 pts/1 T+ 12:50 0:00 [linux] xxx 16360 0.0 0.0 2816 796 pts/2 S+ 13:08 0:00 grep linux
失敗。linuxはrootユーザーで実行しているから、アタッチできないと。
% gdb -p 14911 GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu". Attaching to process 14911 ptrace: Operation not permitted.
これでいけた。
% sudo gdb -p 14911 GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "i486-linux-gnu". Attaching to process 14911 Reading symbols from /home/xxx/linux-2.6/linux...done. Reading symbols from /lib/tls/i686/cmov/libutil.so.1...done. Loaded symbols for /lib/tls/i686/cmov/libutil.so.1 Reading symbols from /lib/tls/i686/cmov/libc.so.6...done. Loaded symbols for /lib/tls/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...done. Loaded symbols for /lib/ld-linux.so.2 0xb7fe2430 in __kernel_vsyscall () (gdb) bt #0 0xb7fe2430 in __kernel_vsyscall () #1 0xb7f22c90 in nanosleep () from /lib/tls/i686/cmov/libc.so.6 #2 0x080662b9 in idle_sleep (nsecs=136458044) at arch/um/os-Linux/time.c:185 #3 0x080586f5 in default_idle () at arch/um/kernel/process.c:250 #4 0x08058aa0 in cpu_idle () at arch/um/kernel/process.c:258 #5 0x081af902 in rest_init () at init/main.c:455 #6 0x0804963b in start_kernel () at init/main.c:705 #7 0x0804a629 in start_kernel_proc (unused=0x0) at arch/um/kernel/skas/process.c:46 #8 0x08064e4f in run_kernel_thread (fn=0x804a5fd <start_kernel_proc>, arg=0x0, jmp_ptr=0x82247fc) at arch/um/os-Linux/process.c:267 #9 0x080588e7 in new_thread_handler () at arch/um/kernel/process.c:153 #10 0x00000000 in ?? ()
ICMPパケットの受信処理でブレークさせる。
(gdb) b icmp_rcv Breakpoint 1 at 0x819787a: file net/ipv4/icmp.c, line 975.
% ping 192.168.10.1 PING 192.168.10.1 (192.168.10.1) 56(84) bytes of data.
ブレークした。
バックトレースを取ってみる。
バックトレースにヒットした関数は重要そう。詳しくはまた今度見てみる。
Breakpoint 1, icmp_rcv (skb=0x9da0680) at net/ipv4/icmp.c:975
975 {
(gdb) bt
#0 icmp_rcv (skb=0x9c7a740) at net/ipv4/icmp.c:975
#1 0x0817910b in ip_local_deliver (skb=0x9c7a740) at net/ipv4/ip_input.c:226
#2 0x081795bf in ip_rcv (skb=0x9c7a740, dev=0x9ee9c00, pt=0x8234178, orig_dev=0x9ee9c00) at include/net/dst.h:317
#3 0x0816348d in __netif_receive_skb (skb=0x9c7a740) at net/core/dev.c:2931
#4 0x08165e2e in process_backlog (napi=0x8235e40, quota=1) at net/core/dev.c:3368
#5 0x08165f0f in net_rx_action (h=0x823c890) at net/core/dev.c:3526
#6 0x08075936 in __do_softirq () at kernel/softirq.c:219
#7 0x080759e4 in do_softirq () at kernel/softirq.c:266
#8 0x08075aa2 in irq_exit () at kernel/softirq.c:303
#9 0x08057fbb in do_IRQ (irq=5, regs=0x8223c78) at arch/um/kernel/irq.c:338
#10 0x080580a9 in sigio_handler (sig=29, regs=0x8223c78) at arch/um/kernel/irq.c:97
#11 0x08065bc6 in sig_handler_common (sig=29, sc=0x8223d24) at arch/um/os-Linux/signal.c:49
#12 0x08065eb5 in sig_handler (sig=164079424, sc=0x8223d24) at arch/um/os-Linux/signal.c:81
#13 0x08065e14 in handle_signal (sig=1, sc=0x8223d24) at arch/um/os-Linux/signal.c:158
#14 0x0806754b in hard_handler (sig=29) at arch/um/os-Linux/sys-i386/signal.c:12
#15 <signal handler called>
Backtrace stopped: previous frame inner to this frame (corrupt stack?)ここで実行を再開する。
(gdb) c
pingのレスポンスには、gdbで止めていた分、レスポンスが遅延して到着したことがわかる。
(gdb) cをするタイミングで、pingのレスポンスが返ってくるので、この様子を見ているだけでも面白い。
ICMPパケットの受信処理の実行タイミングを自分でコントロールできているという点で。
長時間、実行を止めていると、pingでエラーが出始めた。
こんなエラーを見たのははじめて。
64 bytes from 192.168.10.1: icmp_seq=15 ttl=64 time=3102 ms 64 bytes from 192.168.10.1: icmp_seq=16 ttl=64 time=4718 ms 64 bytes from 192.168.10.1: icmp_seq=17 ttl=64 time=6226 ms 64 bytes from 192.168.10.1: icmp_seq=18 ttl=64 time=23856 ms 64 bytes from 192.168.10.1: icmp_seq=19 ttl=64 time=23340 ms 64 bytes from 192.168.10.1: icmp_seq=20 ttl=64 time=22775 ms 64 bytes from 192.168.10.1: icmp_seq=21 ttl=64 time=22141 ms 64 bytes from 192.168.10.1: icmp_seq=22 ttl=64 time=21576 ms 64 bytes from 192.168.10.1: icmp_seq=23 ttl=64 time=20913 ms 64 bytes from 192.168.10.1: icmp_seq=24 ttl=64 time=20290 ms ping: sendmsg: No buffer space available ping: sendmsg: No buffer space available ping: sendmsg: No buffer space available
