ダンプファイルに保存された ETW トレースログを表示する

  • Article

ご自身が開発されているドライバについて、BSOD 発生時点のダンプファイルの情報からでは根本原因がわからず、BSOD 直前から発生までのドライバ内部の状態を知りたいと思ったことはありますか？

 

皆さん、こんにちは。Windows Driver Kit サポートチームの津田です。今回は、そんな皆様に、ETW トレースログを BSOD 発生時点のダンプファイルから参照する方法をご案内します。ETW についてご存じない方は、まずは、以前の「Event Tracing for Windows (ETW)」<https://blogs.msdn.microsoft.com/jpwdkblog/2011/12/27/event-tracing-for-windows-etw/> のエントリをご参照ください。

 

BSOD が発生するまでのトレースログがダンプファイルで参照できますと、以下の 4 点の事前準備は必要ですが、BSOD 発生時のメモリやレジスタの情報から逆アセンブリを追いかけるだけでは遡れなかった情報が取得できます。

 

  (a) BSOD 発生時のダンプファイルで、根本原因特定のために知りたい変数や構造体を特定する。

  (b) それがわかるよう、ETW トレースログをご自身のドライバのソースコードに埋め込む。

  (c) そのドライバを、現象が再現する環境にインストールする。

  (d) logman.exe でトレースログ採取を開始した後、現象を再現する。

 

これにより、根本原因が判明する可能性が高まります。しかも、ライブデバッグのように WinDbg をカーネルデバッグ接続してタイミングが変わったり、ソースコードのどこが原因なのか必ずしも特定できていない状況でステップ実行をするというような時間がかかったりするというデメリットを回避できます。

 

本ブログ エントリでは、以下の前提で進めます。

 

  - (a),(b) は省略します。

  - (c) として上述のブログ エントリで使用した tracedrv ドライバ サンプルを使用します。

  - (d) を実施して、NotMyFault というツールで強制的に BSOD を発生させ、ダンプファイルを採取します。

  - そのダンプファイルを WinDbg でオープンし、!wmitrace デバッガエクステンションを使用して、BSOD 発生直前までの ETW トレースログを表示します。

 

具体的には、以下の手順で進めます。

 

  1. tracedrv サンプルの入手

  2. サンプルのビルド

  3. テスト環境に必要なファイルをコピー

  4. 完全メモリダンプの設定

  5. logman.exe でトレースログ採取を開始

  6. tracectl.exe を実行してトレースメッセージを生成

  7. NotMyFault を使用して BSOD を発生

  8. ダンプファイルを WinDbg でオープン

  9. !wmitrace を使用して ETW トレースログを表示

 

今回は、例として Windows 10 (1607) x86 で行います。

 

1. tracedrv サンプルの入手

 

Tracedrv サンプルは、以下のサイトの右上にある [Clone or download] から [Download ZIP] で Windows-driver-samples-master.zipをダウンロードすると、Windows-driver-samples-master\general\tracing\tracedriver のフォルダにあります。

 

  <https://github.com/Microsoft/Windows-driver-samples>

 

 

2. サンプルのビルド

 

このフォルダの tracedrv.sln を、Visual Studio 2015 で開きます。

 

[ ソリューション 'tracedrv'] を右クリックして [構成マネージャー] をクリックします。

 

clip_image002

 

[ アクティブ ソリューション構成] を [Debug] 、 [アクティブ ソリューションプラットフォーム] を [Win32] とします。

 

clip_image004

 

続いて、 [ソリューション エクスプローラー] 内で [Tracectl] のフォルダを展開し、 [Tracectl] のプロジェクトを右クリックして [プロパティ] をクリックします。

 

clip_image006

 

[tracectl プロパティページ] の左側のペインで [構成プロパティ] の [C/C++] の [コード生成] を選択し、右側のペインで [ランタイム ライブラリ] を [マルチスレッド デバッグ (/MTd)] に変更し [OK] をクリックします。テスト対象の環境にランタイムライブラリ DLL を入れていない場合のために、静的リンクのライブラリでビルドしておくための手順です。

 

clip_image008

 

[ ソリューション 'tracedrv'] を右クリックして [ソリューションのリビルド] をクリックします。\tracedriver\tracectl\Debug フォルダに tracectl.exe、\tracedriver\tracedrv\Debug フォルダに tracedrv.sys と tracedrv.pdb が確認できます。

 

tracedrv.pdb は後述の手順 9 でメモリダンプに含まれる ETW トレースログを人間が読めるメッセージ形式にデコードするために必要となります。

 

 

3. テスト環境に必要なファイルをコピー

 

上述の tracectl.exe と tracedrv.sys を、テスト環境の Windows 10 (1607) x86 の同一フォルダ (例： C:\tracedrv\) にコピーします。

 

また、併せて \tracedriver\tracedrv\ フォルダにある tracedrv.ctl ファイルもコピーします。これは、「d58c126f-b309-11d1-969e-0000f875a5bc CtlGuid」という内容を含むテキストファイルであり、後程の手順 5. で logman.exe によるトレースログ採取を開始する際に使います。

 

続いて、後程の手順 7. で、 NotMyFault ツールを使って BSOD を発生させるので、以下の URL から NotMyFault.zip をテスト環境にダウンロードします。

 

  <https://live.sysinternals.com/Files/NotMyFault.zip>

 

ダウンロードが完了したら、zip ファイルを展開してください。 今回は Windows 10 x86 環境ですので、展開したフォルダの直下にある notmyfault.exe を使用します。

 

 

4. 完全メモリダンプの設定

 

以下のブログエントリに記載の手順で完全メモリダンプを取得できるよう設定します。

 

  完全メモリダンプ採取の設定方法

  <https://blogs.msdn.microsoft.com/jpwdkblog/2016/06/29/%e5%ae%8c%e5%85%a8%e3%83%a1%e3%83%a2%e3%83%aa%e3%83%80%e3%83%b3%e3%83%97%e6%8e%a1%e5%8f%96%e3%81%ae%e8%a8%ad%e5%ae%9a%e6%96%b9%e6%b3%95/>

 

 

5. logman.exe でトレースログ採取を開始

 

管理者権限のコマンドプロンプトを起動します。tracedrv.ctl をメモ帳で開くと、「d58c126f-b309-11d1-969e-0000f875a5bc」の GUID が確認できます。

これを用いて、保存したフォルダ (例： C:\tracedrv\) で、下記のコマンドを実行します。

 

echo {d58c126f-b309-11d1-969e-0000f875a5bc} 0x1 > TestTrace.ctl

 

logman -ets start TestTrace -pf TestTrace.ctl

 

これらのコマンドについては、「Event Tracing for Windows (ETW)」のブログエントリの「■ logman.exe によるログの採取方法」をご参照ください。

 

 

6. tracectl.exe を実行してトレースメッセージを生成

 

コマンドプロンプト上で tracectl.exe をオプションなしで実行します。

すると、tracedrv.sys がロードされます。コマンドプロンプト上で Q または q 以外の文字を入力するたびに、 tracectl.exe は I/O Control を tracedrv.sys に送り、 tracedrv.sys はトレースメッセージを生成します。

今回は “a”, “b”, “c” と順に入力します。(次の手順で BSOD を発生させるので、Q または q を入力しません。)

 

 

7. NotMyFault を使用して BSOD を発生

 

手順 3 でダウンロードした notmyfault.exe を実行します。

[Crash] タブにある Options のオプションであれば何でもいいのですが、今回は、デフォルトの [High IRQL fault (Kernel-mode)] のまま、右下の [Crash] ボタンを押します。

BSOD が発生し、「～ % complete」の数字が 100 % になったら、完全メモリダンプの採取が完了したため、OS が再起動します。

 

clip_image010

 

 

8. ダンプファイルを WinDbg でオープン

 

OS が起動したら、%SystemRoot%\MEMORY.DMP に完全メモリダンプが保存されていますので、これを WinDbg.exe で開きます。

 

WinDbg.exe の入手方法についてご存じない方は、以下のブログエントリをご参照ください。

 

  デバッガ (WinDbg) をインストールする

  <https://blogs.msdn.microsoft.com/jpwdkblog/2016/03/07/%e3%83%87%e3%83%90%e3%83%83%e3%82%ac-windbg-%e3%82%92%e3%82%a4%e3%83%b3%e3%82%b9%e3%83%88%e3%83%bc%e3%83%ab%e3%81%99%e3%82%8b/>

 

WinDbg.exe を開いたら [File] > [Open Crash Dump] で該当メモリダンプ (MEMORY.DMP) を開きます。

 

[Command] ウィンドウが開き、以下のような内容が表示された後、一番下の「kd>」 の右側の枠にコマンドが入力可能となります。

 

clip_image012

 

 

9. !wmitrace を使用して ETW トレースログを表示

 

ETW トレースログを表示するためには、トレースログをデコードするために、シンボルファイルが必要になります。

そこで、WinDbg.exe の [File] > [Symbol File Path] をクリックし、開いた [Symbol Search Path] というウィンドウの [Symbol Path:] に、手順 2 で生成した tracedrv.pdb があるフォルダを入力します。

そして、下部の [Reload] にチェックを入れて、右側の [OK] をクリックします。

 

[Command] ウィンドウで以下を実行します。

 

!wmitrace.logdump TestTrace

 

TestTrace は手順 5 で logman.exe を実行する際に「logman -ets start TestTrace -pf TestTrace.ctl」と入力した、トレースセッション名です。

 

実行結果は以下の通りです。

 

[0]1038.103C::08/20/2016-15:36:42.169 [tracedrv]IOCTL = 1

[0]1038.103C::08/20/2016-15:36:42.169 [tracedrv]Hello, 1 Hi

[0]1038.103C::08/20/2016-15:36:42.169 [tracedrv]Hello, 2 Hi

[0]1038.103C::08/20/2016-15:36:42.169 [tracedrv]Hello, 3 Hi

[0]1038.103C::08/20/2016-15:36:42.169 [tracedrv]Function Return=0x8000000f(STATUS_DEVICE_POWERED_OFF)

[0]1038.103C::08/20/2016-15:36:45.706 [tracedrv]IOCTL = 2

[0]1038.103C::08/20/2016-15:36:45.706 [tracedrv]Hello, 1 Hi

[0]1038.103C::08/20/2016-15:36:45.706 [tracedrv]Hello, 2 Hi

[0]1038.103C::08/20/2016-15:36:45.706 [tracedrv]Hello, 3 Hi

[0]1038.103C::08/20/2016-15:36:45.706 [tracedrv]Function Return=0x8000000f(STATUS_DEVICE_POWERED_OFF)

[0]1038.103C::08/20/2016-15:36:47.098 [tracedrv]IOCTL = 3

[0]1038.103C::08/20/2016-15:36:47.098 [tracedrv]Hello, 1 Hi

[0]1038.103C::08/20/2016-15:36:47.098 [tracedrv]Hello, 2 Hi

[0]1038.103C::08/20/2016-15:36:47.098 [tracedrv]Hello, 3 Hi

[0]1038.103C::08/20/2016-15:36:47.098 [tracedrv]Function Return=0x8000000f(STATUS_DEVICE_POWERED_OFF)

 

「Event Tracing for Windows (ETW)」のブログエントリの「(8) tracefmt.exe を使い、 tracedrv.etl のトレースメッセージを表示」の結果と同じであることが確認できます。

 

 

以上の方法で、ダンプファイルに ETW トレースログを保存し、それをデバッガで表示することができました。読者の皆様のデバッグに少しでもお役に立てましたら幸いです。

 

 

■参考文献

 

  !wmitrace.logdump

  <https://msdn.microsoft.com/ja-jp/library/windows/hardware/ff566159(v=vs.85).aspx>