はじめに
前回記事の続きとして、カーネルクラッシュダンプを解析する方法について書きました。"カーネルクラッシュダンプを解析した経験のない人向け" の記事です。
この記事では、カーネルクラッシュダンプ (以降、クラッシュダンプと表現) の解析に必要なツール類を導入したあと、実際に解析をしてみるという流れになっています。
なお、解析方法 (確認観点) はクラッシュの原因により変わりますので、この記事では一例として、NULL ポインタ参照により意図的にクラッシュさせた環境のダンプ（前回記事と同じ Magic SysRq Key）を用いて解析します。原因は判明していますが、解析のなんとなくのイメージを掴むには良いと思いました。
解析環境を整える
解析には、次の3つが必要です。
- クラッシュダンプ (vmcore)
- カーネルのデバッグ情報
- crash コマンド
クラッシュダンプ
まずはクラッシュダンプ (vmcore) が必要です。
もしクラッシュダンプの取り方を知らない場合は、前回記事を参考に取得してください。
カーネルのデバッグ情報
解析には、クラッシュダンプを取得した環境のカーネルに対応するデバッグ情報が必要です。クラッシュダンプを取得した環境のカーネル (バージョン) は、strings コマンドから確認できます。
[root@localhost ~]# strings <vmcore 配置パス>/vmcore | head KDUMP Linux localhost.localdomain 3.10.0-957.el7.x86_64 ...(snip)...
デバッグ情報は、次のコマンドからインストールできます (3.10.0-957.el7.x86_64 の場合)。
[root@localhost ~]# yum install --enablerepo=base-debuginfo kernel-debuginfo-3.10.0-957.el7
インストールに成功すると、/usr/lib/debug/usr/lib/modules/<カーネルバージョン>/ ディレクトリ配下に vmlinux が格納されます (後で使います)。
[root@localhost ~]# ls /usr/lib/debug/usr/lib/modules/3.10.0-957.el7.x86_64/ kernel vdso vmlinux
crash コマンド
解析ツールとして crash コマンドが必要です。次のコマンドからインストールできます。
[root@localhost ~]# yum install crash
クラッシュダンプを解析する
解析するには、次のようにデバッグ情報とクラッシュダンプを crash コマンドに渡して実行します。
[root@localhost ~]# crash /usr/lib/debug/usr/lib/modules/<カーネルバージョン>/vmlinux <vmcore 配置パス>/vmcore
しらばらくすると (読み込みに成功すると)、次のように表示されます。
crash 7.2.3-8.el7
...(snip)...
KERNEL: /usr/lib/debug/usr/lib/modules/3.10.0-957.el7.x86_64/vmlinux
DUMPFILE: /var/crash/127.0.0.1-2019-04-25-21:24:51/vmcore [PARTIAL DUMP]
CPUS: 1
DATE: Thu Apr 25 21:24:41 2019
UPTIME: 14:22:25
LOAD AVERAGE: 0.00, 0.01, 0.05
TASKS: 457
NODENAME: localhost.localdomain
RELEASE: 3.10.0-957.el7.x86_64
VERSION: #1 SMP Thu Nov 8 23:39:32 UTC 2018
MACHINE: x86_64 (2599 Mhz)
MEMORY: 3 GB
PANIC: "SysRq : Trigger a crash"
PID: 5013
COMMAND: "bash"
TASK: ffff927722ec1040 [THREAD_INFO: ffff92771e70c000]
CPU: 0
STATE: TASK_RUNNING (SYSRQ)
crash>
各文字列の意味は次表のとおりです。
| 文字列 | 意味 |
|---|---|
| KERNEL: | crash の引数に与えた vmlinux のパス |
| DUMPFILE: | crash の引数に与えた vmlinux のパス |
| CPUS: | クラッシュしたマシンの CPU 数 |
| DATE: | クラッシュ発生日時 |
| UPTIME: | クラッシュしたマシンの稼働時間 |
| LOAD AVERAGE: | クラッシュ時のロードアベレージ |
| TASKS: | クラッシュ時のタスク数 |
| NODENAME: | クラッシュしたマシンのノード名 |
| RELEASE: | クラッシュしたマシンのカーネルバージョン |
| VERSION: | 上記カーネル (RELEASE:) のリリース日 |
| MACHINE: | クラッシュしたマシンの CPU のアーキテクチャ |
| MEMORY: | クラッシュしたマシンの物理メモリサイズ |
| PANIC: | クラッシュの種類やメッセージなどの情報 |
| PID: | クラッシュ時に動作していたプロセスの ID |
| COMMAND: | PID: に対応するプロセス名 |
| TASK: | PID: に対応するプロセスのアドレス |
| CPU: | PID に対応するプロセスが 実行されていた CPU コア番号 |
| STATE: | PID に対応するプロセスの状態 |
mod -S でモジュール情報を読み込む
本格的に解析を始める前に crash> mod -Sで、ロードされている全てのカーネルモジュールのデバッグ情報を読み込んでおいた方が良いです。これをしておかないと、特定のモジュールに関連した関数などの情報を確認する際に対応するデバッグ情報を読み込まなくてはいけない (crash> mod -s <モジュール名>) ので面倒です。
crash> mod -S
MODULE NAME SIZE OBJECT FILE
ffffffffc02f5880 dm_mod 124407 /usr/lib/debug/usr/lib/modules/3.10.0-957.el7.x86_64/kernel/drivers/md/dm-mod.ko.debug
ffffffffc0302000 dm_region_hash 20813 /usr/lib/debug/usr/lib/modules/3.10.0-957.el7.x86_64/kernel/drivers/md/dm-region-hash.ko.debug
ffffffffc030f160 dm_log 18411 /usr/lib/debug/usr/lib/modules/3.10.0-957.el7.x86_64/kernel/drivers/md/dm-log.ko.debug
...(snip)...
log から状況を把握する
クラッシュ時のリングバッファからは様々な情報が確認できます。まずはここからクラッシュ時の状況を把握するのが良いと思います。
crash> log [ 0.000000] Initializing cgroup subsys cpuset ...(snip)... [51745.467192] SysRq : Trigger a crash
次の２行からNULL ポインタ参照が直接の原因であることと、sysrq_handle_crash 関数がその引き金となったことがわかります 1。
[51745.467352] BUG: unable to handle kernel NULL pointer dereference at (null) [51745.467356] IP: [<ffffffff9d461bf6>] sysrq_handle_crash+0x16/0x20
次の行は参照しようとしたアドレスのページテーブル情報です。
[51745.467403] PGD 8000000098f52067 PUD a9306067 PMD 0
Oops: の後ろにある 0002 (2進数: 0010) はエラーコードです。
2進数表記にした時の各 bit の意味を左から順に説明すると次のとおりです。
- 1 bit 目 ... 1 なら命令フェッチに成功、0 なら失敗
- 2 bit 目 ... 1 ならユーザモード、0 ならカーネルモード
- 3 bit 目 ... 1 なら書き込みアクセス、0 なら読み取り or 実行アクセス
- 4 bit 目 ... 1 なら無効なアクセス、0 ならページが存在しなかった
[51745.467411] Oops: 0002 [#1] SMP
Modules linked in: 以降の文字列はロード済みモジュールの情報です。
[51745.467420] Modules linked in: tcp_lp fuse uinput xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun devlink ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter sunrpc ppdev iosf_mbi crc32_pclmul ghash_clmulni_intel snd_hda_codec_generic aesni_intel lrw gf128mul glue_helper ablk_helper cryptd joydev pcspkr snd_hda_intel virtio_balloon snd_hda_codec snd_hda_core sg snd_hwdep snd_seq snd_seq_device snd_pcm parport_pc parport [51745.467499] snd_timer snd soundcore i2c_piix4 ip_tables xfs libcrc32c sr_mod cdrom virtio_blk virtio_console virtio_net crct10dif_pclmul crct10dif_common crc32c_intel ata_generic serio_raw qxl pata_acpi drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm floppy drm ata_piix libata virtio_pci virtio_ring virtio drm_panel_orientation_quirks dm_mirror dm_region_hash dm_log dm_mod
次の行にある情報は crash コマンドの起動時に表示される情報とほとんど同じです。この中で注目すべき箇所は Not tainted という文字列です。これは、カーネルが汚染されていないことを示します。汚染要因は様々ですが、汚染されている場合は、Tainted: P のように表示されます (詳細は割愛)。
[51745.467550] CPU: 0 PID: 5013 Comm: bash Kdump: loaded Not tainted 3.10.0-957.el7.x86_64 #1
次の行は文字通りハードウェアの名の情報です (今回は KVM 上でクラッシュさせました)。なお、ハードウェア名は dmicode コマンドなどでも確認できます。
[51745.467555] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014
次の行はクラッシュ時に動作していたプロセスのアドレスなどの情報です。
[51745.467559] task: ffff927722ec1040 ti: ffff92771e70c000 task.ti: ffff92771e70c000
RIP から CR2 はクラッシュ時のレジスタの情報です。
[51745.467563] RIP: 0010:[<ffffffff9d461bf6>] [<ffffffff9d461bf6>] sysrq_handle_crash+0x16/0x20 [51745.467576] RSP: 0018:ffff92771e70fe58 EFLAGS: 00010246 [51745.467580] RAX: ffffffff9d461be0 RBX: ffffffff9dce4c60 RCX: 0000000000000000 [51745.467583] RDX: 0000000000000000 RSI: ffff92773fc13898 RDI: 0000000000000063 [51745.467585] RBP: ffff92771e70fe58 R08: ffffffff9dfe38bc R09: ffffffff9dfee37b [51745.467591] R10: 000000000000025c R11: 000000000000025b R12: 0000000000000063 [51745.467594] R13: 0000000000000000 R14: 0000000000000004 R15: 0000000000000000 [51745.467598] FS: 00007fbedb513740(0000) GS:ffff92773fc00000(0000) knlGS:0000000000000000 [51745.467601] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [51745.467603] CR2: 0000000000000000 CR3: 000000009ce18000 CR4: 00000000001606f0
コールトレースの情報です。
[51745.467610] Call Trace: [51745.467617] [<ffffffff9d46241d>] __handle_sysrq+0x10d/0x170 [51745.467628] [<ffffffff9d462888>] write_sysrq_trigger+0x28/0x40 [51745.467645] [<ffffffff9d2b7f30>] proc_reg_write+0x40/0x80 [51745.467650] [<ffffffff9d2410a0>] vfs_write+0xc0/0x1f0 [51745.467654] [<ffffffff9d241ebf>] SyS_write+0x7f/0xf0 [51745.467680] [<ffffffff9d774ddb>] system_call_fastpath+0x22/0x27
RIP が示すアドレスから 64 バイト分までのコードの情報です。
[51745.467682] Code: eb 9b 45 01 f4 45 39 65 34 75 e5 4c 89 ef e8 e2 f7 ff ff eb db 0f 1f 44 00 00 55 48 89 e5 c7 05 21 57 7e 00 01 00 00 00 0f ae f8 <c6> 04 25 00 00 00 00 01 5d c3 0f 1f 44 00 00 55 31 c0 c7 05 9e
前述したレジスタの情報と同じです (内容が重複していることもあるようです)。
[51745.467750] RIP [<ffff92771e70fe58>] sysrq_handle_crash+0x16/0x20 [51745.467755] RSP <ffff92771e70fe58> [51745.467757] CR2: 0000000000000000
bt でバックトレースを確認する
クラッシュに至るまでの処理の流れなどを確認してみます。
(内容的には前述のコールトレースと一部被ります)
crash> bt PID: 5013 TASK: ffff927722ec1040 CPU: 0 COMMAND: "bash" #0 [ffff92771e70fa98] machine_kexec at ffffffff9d063674 #1 [ffff92771e70faf8] __crash_kexec at ffffffff9d11ce12 #2 [ffff92771e70fbc8] crash_kexec at ffffffff9d11cf00 #3 [ffff92771e70fbe0] oops_end at ffffffff9d76c758 #4 [ffff92771e70fc08] no_context at ffffffff9d75aa7e #5 [ffff92771e70fc58] __bad_area_nosemaphore at ffffffff9d75ab15 #6 [ffff92771e70fca8] bad_area at ffffffff9d75ae25 #7 [ffff92771e70fcd0] __do_page_fault at ffffffff9d76f821 #8 [ffff92771e70fd40] trace_do_page_fault at ffffffff9d76f9c6 #9 [ffff92771e70fd80] do_async_page_fault at ffffffff9d76ef42 #10 [ffff92771e70fda0] async_page_fault at ffffffff9d76b788
[exception RIP: sysrq_handle_crash+22] からは、関数のどの行 (オフセット) でクラッシュしたのかがわかります (実際にクラッシュ処理を実行するのは、async_page_fault などのそれより先にある処理)。この行と対応するソースは crash> dis sysrq_handle_crash or crash> dis sysrq_handle_crash+22 から確認できます (この辺は後述)。
[exception RIP: sysrq_handle_crash+22]
RIP: ffffffff9d461bf6 RSP: ffff92771e70fe58 RFLAGS: 00010246
RAX: ffffffff9d461be0 RBX: ffffffff9dce4c60 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffff92773fc13898 RDI: 0000000000000063
RBP: ffff92771e70fe58 R8: ffffffff9dfe38bc R9: ffffffff9dfee37b
R10: 000000000000025c R11: 000000000000025b R12: 0000000000000063
R13: 0000000000000000 R14: 0000000000000004 R15: 0000000000000000
CS: 0010 (2進数: 10000) からは、クラッシュ時に動作していた CPU の特権レベル (CPL: Current Privilege Level) を確認できます。CPL は CS レジスタの下位 2bit から判断できます。00 (0) ならカーネル (特権) モード、11 (3) ならユーザ (非特権) モードの意味です。
今回の場合は下位 2bit が 00 なのでカーネルモードで動作していたと判断できます。
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#11 [ffff92771e70fe60] __handle_sysrq at ffffffff9d46241d
#12 [ffff92771e70fe90] write_sysrq_trigger at ffffffff9d462888
#13 [ffff92771e70fea8] proc_reg_write at ffffffff9d2b7f30
#14 [ffff92771e70fec8] vfs_write at ffffffff9d2410a0
#15 [ffff92771e70ff08] sys_write at ffffffff9d241ebf
#16 [ffff92771e70ff50] system_call_fastpath at ffffffff9d774ddb
RIP: 00007fbedabfefd0 RSP: 00007ffd4a5b6e38 RFLAGS: 00010202
RAX: 0000000000000001 RBX: 0000000000000002 RCX: 0000000000000063
RDX: 0000000000000002 RSI: 00007fbedb523000 RDI: 0000000000000001
RBP: 00007fbedb523000 R8: 000000000000000a R9: 00007fbedb513740
R10: 00007fbedb513740 R11: 0000000000000246 R12: 00007fbedaed7400
R13: 0000000000000002 R14: 0000000000000001 R15: 0000000000000000
ORIG_RAX: 0000000000000001 CS: 0033 SS: 002b
dis で関数の中身を確認する
crash> bt から sysrq_handle_crash+22 の行が引き金となり、クラッシュしたことがわかりました。この行では何をしているのか crash> dis sysrq_handle_crash で関数を確認すると、+22 の行は movb $0x1,0x0 であることがわかりました。0 番地への書き込みなので、これにより NULL ポインタ参照によるクラッシュが発生したと考えられます。
crash> dis sysrq_handle_crash 0xffffffff9d461be0 <sysrq_handle_crash>: nopl 0x0(%rax,%rax,1) [FTRACE NOP] 0xffffffff9d461be5 <sysrq_handle_crash+5>: push %rbp 0xffffffff9d461be6 <sysrq_handle_crash+6>: mov %rsp,%rbp 0xffffffff9d461be9 <sysrq_handle_crash+9>: movl $0x1,0x7e5721(%rip) # 0xffffffff9dc47314 0xffffffff9d461bf3 <sysrq_handle_crash+19>: sfence 0xffffffff9d461bf6 <sysrq_handle_crash+22>: movb $0x1,0x0 0xffffffff9d461bfe <sysrq_handle_crash+30>: pop %rbp 0xffffffff9d461bff <sysrq_handle_crash+31>: retq
実際のカーネルソースとも比較してみます。この中で 1 を書き込もうとしているのは、143 行目と145 行目で、書き込み先が NULL となるのは 145 行目です。145 行目の *killer には 135 行目で NULL が渡されています。また位置的に考えても 145 行目の *killer = 1 が movb $0x1,0x0 の対応行であるのは間違いなさそうです (より確実な確認方法については後述)。
このことを踏まえると、今回の事象は NULL を指している *killer へ 1 を書き込もうとしたところ NULL ポインタ参照となり、アクセス例外でクラッシュが発生...という流れだったと考えられます。
drivers/tty/sysrq.c 133 static void sysrq_handle_crash(int key) 134 { 135 char *killer = NULL; 136 137 /* we need to release the RCU read lock here, 138 * otherwise we get an annoying 139 * 'BUG: sleeping function called from invalid context' 140 * complaint from the kernel before the panic. 141 */ 142 rcu_read_unlock(); 143 panic_on_oops = 1; /* force panic */ 144 wmb(); 145 *killer = 1; 146 }
なお、カーネルソースとの対応を確認するには、次のような方法もあります。
crash> dis -s sysrq_handle_crashを実行。 -> 指定した関数と対応するソースコードをそのまま表示。crash> dis -l sysrq_handle_crashを実行。 -> 指定した関数と対応するソースコードの行数のみを表示。通常のターミナル上で
<カーネルソース>/scripts/faddr2line /usr/lib/debug/usr/lib/modules/<カーネルバージョン>/vmlinux sysrq_handle_crash+22を実行。 -> 指定した関数とオフセット値(+22)に対応するソースコードの行数をピンポイントで表示 (これをあえて使う場面は思いつきませんが、こんな方法もあるというメモ)。
その他、トピックス
解析的には以上で終了ですが、crash コマンドで確認できることはその他にも色々あるため、今回の事象に関連していそうなものをいくつか紹介します。
RDI レジスタを確認する
crash> bt などで確認できる RDI レジスタには関数に渡される第一引数の値が入っています。この値を確認することで、クラッシュ時に実行された関数の引数 (第1引数) を知ることができます 2。
sysrq_handle_crash の第一引数は int 型の key でした。構造体などの場合はアドレスが入っているため、値を確認するのが面倒 (crash> p ((struct hoge *) address)->member など)ですが、値がそのまま入っている場合は、crash> ascii で16進数を ascii に変換すれば確認できます。
133 static void sysrq_handle_crash(int key) ...(snip)...
第一引数には c が入っていたようです。
crash> ascii 0000000000000063 0000000000000063: c<NUL><NUL><NUL><NUL><NUL><NUL><NUL>
ps でプロセスを確認する
クラッシュしたプロセス (5013) の状態も確認してみます。
crash> ps 5013 PID PPID CPU TASK ST %MEM VSZ RSS COMM > 5013 5005 0 ffff927722ec1040 RU 0.1 116832 3688 bash
メモリ使用量などに高騰は見られません。普通です。親プロセス (5005) も見てみます。
crash> ps 5005 PID PPID CPU TASK ST %MEM VSZ RSS COMM 5005 1 0 ffff927726bce180 IN 0.8 681112 26560 gnome-terminal-
こちらも特に異常は見られません (gnome-terminal- が途中で切れていますが、gnome-terminal-server のことだと思います)。
files でオープンファイルを確認する
クラッシュしたプロセスである bash (5013) が何をオープンしていたのか見てみます。
FD が 1 (標準出力) の行に /proc/sysrq-trigger があります。クラッシュ時には、bash プロセスの標準出力先が /proc/sysrq-trigger になっています。
crash> files 5013 PID: 5013 TASK: ffff927722ec1040 CPU: 0 COMMAND: "bash" ROOT: / CWD: /var/crash FD FILE DENTRY INODE TYPE PATH 0 ffff92771e6c9600 ffff9277394e79c0 ffff927739c2b720 CHR /dev/pts/0 1 ffff927731f8c200 ffff9276d9cc3840 ffff9276d9d259e0 REG /proc/sysrq-trigger 2 ffff92771e6c9600 ffff9277394e79c0 ffff927739c2b720 CHR /dev/pts/0 10 ffff92771e6c9600 ffff9277394e79c0 ffff927739c2b720 CHR /dev/pts/0 255 ffff92771e6c9600 ffff9277394e79c0 ffff927739c2b720 CHR /dev/pts/0
fuser でファイルや inode を使用しているプロセスを確認する
files とは逆に指定のファイルや inode を使用しているプロセスを確認できます。/proc/sysrq-trigger を使用しているのは bash のようです。
crash> fuser /proc/sysrq-trigger PID TASK COMM USAGE 5013 ffff927722ec1040 "bash" fd
help を眺める
解析に詰まったら、help を眺めてみて、色々試してみるのもありです。新しい手がかりが掴めるかもしれません。
crash> help
* extend log rd task
alias files mach repeat timer
ascii foreach mod runq tree
bpf fuser mount search union
bt gdb net set vm
btop help p sig vtop
dev ipcs ps struct waitq
dis irq pte swap whatis
eval kmem ptob sym wr
exit list ptov sys q
...(snip)...
help bt のようにすることで、bt のオプションなどを確認することもできます。
crash> help bt
NAME
bt - backtrace
SYNOPSIS
bt [-a|-c cpu(s)|-g|-r|-t|-T|-l|-e|-E|-f|-F|-o|-O|-v] [-R ref] [-s [-x|d]]
[-I ip] [-S sp] [pid | task]
DESCRIPTION
Display a kernel stack backtrace. If no arguments are given, the stack
trace of the current context will be displayed.
-a displays the stack traces of the active task on each CPU.
(only applicable to crash dumps)
-A same as -a, but also displays vector registers (S390X only).
...(snip)...
crash コマンドを自動で実行させる
log や bt などよく使うコマンドを crash の起動と共に自動で実行させる方法を紹介します。
まずは、次のように bt などのコマンドを列挙したファイルを用意します。
log bt q
crash コマンド実行時、-i オプションと共に上記のファイルを指定すると、ファイルに列挙されている crash コマンドを自動で実行させることができます。
[root@localhost ~]# crash -i crash_cmd.txt /usr/lib/debug/usr/lib/modules/<カーネルバージョン>/vmlinux <vmcore 配置パス>/vmcore ...(snip)... crash> log ...(snip)... crash> bt ...(snip)... crash> q [root@localhost ~]#
補足情報
検証環境
- カーネル:
3.10.0-957.el7.x86_64 - ディストリビューション:
CentOS Linux release 7.6.1810 (Core) - crash:
crash-7.2.3-8.el7.x86_64
参考
Web
- White Paper: Red Hat Crash Utility
- Analyzing Linux kernel crash dumps with crash - The one tutorial that has it all
- RHEL7 カーネルクラッシュダンプガイド
- ダンプ解析講座 第4回: crashコマンドの準備
- ダンプ解析講座 第5回: crashコマンドによるダンプ解析（1）
- wikipedia: 呼出規約
