my_knowledge.ko

Linux | Debug, Analyze, Trace | Tech | etc...

カーネルクラッシュダンプの解析方法 (crash コマンド)

はじめに

前回記事の続きとして、カーネルクラッシュダンプを解析する方法について書きました。"カーネルクラッシュダンプを解析した経験のない人向け" の記事です。

この記事では、カーネルクラッシュダンプ (以降、クラッシュダンプと表現) の解析に必要なツール類を導入したあと、実際に解析をしてみるという流れになっています。

なお、解析方法 (確認観点) はクラッシュの原因により変わりますので、この記事では一例として、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

次の2行から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 = 1movb $0x1,0x0 の対応行であるのは間違いなさそうです (より確実な確認方法については後述)。

このことを踏まえると、今回の事象は NULL を指している *killer1 を書き込もうとしたところ 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 コマンドを自動で実行させる

logbt などよく使うコマンドを 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
書籍

  1. 2行目にある IP: とは、Instruction Pointer のことです。実行中のプログラムの位置を指す実行ポインタを表しています。sysrq_handle_crash+0x16 で止まっているということは、ここでクラッシュしたということです。ちなみに sysrq_handle_crash+0x16/0x20 にある 0x16 は関数内の位置、0x20 は関数サイズを表しています。

  2. x86_64 Linux では、第1引数:RDI、第2引数:RSI、第3引数:RDX、第4引数:RCX、第5引数:R8、第6引数:R9、第7引数以降:スタック…という具合にレジスタを使います。