不安定なカーネルモジュールのやっつけ方

始めに

最近コード変更を行った自作のファイルシステムがあまりに不安定で頻繁に 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

カーネルパラメータで上記の値をセットすると

  1. カーネルメモリの確保時/開放時の情報(スタックトレース等)の維持
  2. すでに解放されたアドレスへのアクセスのチェック
  3. 確保した領域外のアドレスへのアクセスチェック

が行われます。

なお、このパラメータをセットした場合、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 から先のフレームでは

  1. 指定範囲のアドレスに該当するページが存在しないため trap が発生
  2. pagefault が呼び出され該当アドレス範囲ののセグメントドライバのページフォルトの処理関数が呼び出される
  3. セグメントドライバ(ここでは 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 で埋めようとしている、という事です。
f:id:kaizawa2:20110814223652p:image
ところが、上記のコードでご覧いただけるように Need kzero の部分のサイズ計算が間違っているため、実際に確保した PAGESIZE を超過してアクセスが発生してしまいます。
f:id:kaizawa2:20110814224126p:image
これによって、不正アドレスへのアクセスが発生し 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 というアドレスの出所を探り当てることができました。