--ホーム--
|
死亡例その2 (vfs_cluster.cのバグ)では次に,実際にバグを修正するまでの道のりを見てみます.今度は本当に原 因をみつけ,フィックスするまでの過程を説明します. 1996年3月2日から6月3日まで,vfs_cluster.cにとんでもないバグが潜 んでいました.これが見つかったきっかけはCD-ROMをマウントして egrep hogehoge */* を実行したらなぜか panic: vwakeup: neg numoutput と,パニックしてしまったからです.まずは, パニックを起こしたコードを見てみます.vfs_subr.cの vwakeup()という関数です.ソースは, vwakeup(bp) register struct buf *bp; { register struct vnode *vp; bp->b_flags &= ~B_WRITEINPROG; if ((vp = bp->b_vp)) { vp->v_numoutput--; if (vp->v_numoutput < 0) panic("vwakeup: neg numoutput"); if ((vp->v_numoutput == 0) && (vp->v_flag & VBWAIT)) { vp->v_flag &= ~VBWAIT; wakeup((caddr_t) &vp->v_numoutput); } } } となっています. vp->v_numoutput-- の結果が負になったのがパニックの原因です.どうしてこんなことになったの か調べて,CD-ROMにたいしてまともにアクセスできるようにするのがとりあえ ずの目標です. それではkgdbを立ちあげてみましょう.実際はログを無くしてしまっ たため,一部省略されています. kato@marble[84]% kgdb (kgdb) symbol-file kernel.debug (kgdb) exec-file /var/crash/kernel.1 (kgdb) core-file /var/crash/vmcore.1 /var/crashに二つのコアファイルがあるので,ピリオドの後の数字が1になっています. (kgdb) where #0 boot (howto=256) (...) #1 0xf0119207 in panic (...) #2 0xf0130de3 in vwakeup (...) #3 0xf012da6a in biodone (...) #4 0xf01861eb in cd:cd_strategy (...) #5 0xf018bd94 in scsi_strategy (...) #6 0xf0185dc8 in cd:cdstrategy (...) #7 0xf0138f1a in spec_strategy (...) #8 0xf0108030 in cd9660_vnops:cd9660_strategy (...) #9 0xf012eed3 in cluster_read (...) #10 0xf0107665 in cd9660_vnops:cd9660_read (...) #11 0xf0135b32 in vfs_vnops:vn_read (...) #12 0xf011a84f in read (...) #13 0xf01b823d in syscall (...) 今回はカーネル内でトラップが起こったわけではないので,frame pointerの 操作は必要ありません.上のリストを見てもtrap()なんて関数は呼び 出されていないですよね.#2はさきほどソースを見た vwakeup()関数です.それでは一気にvwakeup()を呼び出した部 分を見てみます. (kgdb) up 3 Reading in symbols for ../../kern/vfs_bio.c...done. #3 0xf012da6a in biodone (bp=(struct buf *) 0xf2c9ed14) (../../kern/vfs_bio.c line 1377) 1377 vwakeup(bp); リストを表示させると, (kgdb) list 1372 return; 1373 } 1374 bp->b_flags |= B_DONE; 1375 1376 if ((bp->b_flags & B_READ) == 0) { 1377 vwakeup(bp); 1378 } 1379 #ifdef BOUNCE_BUFFERS 1380 if (bp->b_flags & B_BOUNCE) 1381 vm_bounce_free(bp); となっています.buf構造体のb_flagsにB_READがセットされて いない場合にvwakeup()が呼び出されることがわかります.ここで変だ と気がつかないといけません.行なった操作はCD-ROMに対するものであり, B_READがセットされていない,すなわち書き込み操作が行なわれているのは異 常です.とりあえずb_flagsの内容を見ていきましょう. (kgdb) x bp 0xf2c9ed14 <end+44643220>: 0xf2c8d52c (kgdb) print bp->b_flags $4 = 68112 b_flagsの内容は,B_MALLOC | B_DONE | B_BUSY | B_ERROR です.こ の後,upやlistを使ったり,実際のソースファイルを覗き ながら以下の観点でたどっていきます.
すると,まず #3 0xf012da6a in biodone (...) のところで,biodone)()によってB_DONEがセットされることがわかり ます.さらにたどり, #4 0xf01861eb in cd:cd_strategy (...) のところでcd.cのcd_strategy()を読むことにより,ここが呼 び出された時にB_READがセットされていなかったためにB_ERRORを立ててから biodone()が呼び出されたことがわかります. さらにたどっていきます. #9 0xf012eed3 in cluster_read (...) これは,vfs_cluster.cのcluster_read()という関数です.こ こではどうもbuf構造体をいろいろいじっているようなので,気合いを 入れて見てみる必要があります.upで遡っていった場合,ここは, #9 0xf012eed3 in cluster_read (vp=(struct vnode *) 0xf0d92400, filesize=0x1800, lblkno=0, size=2048, cred=(struct ucred *) 0x0, bpp=(struct buf **) 0xefbffecc) (./vnode_if.h line 1116) 1116 return (VCALL((bp)->b_vp, VOFFSET(vop_strategy), &a)); となっています.これは,/sys/compile/HOGEHOGE/vnode_if.hの中身 です.そこの116行目付近を見ると,VOP_STRATEGYというマクロであることが わかります.vfs_cluster.cにはこのVOP_STRATEGYが /* * handle the synchronous read */ if (bp) { if (bp->b_flags & (B_DONE | B_DELWRI)) panic("cluster_read: DONE bp"); else { vfs_busy_pages(bp, 0); error = VOP_STRATEGY(bp); vp->v_maxra = bp->b_lblkno + bp->b_bcount / size; totreads++; totreadblocks += bp->b_bcount / size; curproc->p_stats->p_ru.ru_inblock++; } } と /* * and if we have read-aheads, do them too */ if (rbp) { vp->v_maxra = rbp->b_lblkno + rbp->b_bcount / size; if (error) { rbp->b_flags &= ~(B_ASYNC | B_READ); brelse(rbp); } else if (rbp->b_flags & B_CACHE) { rbp->b_flags &= ~(B_ASYNC | B_READ); bqrelse(rbp); } else { if ((rbp->b_flags & B_CLUSTER) == 0) vfs_busy_pages(rbp, 0); (void) VOP_STRATEGY(rbp); totreads++; totreadblocks += rbp->b_bcount / size; curproc->p_stats->p_ru.ru_inblock++; } } の2か所あるのでそのどちらなのか特定します.とりあえず逆アセンブルして みます. (kgdb) disassemble 0xf012eed3 0xf012ef40 Dump of assembler code from 0xf012eed3 to 0xf012ef1c: 0xf012eed3 <cluster_read+795>: addl $0x4,%esp 0xf012eed6 <cluster_read+798>: incl -266339692 0xf012eedc <cluster_read+804>: movl 52(%ebx),%eax 0xf012eedf <cluster_read+807>: cltd 0xf012eee0 <cluster_read+808>: idivl 24(%ebp),%eax 0xf012eee3 <cluster_read+811>: addl %eax,-266339688 0xf012eee9 <cluster_read+817>: movl -266415424,%edx 0xf012eeef <cluster_read+823>: movl 24(%edx),%edx 0xf012eef2 <cluster_read+826>: incl 44(%edx) 0xf012eef5 <cluster_read+829>: cmpl $0x0,-40(%ebp) 0xf012eef9 <cluster_read+833>: je 0xf012ef0c 0xf012eefb <cluster_read+835>: movl -40(%ebp),%edx 0xf012eefe <cluster_read+838>: testb $0x4,36(%edx) 0xf012ef02 <cluster_read+842>: jne 0xf012ef0c 0xf012ef04 <cluster_read+844>: pushl %edx 0xf012ef05 <cluster_read+845>: call 0xf012d830 0xf012ef0a <cluster_read+850>: jmp 0xf012ef0f 0xf012ef0c <cluster_read+852>: movl -48(%ebp),%eax 0xf012ef0f <cluster_read+855>: leal -76(%ebp),%esp 0xf012ef12 <cluster_read+858>: popl %ebx 0xf012ef13 <cluster_read+859>: popl %esi 0xf012ef14 <cluster_read+860>: popl %edi 0xf012ef15 <cluster_read+861>: leave 0xf012ef16 <cluster_read+862>: ret 0xf012ef17 <cluster_read+863>: addb %dl,-119(%ebp) 0xf012ef1a <vfs_cluster:cluster_rbuild+2>: inl $0x83,%eax 0xf012ef1c <vfs_cluster:cluster_rbuild+4>: inb (%dx),%al End of assembler dump. strategyルーチンを呼び出すところから,cluster_rbuild()の先頭ま で逆アセンブルしてみましたが,
ところから,2番目のVOP_STRATEGYであることがわかります.ソースコードを 遡ると,buf構造体のrbpがどこで代入されたのか しらべてみます.cluster_read()関数を見ると, if (num_ra) { rbp = cluster_rbuild(vp, filesize, rablkno, blkno, size, num_ra + 1); } else { rbp = getblk(vp, rablkno, size, 0, 0); rbp->b_flags |= B_READ | B_ASYNC; rbp->b_blkno = blkno; } という部分があります.もし後者ならB_READとB_ASYNCがセットされるので cluster_rbuild()関数の戻り値であることがわかります.つぎに, cluster_rbuild()関数を見てみます.すると, tbp = getblk(vp, lbn, size, 0, 0); if (tbp->b_flags & (B_CACHE|B_MALLOC)) return tbp; tbp->b_blkno = blkno; tbp->b_flags |= B_ASYNC | B_READ; if( ((tbp->b_flags & B_VMIO) == 0) || (run <= 1) ) return tbp; という部分があります.B_MALLOCがセットされていてB_READもB_ASYNCもセッ トされていないことから,最初のif文によりbuf構造体を 返したことがわかります.では,次にgetblk()関数を見ていきます. 我々は,buf構造体のb_flagsがB_MALLOC | B_BUSY であることを知っているので,そのような条件が生じる場所を探します.すると, allocbuf(bp, size); #ifdef PC98 /* * 1024byte/sector support */ #define B_XXX2 0x8000000 if (vp->v_flag & 0x10000) bp->b_flags |= B_XXX2; #endif return (bp); } のallocbuf()関数の戻り値であるように見えてきます.そこで, allocbuf()関数もおなじような観点で見ていくと, if ( (bufmallocspace < maxbufmallocspace) && (bp->b_bufsize == 0) && (mbsize <= PAGE_SIZE/2)) { bp->b_data = malloc(mbsize, M_TEMP, M_WAITOK); bp->b_bufsize = mbsize; bp->b_bcount = size; bp->b_flags |= B_MALLOC; bufspace += mbsize; bufmallocspace += mbsize; return 1; } であることがわかります. わかった!cluster_rbuild()関数が返したbuf構造体は malloc()を用いて得られたバッファであります.これにB_MALLOC がセットされているためにcluster_rbuild()は何もせずにリターン しています.cluster_rbuild()関数は読み込みのためのバッファを 返さなければいけないのにもかかわらずなにも考えていません. cluster_read()関数はcluster_rbuild()がまともな値を返すこ とを期待しているので,そのままVOP_STRATEGY()を呼び出します.その先がた またまCD-ROMという読み込み専用のファイルシステムであったためにパニック を起こしたわけです. では,これが書き込み可能であった場合はどうなるでしょうか?カーネル下位 層は,b_flagsのB_READがセットされているかどうかで,上位層からの 要求が書き込みなのか読み込みなのか区別します.したがって,書き込み要求 が来たものとして処理することになり,誤ったデータを書き込むことになりま す. バグフィックスこの不具合に対し,vfs_cluster.cのリビジョン1.36には 以下の修正が施されています. tbp = getblk(vp, lbn, size, 0, 0); if (tbp->b_flags & B_CACHE) return tbp; tbp->b_blkno = blkno; tbp->b_flags |= B_ASYNC | B_READ; if( (tbp->b_flags & B_MALLOC) || ((tbp->b_flags & B_VMIO) == 0) || (run <= 1) ) return tbp; |