不安定なカーネルモジュールのやっつけ方
始めに
最近コード変更を行った自作のファイルシステムがあまりに不安定で頻繁に Panic および Hang を引き起こして core 解析にさんざん時間を取られてたのですが、このままこの時間を無駄にしては悔しいのでカーネル core 解析ネタでエントリ書いておきます。
調査対象
今回問題になっているのは Solaris カーネルにロードされているファイルシステムモジュールですが、デバイスドライバでも基本的な初期調査としては同じかと思います。
プラットフォームとしては x86 Solaris 11 Express, x86 OpenIndiana 上で共通して発生した問題を取り上げています。(基本的には OpenIndiana を想定しています)
事前準備
カーネルモジュールに問題が発生した場合システムが Panic し、カーネルメモリイメージをダンプデバイスに書き出します。再起動後このメモリイメージを savecore(1M) コマンドでクラッシュダンプファイルとして保存しますが、その際にあらかじめ決められたディレクトリが存在しないと保存できないので、保存先ディレクトリがあるかどうかを確認し、なければ作成します。
設定済みの保存先を確認
ルートユーザにて dumpadm(1M) を実行し Savecore directory を確認します。
# /usr/sbin/dumpadm Dump content: kernel pages Dump device: /dev/zvol/dsk/rpool/dump (dedicated) Savecore directory: /var/crash/oi148 Savecore enabled: no Save compressed: on
※ デフォルトでは /var/crash/"ノード名" です。
この例では oi148 がノード名です。uname(1M) コマンドで確認できます。
$ uname -n
oi148
保存先ディレクトリの作成
もし既存ディレクトリがなければ作成します。
# /usr/bin/mkdir -p /var/crash/oi148 #
※ デフォルトでは作成されていないようです
再起動後の savecore の自動実行設定
Panic 発生後の再起動時に savecore(1M) コマンドを自動実行するように設定します。
設定は root ユーザで dumpadm(1M) コマンドを用いて行います。
# /usr/sbin/dumpadm -y Dump content: kernel pages Dump device: /dev/zvol/dsk/rpool/dump (dedicated) Savecore directory: /var/crash/oi148 Savecore enabled: yes Save compressed: on
kmem_flags のセット
このパラメータの設定は必須ではありません。でももし Panic の発生契機やタイミングが分かっている場合には、このパラメータをセットした上で再現させればメモリアクセス関わる問題箇所をみつけるヒントを発見できるかもしれません。
root ユーザで /etc/system ファイルに以下の行を追加
set kmem_flags = 0x7
カーネルパラメータで上記の値をセットすると
- カーネルメモリの確保時/開放時の情報(スタックトレース等)の維持
- すでに解放されたアドレスへのアクセスのチェック
- 確保した領域外のアドレスへのアクセスチェック
が行われます。
なお、このパラメータをセットした場合、CPU に余計な負荷がかかりますし、システムメモリも余計に消費されますので普段から設定しておくのは避けたほうが良いです。
カーネルデバッガでの調査
クラッシュダンプファイルの確認
Panic 発生後のシステム起動後に、root ユーザでクラッシュダンプが作成されているかどうかを確認します。
# cd /var/crash/oi148 # ls bounds vmdump.1
もしなかったら自動的にクラッシュダンプをファイルに書き出すことができなかったようです。
上述の Savecore directory が存在するどうか再度確認したうえで savecore(1M) を実行し手動でクラッシュダンプファイルとして書き出します。
# ls /var/crash/oi148 bounds # /usr/sbin/savecore
圧縮ダンプファイルの解凍
デフォルトではダンプファイルは圧縮されて保存されているので savecore(1M) コマンドで解凍します。
# cd /var/crash/oi148 # ls bounds vmdump.1 # /usr/sbin/savecore -vf vmdump.1 : # ls bounds unix.1 vmcore.1 vmdump.1
デバッガの起動
事前に保存、解凍してあるクラッシュダンプファイルを指定してデバッガ mdb(1M) を起動します
# /usr/bin/mdb -k 1 Loading modules: [ unix genunix specfs dtrace mac cpu.generic uppc pcplusmp scsi_vhci zfs ip hook neti sockfs arp usba stmf stmf_sbd fctl idm mpt crypto sd md random fcp cpc smbsrv nfs fcip lofs sppp ufs logindmux ptm nsmb ] >
※ -k でカーネルクラッシュダンプのデバッグであることを指定し、「1」はダンプファイルの通し番号を指定します。例では 1 ですが、クラッシュダンプファイルが増えてくれば、 vmcore.1, vmcore.2 ...といった感じで増えていきます。
コンソールメッセージの出力
msgbuf コマンドを使って Panic 直前にコンソールに吐き出されたメッセージを確認します。Panic を引き起こしたスレッドのスタックトレース、Panic 発生時のレジスター値が表示されます。
簡単な問題であればこの情報とソースの参照だけからでもかなり問題箇所を絞り込むことができます。
/var/adm/messages ファイルに吐き出されなかったデバッグメッセージが見れる場合もありますので、警告やエラー等 Panic 直前のヒントが得られる可能性もあります。
> ::msgbuf : panic[cpu1]/thread=d9bb2480: BAD TRAP: type=e (#pf Page fault) rp=ecc4fac4 addr=baddcafe occurred in module "<unknown>" due to an il legal access to a user address mkfile: #pf Page fault Bad kernel fault at addr=0xbaddcafe pid=1031, pc=0xddcafeba, sp=0xfea6efd6, eflags=0x10206 cr0: 80050033<pg,wp,ne,et,mp,pe> cr4: 6b8<xmme,fxsr,pge,pae,pse,de> cr2: baddcafe cr3: 32de040 gs: d38201b0 fs: dc4c0000 es: ecc40160 ds: fe980160 edi: 0 esi: e9cb05c0 ebp: ecc4fb6c esp: ecc4fafc ebx: db7c2880 edx: 0 ecx: 2000 eax: ddcafeba trp: e err: 2 eip: ddcafeba cs: 158 efl: 10206 usp: fea6efd6 ss: db7c2880 ecc4fa00 unix:die+93 (e, ecc4fac4, baddca) ecc4fab0 unix:trap+1463 (ecc4fac4, baddcafe,) ecc4fac4 unix:_cmntrap+7c (d38201b0, dc4c0000,) ecc4fb6c ddcafeba (db7c2880, 2000, 0, ) ecc4fc0c genunix:segmap_fault+1b9 (d43f7f58, fec26e60,) ecc4fcac genunix:as_fault+4c1 (d43f7f58, fec23da0,) ecc4fd0c unix:pagefault+1ac (d2d50000, 0, 2, 1) ecc4fdbc unix:trap+136f (ecc4fdd0, d2d50000,) ecc4fdd0 unix:_cmntrap+7c (1b0, 0, 160, ecc401) ecc4fe24 unix:kzero+23 (d2d4f800, fff, 1, 0) ecc4fea4 iumfs:iumfs_write+2c9 (db7c2b80, ecc4ff3c,) ecc4fef4 genunix:fop_write+4a (db7c2b80, ecc4ff3c,) ecc4ff84 genunix:write+2bb (3, 805189c, 1, ecc4) syncing file systems... done dumping to /dev/zvol/dsk/rpool/dump, offset 65536, content: kernel
Panic が発生したアドレスを確認すると addr が '0xbaddcafe' (バッドカフェ)になってます。
BAD TRAP: type=e (#pf Page fault) rp=ecc4fac4 addr=baddcafe occurred in module "<unknown>" due to an il ^^^^^^^^^^^^^
これは前述の kmem_flags の設定によって初期化されていないメモリ領域に設定される値です。
つまり 'baddcafe' にアクセスているような様子が見えたら初期化されていないアドレスにアクセスしてしまっているということです。
スタックトレースを見ると iumfs_write という IUMFS ファイルシステムの関数が kzero というカーネル関数を呼び出しているところのようです。kzero は libc の bzero(3c) の様に指定アドレスを範囲を 0x0 で埋めるものです。
スタックトレースの kzero から先のフレームでは
- 指定範囲のアドレスに該当するページが存在しないため trap が発生
- pagefault が呼び出され該当アドレス範囲ののセグメントドライバのページフォルトの処理関数が呼び出される
- セグメントドライバ(ここでは seg_map ドライバ)が当該 VNODE にの属するファイルシステムの VOP_GETPAGE(ページ取得)ルーチンを呼びだそうとするがアドレスが 'baddcafe' で Panic!
という流れになっています。
実際には上のように Panic がおきたフレームまでの流れを全て調査して理解するには少々時間がかかりますが(後述)、ぶっちゃけ途中のカーネルモジュールに問題がある可能性は低いので、きっかけになった自作ファイルシステムモジュールの kzero 関数の呼び出し引数が悪い(泣)、と容易に想像できます。
それで、問題のコードがこちら。
iumfs_vnode.c
/* * 作成したページの未使用の領域を 0 で埋める。 */ if (pagecreated) { if (uiop->uio_loffset & PAGEOFFSET || wsize == 0) { if(wsize > PAGESIZE){ cmn_err(CE_WARN, "iumfs_write: copyin size(%" PRId64 ") is larger than pagesize\n", wsize); } else { cmn_err(CE_WARN, "iumfs_write: copyin size %" PRId64 "\n", wsize); (void) kzero(uiomvbase + wsize, PAGESIZE - wsize); ^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^ 開始アドレス サイズ } }
これだけみてもわかないと思いますが、簡単にいうと下図でいうところの PAGESIZE 分を確保した直後で、uiomvbase のオフセット位置に wsize だけ書き込んだんだけど、PAGESIZE の残りの部分は使わないから 0x0 で埋めようとしている、という事です。
ところが、上記のコードでご覧いただけるように Need kzero の部分のサイズ計算が間違っているため、実際に確保した PAGESIZE を超過してアクセスが発生してしまいます。
これによって、不正アドレスへのアクセスが発生し panic に至ったということです。
で、正しく書きなおしたコードがこちら。
iumfs_vnode.c
/* * 作成したページの未使用の領域を 0 で埋める。 */ if (pagecreated) { if (uiop->uio_loffset & PAGEOFFSET || wsize == 0) { if(wsize > PAGESIZE){ cmn_err(CE_WARN, "iumfs_write: copyin size(%" PRId64 ") is larger than pagesize\n", wsize); } else { (void) kzero(uiomvbase + wsize, PAGESIZE - (preloff + wsize)); ^^^^^^^^^^^^^^^^^^ ^^^^^^^^^^^^^^^^^^^^^^^^^^^^ } }
これで panic は発生しなくなりました。カーネルモジュールという点を除けば単純なバグ…かと思います。
追加調査
障害自体は上記のコード変更で修復しますが、ついでに Panic が発生した周辺を調査し、Panic に至った原因を詳細に解析してみます。
スタックの表示
上記では msgbuf を使って panic を引き起こしたスレッドのスタックトレースをみましたが, stackregs コマンドを使っても確認できます。
> ::stackregs ecc4fb6c 0xddcafeba(db7c2880, 2000, 0, 1000, ecc4fbe0, ecc4fbe4) ecc4fc0c segmap_fault+0x1b9(d43f7f58, fec26e60, d2d50000, 1000, 0, 2) ecc4fcac as_fault+0x4c1(d43f7f58, fec23da0, d2d50000, 1, 0, 2) ecc4fd0c pagefault+0x1ac(d2d50000, 0, 2, 1) ecc4fdbc trap+0x136f(ecc4fdd0, d2d50000, 1) ecc4fdd0 0xfe80037c() ecc4fe24 kzero+0x23() ecc4fea4 iumfs_write+0x2c9(db7c2b80, ecc4ff3c, 0, e9cb05c0, 0, dab41850) ecc4fef4 fop_write+0x4a(db7c2b80, ecc4ff3c, 0, e9cb05c0, 0, 1) ecc4ff84 write+0x2bb() ecc4ffac sys_sysenter+0x106() >
アセンブラの命令をデコード
上記の一番上の 0xddcafeba という怪しいアドレスを呼び出している segmap_fault という関数をディスアセンブルしてみます
> ::dis segmap_fault segmap_fault: pushl %ebp segmap_fault+1: movl %esp,%ebp segmap_fault+3: pushl %ebx segmap_fault+4: pushl %esi segmap_fault+5: pushl %edi : segmap_fault+0x1a6: leal -0x2c(%ebp),%eax segmap_fault+0x1a9: pushl %eax segmap_fault+0x1aa: pushl -0x38(%ebp) segmap_fault+0x1ad: pushl %edi segmap_fault+0x1ae: pushl -0x30(%ebp) segmap_fault+0x1b1: pushl -0x58(%ebp) segmap_fault+0x1b4: call +0x98113 <fop_getpage> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ segmap_fault+0x1b9: addl $0x30,%esp
fop_getpage という関数を呼びだそうとしたことが分かります。
ソースコードチェック
実行している OS は OpenIndiana oi_148 なので多少コードが違う可能性がありますが、OpenSolaris のコードをみると fop_getpage は第一引数として vnode_t 構造体を取ることが分かります。
http://cvs.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/fs/vnode.c#3842
3842 fop_getpage( 3843 vnode_t *vp, ^^^^^^^^^^^^ 3844 offset_t off, 3845 size_t len, 3846 uint_t *protp, 3847 page_t **plarr, 3848 size_t plsz, 3849 struct seg *seg, 3850 caddr_t addr, 3851 enum seg_rw rw, 3852 cred_t *cr, 3853 caller_context_t *ct) 3854 { 3855 int err; 3856 3857 VOPXID_MAP_CR(vp, cr); 3858 3859 err = (*(vp)->v_op->vop_getpage) ^^^^^^^^^^^^^^^^^^^^^^^^^ 3860 (vp, off, len, protp, plarr, plsz, seg, addr, rw, cr, ct); 3861 VOPSTATS_UPDATE(vp, getpage); 3862 return (err); 3863 }
そして fop_getpage の中では引数として受け取った vnode 構造体のメンバを手繰って vop_getpage という関数を呼びだそうとしているのが分かります。
関数の呼び出し引数を確認
x86 では関数を呼び出す前に引数を push 命令を使ってスタックに積んでおいて、呼び出し先の関数に渡します。
一番最後に push されたものが第一引数ですので
segmap_fault+0x1b1: pushl -0x58(%ebp) ^^^^^^^^^^^^^^^^^^^ %ebp に入っているアドレスに -0x58 したアドレス が指すデータをスタックにプッシュ。
が vnode_t 構造体であることが分かります。
%ebp はベースポインタのアドレスが入っているはずですが、スタックトレースより segmap_fault の ベースポインタは
ecc4fc0c segmap_fault+0x1b9(d43f7f58, fec26e60, d2d50000, 1000, 0, 2) ^^^^^^^
であることが分かります。なので、上記の vnode のアドレスは
> ecc4fc0c-0x58/X 0xecc4fbb4: db7c2880 ^^^^^^^^
だと判明します。
構造体のメンバーを表示する
主要なカーネルの構造体はアドレスを指定するだけで簡単にメンバを参照することができます。
先程の vnode_t 構造体のアドレスから中身を確認してみます。
> db7c2880::print vnode_t { v_lock = { _opaque = [ 0xdeadbeef, 0xdeadbeef ] } v_flag = 0xdeadbeef v_count = 0xdeadbeef v_data = 0xdeadbeef v_vfsp = 0xdeadbeef v_stream = 0xdeadbeef v_type = -0t559038737 (???) v_rdev = 0xdeadbeef v_vfsmountedhere = 0xdeadbeef v_op = 0xdeadbeef v_pages = 0xdeadbeef v_filocks = 0xdeadbeef v_shrlocks = 0xdeadbeef v_nbllock = { _opaque = [ 0xdeadbeef ] } v_cv = { _opaque = 0xbeef } v_locality = 0xdeadbeef v_femhead = 0xdeadbeef v_path = 0xdeadbeef v_rdcnt = 0xdeadbeef v_wrcnt = 0xdeadbeef v_mmap_read = 0xdeadbeefdeadbeef v_mmap_write = 0xdeadbeefdeadbeef v_mpssdata = 0xdeadbeef v_fopdata = 0xdeadbeef v_vsd_lock = { _opaque = [ 0xdeadbeef, 0xdeadbeef ] } v_vsd = 0xdeadbeef v_xattrdir = 0xdeadbeef v_count_dnlc = 0xdeadbeef }
もうこれ以上追うのが悲しくなるような状態です。><
値が軒並み 0xdeadbeef(デッドビーフ) となっているのは kmem_flags の設定のおかげで、すでに解放されたアドレスを見ているというのが分かります。
(kmem_flags を設定しているので解放されたアドレスに 0xdeadbeef という特別なデータを書きこんでくれています)
アドレスをフリーしたスタックを確認する。
kmem_flags を設定してればさらにこの vnode_t 構造体用のアドレスをフリーしたスタックも確認できます。
> db7c2880::whatis db7c2880 is freed from vn_cache: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ ADDR BUFADDR TIMESTAMP THREAD CACHE LASTLOG CONTENTS db8d9e98 db7c2880 23ced95ce7f8 db0cb940 d53e2208 d3ac66fc 0 kmem_cache_free_debug+0x10d kmem_cache_free+0x92 vn_free+0x8c fop_inactive+0xb8 vn_rele+0x5e iumfs_remove+0x65 fop_remove+0x7f vn_removeat+0x2b5 unlinkat+0x5d
vnode は問題の IUMFS ファイルシステムのものでしたが、極めて正常にフリーされているようです。
構造体メンバを追う
すでに 0xdeadbeef で埋め尽くされた構造体を追っても虚しいですが、最終的な Panic のきっかけになったところを突き止めるため無理やり構造体メンバを追います。
fop_getpage では vnode 構造体の v_op メンバからさらに vop_getpage のアドレスを得ています。
3859 err = (*(vp)->v_op->vop_getpage)
ヘッダファイルによると v_op は vnodeops 構造体へのポインタのようです。
/usr/include/sys/vnode.h
typedef struct vnode { : struct vnodeops *v_op; /* vnode operations */
vnodeops は同じく vnode.h に以下のように宣言してあります。
typedef struct vnodeops { const char *vnop_name; VNODE_OPS; /* Signatures of all vnode operations (vops) */ } vnodeops_t;
VNODE_OPS は各 VNODE オペレーション関数へのポインタが列記されています。
#define VNODE_OPS : int (*vop_getpage)(vnode_t *, offset_t, size_t, uint_t *, \ struct page **, size_t, struct seg *, \ caddr_t, enum seg_rw, cred_t *, \ caller_context_t *); \ :
構造体の中のメンバのオフセットは printf コマンドで分かります。
vnodeops 構造体の中でこの vop_getpage 関数のアドレスまでのオフセットは print コマンドで分かります。
> ::print -a vnodeops_t 0 { 0 vnop_name 4 vop_open : 70 vop_space 74 vop_realvp 78 vop_getpage ^^^^^^^^^^^^^^ :
構造体メンバの先頭にある数字がオフセットです。16進数表示ですので vop_getpage への オフセットは0x78 バイトということがわかります。
vnodeops 自体のアドレスは先程の vnode の構造体のダンプ結果から 0xdeadbeef (泣) とわかっているので、むりやりこのアドレスから 0x78 バイトのところをみてみます。(注: 0xdeadbeef はすでに無効なアドレスなので普通はこのアドレスからさらに追うのは無意味ですが、ここでは panic 箇所の特定のためむりやりデータを確認しています)
> 0xdeadbeef+0x78/X 0xdeadbf67: ddcafeba ^^^^^^^^
0xddcafeba というアドレスを vop_getpage関数 と思ってアクセスしようとしていたという事が分かります。
これは Panic メッセージにあった Panic が発生した命令のアドレスです。
pid=1031, pc=0xddcafeba, sp=0xfea6efd6, eflags=0x10206 ^^^^^^^^^
これでなぜ Panic 時 0xddcafeba というアドレスにある命令を実行しようとしていたのかは判明しました。
次に、さらにこのアドレスの命令をディスアセンブルしてみます。(もちろん結果は無意味なものです)
> ddcafeba/ai 0xddcafeba: 0xddcafeba: fnstsw 0xbaddcafe(%edx) ^^^^^^^^^^^^^^^^^^^
Intel の命令セットリファレンスによると、fnstsw という命令は「x87 FPU ステータス・ワードの現在値をデスティネーション・ロケーションにストアする」のだそうですが、どうでもいいですね。(苦笑)
ここでは %edx+0xbaddcafe というアドレスにアクセスするということになりますが、msgbuf コマンドの出力にもあったように %edx レジスタの値は 0x0 なのでつまり 0xbaddcafe にアクセスすることになります。
ebx: db7c2880 edx: 0 ecx: 2000 eax: ddcafeba ^^^^^^^^^
という訳で、めでたく(?) panic の原因となった 0xbaddcafe というアドレスの出所を探り当てることができました。