イベントログの出力方法

Article
05/31/2011

皆さん、こんにちは。A寿です。

突然ですが、皆さんは、パスポートなしで他国に入国したことはありますか？・・・このお話にご興味のある方は本文の最後の【閑話休題】までどうぞ。

さて、今回はカーネルドライバでのシステムイベントログの出力方法をご紹介しようと思います。ドライバ内の情報をシステムイベントログに残すことで、お客様先のトラブル発生時に、イベントビューアーでそのドライバ以外のモジュールのログと併せて確認できるため、トラブル発生時の大まかな状況をつかむことができます。トラブルシューティングのための情報記録の手段として、他に DbgPrint や、 Event Tracing for Windows (ETW) という方法があります。これらは、イベントログよりも詳細な情報を記録できるメリットがあります。しかし、その一方で、常時採取するには、イベントログよりもデータ量が大きくなってしまったり、データ量を抑えようとしてサイクリックに上書きすると、肝心のエラー時の情報が上書きで消されてしまう可能性があったりというデメリットもあります。そのため、イベントログで、トラブルが発生した時点までのどこを調査すべきかを判断してから、より詳細な情報を見るために、DbgPrint や ETW を使われるのが良いかと思います。

まず、カーネルドライバでのシステムイベントログの出力方法について、手順の概要は以下の通りです。

IO_ERROR_LOG_PACKET のポインタを宣言します。
IoAllocateErrorLogEntry() を呼び、戻り値を 1. のポインタに代入します。

第一引数にはドライバオブジェクトまたはデバイスオブジェクトのポインタを入れます。

第二引数には IO_ERROR_LOG_PACKET 構造体のサイズ、 DumpData のサイズ×個数、 %n に挿入する文字列のサイズ、の和を入れます。

3. 2. の戻り値が NULL でなければ、 IO_ERROR_LOG_PACKET のメンバ変数に値をセットし、 IoWriteErrorLogEntry() を呼びます。

続いて、 Toaster サンプルの busenum.sys の DriverEntry() に、上記手順の具体的な実装を追加して、 busenum.sys ロード時にシステムイベントログが出力されるまでの流れをお見せしたいと思います。 Toaster サンプルは、バージョン 7600.16385.1 のWDKの場合、 C:\WinDDK\7600.16385.1\src\general\toaster のフォルダにあります。出力するイベントは、「情報」「警告」「エラー」の 3 種類とします。

(1) wdm\bus フォルダに、以下の記述をした .mc ファイルを追加します。

ここでは、 busenlog.mc ファイルというファイル名にします。

MessageIdTypedef=NTSTATUS

SeverityNames=(Success=0x0:STATUS_SEVERITY_SUCCESS

Informational=0x1:STATUS_SEVERITY_INFORMATIONAL

Warning=0x2:STATUS_SEVERITY_WARNING

Error=0x3:STATUS_SEVERITY_ERROR

)

FacilityNames=(System=0x0

RpcRuntime=0x2:FACILITY_RPC_RUNTIME

RpcStubs=0x3:FACILITY_RPC_STUBS

Io=0x4:FACILITY_IO_ERROR_CODE

Busenum=0x5:FACILITY_BUSENUM_ERROR_CODE

)

MessageId=0x0001 Facility=Busenum Severity=Informational SymbolicName=BUSENUM_DRIVERENTRY_INFO

Language=English

Busenum DriverEntry Information.

MessageId=0x0002 Facility=Busenum Severity=Warning SymbolicName=BUSENUM_DRIVERENTRY_WARN

Language=English

Busenum DriverEntry Warning.

MessageId=0x0003 Facility=Busenum Severity=Error SymbolicName=BUSENUM_DRIVERENTRY_ERR

Language=English

Busenum DriverEntry Error.

上記ファイルの見方を簡単に説明しますと、以下のような内容になります。

後程、(12) でイベントビューアーで実際に表示させた時の絵と見比べてみてください。

- MessageId ＝イベントビューアーの「イベント ID」

- Facility ＝イベントビューアーの「ソース」

- Severity ＝イベントビューアーの「レベル」(情報、警告、エラー)

- SymbolicName ＝ソースコード中で使用する、一意なイベントのタグ ( IO_ERROR_LOG_PACKET 構造体の ErrorCode )

- Language ＝イベントログに出力する言語の種類 (English, Japanese, ...)

- "Busenum ..." ＝イベントビューアーのメッセージ本体

.mcファイルのカスタマイズ方法については、下記ドキュメントも参考になりますので、ご参照いただければと思います。

Defining Custom Error Types

https://msdn.microsoft.com/en-us/library/ff543017(VS.85).aspx

また、WDK のサンプルに多数の .mc ファイルがありますので、こちらもご参照いただければと思います。

(2) Windows 7 x86 Checked Build Environmentのコマンドプロンプトを起動します。

具体的には、[スタート]→[すべてのプログラム]→[Windows Driver Kits]→[WDK 7600.16385.1]→[Build Environments]→[Windows 7]→[x86 Checked Build Environment]とクリックします。

(3) (2) のコマンドプロンプトで、cd <wdm\busフォルダ>に移動し、mc busenlog.mc を実行します。

これにより、busenlog.hファイル、busenlog.rcファイル、MSG00001.binファイルを生成します。

C:\develop\blog\eventlog\toaster\wdm\bus>mc busenlog.mc

MC: Compiling busenlog.mc

busenlog.hは、以下のような内容になります。

// Values are 32 bit values laid out as follows:

// 3 3 2 2 2 2 2 2 2 2 2 2 1 1 1 1 1 1 1 1 1 1

// 1 0 9 8 7 6 5 4 3 2 1 0 9 8 7 6 5 4 3 2 1 0 9 8 7 6 5 4 3 2 1 0

// +---+-+-+-----------------------+-------------------------------+

// |Sev|C|R| Facility | Code |

// +---+-+-+-----------------------+-------------------------------+

// where

// Sev - is the severity code

// 00 - Success

// 01 - Informational

// 10 - Warning

// 11 - Error

// C - is the Customer code flag

// R - is a reserved bit

// Facility - is the facility code

// Code - is the facility's status code

// Define the facility codes

#define FACILITY_RPC_STUBS 0x3

#define FACILITY_RPC_RUNTIME 0x2

#define FACILITY_IO_ERROR_CODE 0x4

#define FACILITY_BUSENUM_ERROR_CODE 0x5

// Define the severity codes

#define STATUS_SEVERITY_WARNING 0x2

#define STATUS_SEVERITY_SUCCESS 0x0

#define STATUS_SEVERITY_INFORMATIONAL 0x1

#define STATUS_SEVERITY_ERROR 0x3

// MessageId: BUSENUM_DRIVERENTRY_INFO

// MessageText:

// Busenum DriverEntry Information.

#define BUSENUM_DRIVERENTRY_INFO ((NTSTATUS)0x40050001L)

// MessageId: BUSENUM_DRIVERENTRY_WARN

// MessageText:

// Busenum DriverEntry Warning.

#define BUSENUM_DRIVERENTRY_WARN ((NTSTATUS)0x80050002L)

// MessageId: BUSENUM_DRIVERENTRY_ERR

// MessageText:

// Busenum DriverEntry Error.

#define BUSENUM_DRIVERENTRY_ERR ((NTSTATUS)0xC0050003L)

上記の赤字の通り、busenlog.mc に記述した SymbolicName に対して、一意の値が定義されます。

この値を、後程、ソースコードの中で IO_ERROR_LOG_PACKET 構造体の ErrorCode にセットします。

busenlog.rcファイルは、MSG00001.binファイルを読むようになっています。(7)で使用します。

(4) wdm\busフォルダのbusenum.hのinclude文の最後に以下のコードを追加します。

#include "busenlog.h"

これにより、busenlog.h にある、 SymbolicName とその値を、ソースコード中で使用する準備ができます。

(5) wdm\busフォルダのbusenum.cのDriverEntry()の直前に以下のコードを追加します。

(左端の数字は、説明の便宜上、行番号を付加しています。)

1 VOID

2 Bus_LogError(

3 PVOID IoObject,

4 NTSTATUS FinalStatus,

5 NTSTATUS ErrorCode

6 ) {

7 PIO_ERROR_LOG_PACKET logEntry = NULL;

9 logEntry = IoAllocateErrorLogEntry(IoObject,

10 sizeof(IO_ERROR_LOG_PACKET) + (4 * sizeof(ULONG)));

12 if (logEntry != NULL)

13 {

14 logEntry->FinalStatus = FinalStatus;

15 logEntry->ErrorCode = ErrorCode;

16 logEntry->SequenceNumber = 0;

17 logEntry->MajorFunctionCode = 0;

18 logEntry->IoControlCode = 0;

19 logEntry->RetryCount = 0;

20 logEntry->UniqueErrorValue = 0;

21 logEntry->DumpDataSize = 4 * sizeof(ULONG);

23 logEntry->DumpData[0] = 0;

24 logEntry->DumpData[1] = 1;

25 logEntry->DumpData[2] = 2;

26 logEntry->DumpData[3] = 3;

28 IoWriteErrorLogEntry(logEntry);

29 }

31 }

この Bus_LogError() という関数は、前述の手順概要の処理を一つの関数にまとめたものです。このコードと、前述の手順概要は、以下のような対応関係になっています。

7 行目 :

1. IO_ERROR_LOG_PACKET のポインタを宣言します。

9 ～ 10 行目 :

2. IoAllocateErrorLogEntry() を呼び、戻り値を 1. のポインタに代入します。

第一引数にはドライバオブジェクトまたはデバイスオブジェクトのポインタを入れます。

第二引数には IO_ERROR_LOG_PACKET 構造体のサイズ、 DumpData のサイズ×個数、 %n に挿入する文字列のサイズ、の和を入れます。

12 ～ 28 行目 :

3. 2. の戻り値が NULL でなければ、 IO_ERROR_LOG_PACKET のメンバ変数に値をセットし、 IoWriteErrorLogEntry() を呼びます。

今回は、簡単のために、23 ～ 26 行目の DumpData には 0 ～ 3 までの数字を決め打ちでいれていますが、通常は、 Bus_LogError() の引数を増やし、イベントログに出力したい任意の値を入れられるようにしておきます。手順概要 2. の %n とは、 .mc ファイルのメッセージ本体に、上記 DumpData の値や文字列を入れたい場合に、メッセージ本体に %2 や %3 という変数として記入します。 %1 にはドライバのデバイスオブジェクトの名前が入るので、通常、自分で用意したメッセージ本体には、%2 以降の数字を使用します。

(6) busenum.cのDriverEntry()の最後(returnの直前)に、以下を追加します。

Bus_LogError(DriverObject, STATUS_SUCCESS, BUSENUM_DRIVERENTRY_INFO);

Bus_LogError(DriverObject, STATUS_SUCCESS, BUSENUM_DRIVERENTRY_WARN);

Bus_LogError(DriverObject, STATUS_SUCCESS, BUSENUM_DRIVERENTRY_ERR);

(7) busenum.rcの「#include "common.ver"」の次 (12 行目) くらいに、以下を追加します。

#include "busenlog.rc"

これにより、 busenlog.mc に記述したメッセージの情報が、 busenum.sys に埋め込まれることになります。

(8) (2) のコマンドプロンプトで、wdm\busフォルダに移動し、build -cZコマンドでビルドします。

(9) wdm\inf\i386フォルダのbus.infに、イベントログ用の記述を追加します。

以下の記述を追加することで、 busenum.sys をインストールした環境で、イベントログのメッセージ情報をbusenum.sys から読み出すことができるために必要なパスを指定したことになります。

(a) 59 ～ 60 行目の [ToasterBus_Device.NT.Services] に、以下の通り、イベントログ用にbusenum_Eventlogを追加します。

59 [ToasterBus_Device.NT.Services]

60 AddService = busenum,%SPSVCINST_ASSOCSERVICE%, busenum_Service_Inst, busenum_Eventlog

(b) [busenum_Service_Inst] セクションの次 (70 ～ 71 行目 ) あたりに、以下の記述を追加。

[busenum_Eventlog]

AddReg = busenum_eventlog_addreg

[busenum_eventlog_addreg]

HKR,, EventMessageFile, %REG_EXPAND_SZ%, "%%SystemRoot%%\System32\IoLogMsg.dll;%%SystemRoot%%\System32\drivers\busenum.sys"

HKR,, TypesSupported, %REG_DWORD%, 7

(c) [Strings] セクションの最後に、以下の記述を追加。

REG_EXPAND_SZ = 0x00020000

REG_DWORD = 0x00010001

このレジストリ追加については、下記ドキュメントをご参照ください。

INF AddReg Directive

https://msdn.microsoft.com/en-us/library/ff546320(VS.85).aspx

INF AddService Directive

https://msdn.microsoft.com/en-us/library/ff546326(VS.85).aspx

なお、(7) と (9) の記述をしないと、イベントログを表示しても、メッセージ本体が読み出せないため、メッセージ本体の代わりに、以下のメッセージが出ます。

ソース "busenum" からのイベント ID 1 の説明が見つかりません。このイベントを発生させるコンポーネントがローカルコンピューターにインストールされていないか、インストールが壊れています。ローカルコンピューターにコンポーネントをインストールするか、コンポーネントを修復してください。

(10) ここまでで作成したbusenum.sysとbus.infに加え、WDKの\tools\devcon\i386フォルダのdevcon.exeをテスト環境 (Windows 7) の1つのフォルダにコピーします。

devcon.exeは、まさかたさんの記事の通り、ドライバのインストールなど、デバイスマネージャと同様の機能を持つコマンドツールです。

(11) テスト環境で管理者権限でコマンドプロンプトを起動し、(10)のフォルダで以下のコマンドを実行して、busenum.sysをインストールします。

devcon install bus.inf "root\busenum"

今回はドライバにデジタル署名をしていないので、インストール中に警告のポップアップが出ますが、今回はテストのためですので、そのままインストールします。

(12) イベントビューアーのシステムログを確認します。

具体的には、[スタート]→[コンピューター]で右クリック→[管理]をクリック→[コンピューターの管理]が起動→[イベントビューアー]を展開→[Windows ログ]を展開→[システム]をクリック、とすれば、以下の画面のように表示されます。

上記画面では、ソースが busenum の、イベント ID 1 のメッセージ「Busenum DriverEntry Information.」が表示されていることが確認できます。レベルは「情報」となっています。(1) で説明した busenlog.mc の内容と比較していただければ、対応関係がわかりやすいかと思います。

また、次の画面は、イベントビューアーで [詳細] タブを開いた時の表示です。

(5) の DumpData[0] ～ [3] に、0 から 3 の数字を入れましたが、これらが最後の4バイト×4の領域にあることがご確認いただけると思います。

以上が、カーネルドライバでのシステムイベントログの出力方法になります。お役に立てれば幸いです。

それでは、また。

――――――――――――――――

【閑話休題】突然ですが、皆さんは、パスポートなしで他国に入国したことはありますか？

突然ですが、皆さんは、パスポートなしで他国に入国したことはありますか？

・・・いいえ、密入国ではありません。ちゃんとした国内の某有名旅行会社のパックツアーで行きました。その地方では人気ツアーだそうなので、実際に参加されてご存じの方もいらっしゃるかと思いますが、日本から飛行機で、ある国にいったんパスポート等で入国審査を受けて入国してから、地続きのお隣の国に行きました。その「お隣の国」に入るのに、パスポートが必要なく、しかも、遊園地の出口によくある、一方通行の回転扉を抜けるだけでした。今まで、海外へは必ず空港経由で入国審査後に入国していた私にとっては、入国審査なしでの入国、というのは、初めての体験で、すごく驚きました。入国審査を受ける場合、たいていそのあたりでの写真撮影は禁止なのですが、その国には、入るや否や、国名が彫られた岩(？)のようなものがあり、みんなバシャバシャ写真を撮っていました。ただ、逆に、元の国に帰る時には、厳重な入国審査があるので、「お隣の国」にパスポートを持っていく必要があります。

さて、この「お隣の国」に行った時に、商店が多く並ぶ大通りを歩きました。客引きのオジサマたちが、 「トモダチ、トモダチ！」、「社長！」、「見ルダケ、タダ！」 などと、やたら日本語で話しかけてくるのも、驚きました。本物であれば、数十ドルするようなTシャツが、現地風にアレンジされたものを指さして、「One dollar!」と声をかけてくる客引きの方もいました。明らかに怪しく、あまり海外で買い物をする趣味もなく、現地の言葉もよくわからないので、無視して素通りしていました。すると、最初は「トモダチ！」、「社長！」と好意的（？）な言葉で話しかけてきた彼らも、私や同行の友人たちが通り過ぎるや否や、 「チョット来イ！チョット待テ！」、「係長！」、「金持チ？」 と言葉の内容が、ガラッと変わりました。まさか、見ず知らずの人から命令されたり、いったん「社長」と持ち上げられてから「係長」に格下げされたり、資産を確認されたりするとは思いませんでした。これには驚きを通り越して、爆笑しました。面白かったので、大通りをもう一往復しましたが、残念ながら、これ以上の収穫はありませんでした。皆様も、旅先で、見ず知らずの人が、親しげに声をかけてきたら、ご注意ください。

イベントログの出力方法

Additional resources