SCIENCE PARK

  1. ホーム
  2. デバイスドライバー開発
  3. デバドラ講座
  4. デバイスドライバ講座(中級)

デバドラ講座

【デバドラ講座3(中級):NotMyFaultを使ってみよう】

前回の講座でカーネルデバッグを実施できる準備が整いました。さっそくカーネルの動作を解析してみましょう。
今回はNotMyFaultという意図的にBSOD(ブルースクリーン)を発生させるツールを使用し、その動作を解析してみます。

NotMyFaultはMicrosoftが無償提供しているツールで、下記のサイトでダウンロードが可能です。

https://docs.microsoft.com/en-us/sysinternals/downloads/notmyfault

NotMyFaultでは「クラッシュの原因」を選択してブルースクリーンを起こせます。(図1、2)

(図1:NotMyFaultウインド)

(図2:NotMyFaultで引き起こしたブルースクリーン)

1. High IRQL Fault(Kernel-mode)を選んで仮想マシンをクラッシュさせてみる。

NotMyFaultでHigh IRQL Fault(Kernel-mode)を選択し「Crash」ボタンをを押下すると、デバッグ対象のOSにブルースクリーンが発生します。
この時デバッガに接続されているとWindbgのコマンドウィンドに出力が発生されるはずです。まずその出力内容を確認していきましょう。

1-1. BugCheckReferenceの参照


*** Fatal System Error: 0x000000d1
                       
(0xA481D800,0x00000002,0x00000000,0xA1E1E0F5)

Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows 8.1 9600 x86 compatible target at (Mon Dec  3 15:34:30.108 2018 (UTC + 9:00)), ptr64 FALSE
Loading Kernel Symbols
........................................
				

まず「0x000000d1」に着目してみます。

これはBugCheckCodeといってMicrosoftでReferenceが公開されています。

https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/bug-check-code-reference2

今回のCodeである「0xd1」を参照してみます。

https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/bug-check-0xd1--driver-irql-not-less-or-equal

The DRIVER_IRQL_NOT_LESS_OR_EQUAL bug check has a value of 0x000000D1. This indicates that a 
kernel-mode driver attempted to access pageable memory at a process IRQL that was too high.

Important This topic is for programmers. If you are a customer who has received a blue screen error code 
while using your computer, see Troubleshoot blue screen errors.

  

カーネルモードドライバーが高すぎるIRQLでページメモリーにアクセスししてしまった、ということが始めに書かれてあります。
NotMyFaultで選択したHigh IRQL Faultと一致しています。
これは次の「!analyze -v」コマンドを実行したときにもコマンド画面に書かれてありますが、Referenceは公式な重要資料なので必ず目を通しておきます。

1-2. !analyze -vで自動解析してみる。

しばらくするとBugcheck Analysisが始まりました。ここにもBugCheckCodeが書かれてあります(BugCheck D1)

*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck D1, {a481d800, 2, 0, a1e1e0f5}

*** ERROR: Module load completed but symbols could not be loaded for myfault.sys
*** ERROR: Module load completed but symbols could not be loaded for notmyfault.exe
Probably caused by : myfault.sys ( myfault+10f5 )

Followup:     MachineOwner
---------

 

上記のコマンド画面で「!analyze -v」をクリックまたはコマンド入力してみると下記のように表示されます。

*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high.  This is usually
caused by drivers using improper addresses.
If kernel debugger is available get stack backtrace.
Arguments:

Arg1: a481d800, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4: a1e1e0f5, address which referenced memory

Debugging Details:
------------------
…
READ_ADDRESS:  a481d800 Paged pool

CURRENT_IRQL:  2
…

出力結果から、IRQLが高い状態で、Paged メモリにアクセスしたことにより、BSODとなっていることが分かります。「!analyze -v」の出力にも読み込まれたアドレス「a481d800」がPagedという内容が含まれています。
この現象はDispatchLevelでPaged領域にアクセスしようとしたのでBSODとなっているものと判断できます。(デバドラ講座12参照)

Arg1~Arg4の内容はそれぞれ以下の値を示しています。

・「Arg1: a481d800, memoy referenced」

a481d800が参照されたメモリのアドレスです。

「このメモリa481d800が有効でない、または高すぎるIRQLにあった。これは通常ドライバが不適切なアドレスにアクセスしたため引き起こされた」ということが上記に書かれてあります。

・「Arg2: 00000002, IRQL」

現在のIRQLが2(DISPATCH_LEVEL)であることを示しています。

・「Arg3: 00000000, Value 0 =read operation, 1 = write operation」

Value 0なので、読み込み中であることを示しています。

・「Arg4: a1e1e10f5, address which referenced memory」

 Arg1にアクセスした処理の実行アドレスを示しています。

「!analyze -v」は自動解析コマンドなので他にも様々な解析をしてくれています。その中の一つ、スタックトレースを見てみましょう。

下から上にかけてこれまで行われてきた処理が見られます。中間あたりから見ていくと、

1. カーネルモードでIoCallDriver(次の階層ドライバにIRPを渡す)が呼ばれています。
2. NotMyFaultがクリック起動されています。
3. カーネルモードでクラッシュが起き、トラップが引き起こされました。
4. カーネルモードでBugcheckが開始されています

STACK_TEXT:  
acb87744 8118a59d 00000003 2136068b 00000065 nt!RtlpBreakWithStatusInstruction
acb87798 8118a0b7 801dd340 acb87b98 acb87c38 nt!KiBugCheckDebugBreak+0x1f
acb87b6c 8110cdc6 0000000a a481d800 00000002 nt!KeBugCheck2+0x676
acb87b90 811213c3 0000000a a481d800 00000002 nt!KiBugCheck2+0xc6               
acb87b90 a1e1e0f5 0000000a a481d800 00000002 nt!KiTrap0E+0x1cf                 
WARNING: Stack unwind information not available. Following frames may be wrong.
acb87cb4 a1e1e924 0000010e acb87d40 927d9b93 myfault+0x10f5                     
acb87dc0 a1e1ea4a 87f62948 00000018 00000000 myfault+0x1924
acb87dd8 8109974f 852c43d8 87f62930 00000100 myfault+0x1a4a          
acb87df4 812a765e 87f629c4 87f62930 00000000 nt!IofCallDriver+0x3f             
acb87e50 812ab518 849123b8 00000000 00000201 nt!IopSynchronousServiceTail+0x16e
acb87ef8 812aa516 00000000 00000000 00000204 nt!IopXxxControlFile+0x3e8
acb87f24 8111de17 00000148 00000000 00000000 nt!NtDeviceIoControlFile+0x2a

「 myfault+0x10f5」で問題の処理(不正メモリアクセス)が発生しています。今回はmyfaultのシンボルがないですが、自分で開発したドライバの場合シンボルをあてることで関数名まで特定できます。該当関数のどの処理で今回の問題が発生したかを特定し、該当メモリの確保方法を変更することで修正を行います。

BSOD発生時のダンプを確認する際はまずはコマンド「!analyze -v」により解析を始めることが有効です。

2. Stack overflowを選択して仮想マシンをクラッシュさせてみる。

2-1. BugCheckReferenceの参照

*** Fatal System Error: 0x0000007f
                       (0x00000008,0x801D6780,0x00000000,0x00000000)

Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

WARNING: Process directory table base 7DE0D5A0 doesn't match CR3 001A5000
WARNING: Process directory table base 7DE0D5A0 doesn't match CR3 001A5000
Connected to Windows 8.1 9600 x86 compatible target at (Tue Dec  4 10:30:58.749 2018 (UTC + 9:00)), ptr64 FALSE
Loading Kernel Symbols
.........................................

Press ctrl-c (cdb, kd, ntsd) or ctrl-break (windbg) to abort symbol loads that take too long.
Run !sym noisy before .reload to track down problems loading symbols.

BugCheckCode「0x0000007f」を参照します。

https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/bug-check-0x7f--unexpected-kernel-mode-trap

 

2-2. !analyze -vで自動解析してみる

1: kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

UNEXPECTED_KERNEL_MODE_TRAP (7f)
This means a trap occurred in kernel mode, and it's a trap of a kind
that the kernel isn't allowed to have/catch (bound trap) or that
is always instant death (double fault).  The first number in the
bugcheck params is the number of the trap (8 = double fault, etc)
Consult an Intel x86 family manual to learn more about what these
traps are. Here is a *portion* of those codes:
If kv shows a taskGate
        use .tss on the part before the colon, then kv.
Else if kv shows a trapframe
        use .trap on that value
Else
        .trap on the appropriate frame will show where the trap was taken
        (on x86, this will be the ebp that goes with the procedure KiTrap)
Endif
kb will then show the corrected stack.
Arguments:

Arg1: 00000008, EXCEPTION_DOUBLE_FAULT
Arg2: 801d6780
Arg3: 00000000
Arg4: 00000000
 

・「Arg1: 00000008, EXCEPTION_DOUBLE_FAULT」

00000008とは今回のBugCheckCode「0x7f」における第1パラメータのことでreferenceにも載っています。

コマンド画面のさらに下を見ていくと、STACK_OVERFLOWと書かれている部分があり、Stack Limitのアドレスb936b000が示されています。
そもそもスタックとはすべてのスレッド毎に確保されたメモリ領域のことです。
メモリ上にスタックのベース(下限)とリミット(上限)が決められているため、もしカーネルモードでそれを超えてスタックを使ってしまうとBSODになります。スタック領域はプロセッサアーキテクチャに依存して x86 では 12 KB、x64 (amd64/EM64T 含) では 24KB、Itanium では 32 KB となっています。

…
STACK_OVERFLOW: Stack Limit: b936b000. Use (kf) and (!stackusage)to investigate stack usage.

STACKUSAGE_FUNCTION: The function at address 0xffffffffa34c61c0 was blamed for the stack overflow. It is using 11720 bytes of stack. …

2-3. 「kfコマンド」と「!stackusageコマンド」を使ってみる

kfコマンドはフレーム毎によって使われたスタックメモリーサイズを表示し、!stackusageコマンドはモジュール毎に使われたメモリサイズと回数を表示してくれるコマンドです。

1: kd> kf
 #   Memory  ChildEBP RetAddr  
00           801db914 8179c59d nt!RtlpBreakWithStatusInstruction
01        54 801db968 8179c0b7 nt!KiBugCheckDebugBreak+0x1f
02       3d0 801dbd38 8171edc6 nt!KeBugCheck2+0x676
03        24 801dbd5c 817320f4 nt!KiBugCheck2+0xc6
04         0 801dbd5c a34c61c0 nt!KiTrap08+0x7a
WARNING: Stack unwind information not available. Following frames may be wrong.
05  39192064 b936ddc0 a34c6a4a myfault+0x11c0
06        18 b936ddd8 816ab74f myfault+0x1a4a
07        1c b936ddf4 818b965e nt!IofCallDriver+0x3f
08        5c b936de50 818bd518 nt!IopSynchronousServiceTail+0x16e
09        a8 b936def8 818bc516 nt!IopXxxControlFile+0x3e8
0a        2c b936df24 8172fe17 nt!NtDeviceIoControlFile+0x2a

(kfコマンド)

1: kd> !stackusage
Stack Usage By Function
=================================================================================

      Size     Count  Module
0x00002DC8         1  myfault
0x000003D0         1  nt!KeBugCheck2
0x00000108         1  notmyfault
0x00000100         2  USER32!UserCallWinProcCheckWow
0x000000A8         1  notmyfault
0x000000A8         1  nt!IopXxxControlFile
0x00000090         1  COMCTL32!Button_WndProc
0x00000084         3  USER32!_InternalCallWinProc
0x00000080         1  USER32!UserCallDlgProcCheckWow
0x00000060         1  KERNELBASE!DeviceIoControl
0x00000060         1  USER32!DispatchMessageWorker
0x0000005C         1  USER32!DispatchClientMessage

(!stackusageコマンド)

それぞれのコマンドで表示されたスタックはどちらもmyfaultの部分で明らかに大きすぎるメモリ(kfコマンド:39192049、!stackusageコマンド:0x00002DC8)が使われていることがわかります。

このようにスタックオーバーフローの場合は本質的にクラッシュしたタイミングのドライバが大きなスタックを消費していない可能性もあるため、memory使用量やStackを「kf」や「!stackusage」のようなコマンドで確認することが有効です。今回も「myfault+0x11c0」の処理周辺に問題がある可能性が高いので、該当処理周辺でスタックを多く使う処理を行なっていないか確認し、問題点の特定をします。

次回デバドラ講座4でもNotMyFaultを使ったデバッグを行っていきます。

参考URL

・スタックオーバーフロー

https://blogs.msdn.microsoft.com/jpwdkblog/2011/07/15/443/

page up