IIS 7.0 のワーカープロセス起動直後に問題が発生する場合の調査方法

グローバル HTTP モジュールや ISAPI フィルタなど、 ワーカープロセスの起動直後に動作するようなプログラムを開発する場合、 早い時期にデバッガをアタッチできなければ調査が非常に困難になります。

この資料では Windows の Image File Execution Options を利用して、 IIS 7.0 のワーカープロセスにデバッガをアタッチして、かつ、そのデバッガに接続する方法について説明します。

準備 ～ Debugging Windows for Windows のインストールとシンボルパスの設定

マイクロソフトのサイトからダウンロード可能な Debugging Tools for Windows をインストールし、シンボルパスを設定してください。

Image File Execution Options を利用したデバッガのアタッチ

以下のように Image File Execution Options の Debugger を設定すると、 IIS 7.0 のワーカープロセス (w3wp.exe) 起動時にデバッガがアタッチします。

図1. レジストリの設定

HKEY_LOCAL_MACHINE
 \SOFTWARE
  \Microsoft
   \Windows NT
    \CurrentVersion
     \Image File Execution Options
      \w3wp.exe

名前: Debugger
型: REG_SZ
値: C:\Debuggers\cdb -server npipe:pipe-iiswp

上記設定を行い、IIS に HTTP リクエストを送信すると w3wp.exe にデバッガ cdb.exe が アタッチした状態で起動します。

HTTP リクエストを送信してから、tlist で起動コマンドを確認すると、 以下のようになります。cdb が w3wp.exe をアタッチして起動していることが確認できます。

C:\Debuggers> tlist -v | findstr w3wp
     Command Line: c:\Debuggers\cdb -server npipe:pipe=iiswp 
c:\windows\system32\inetsrv\w3wp.exe 
-a \\.\pipe\iisipm75b69ad5-808c-4b8e-983e-92ed9f4a0a60 -v "v2.0" 
-h "C:\inetpub\temp\apppools\DefaultAppPool.config" -w "" -m 0 -t 20 
-ap "DefaultAppPool"
 0 32 7692 w3wp.exe
     Command Line: c:\windows\system32\inetsrv\w3wp.exe 
-a \\.\pipe\iisipm75b69ad5-808c-4b8e-983e-92ed9f4a0a60 -v "v2.0" 
-h "C:\inetpub\temp\apppools\DefaultAppPool.config" -w "" -m 0 -t 20 
-ap "DefaultAppPool"

C:\Debuggers>

尚、レジストリを直接編集するのが面倒（or 危険で嫌だ）という方は、 デバッグツールの gflags を用いて設定しても構いません。

図2. gflags による Debugger の設定

リモートデバッグの開始

デバッガから iiswp という名前のパイプに接続して、リモートデバッグする場合は、 -remote オプションを指定します。

C:\Debuggers> cdb -remote npipe:server=localhost,pipe=iiswp

以下のように w3wp.exe に接続できたことが確認できます。

...
ModLoad: 75590000 755ae000   C:\Windows\system32\USERENV.dll
ModLoad: 75570000 75584000   C:\Windows\system32\Secur32.dll
ModLoad: 76fb0000 76fdd000   C:\Windows\system32\WS2_32.dll
ModLoad: 77030000 77036000   C:\Windows\system32\NSI.dll
(1c8c.1184): Break instruction exception - code 80000003 (first chance)
eax=00000000 ebx=00000000 ecx=0022f384 edx=76eb9a94 esi=fffffffe edi=76ebb6f8
eip=76ea7dfe esp=0022f39c ebp=0022f3cc iopl=0         nv up ei pl zr na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246
ntdll!DbgBreakPoint:
76ea7dfe cc              int     3
KEISUKEO-HP\Keisuke (npipe iiswp) connected at Wed Nov 12 07:33:34 2008
0:000>

走らせるには g コマンドです。デバッガを起動した直後に走らせてしまってよいなら、 デバッガのオプションとして -g を渡すこともできます。

以下の調査例は、W3WP.EXE が起動直後にクラッシュする状況で実施したものです。

0:000> g
ModLoad: 76f90000 76fae000   C:\Windows\system32\IMM32.DLL
ModLoad: 756e0000 757a8000   C:\Windows\system32\MSCTF.dll
(省略)
***
***
(10e0.1258): Access violation
 - code c0000005 (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=33eddca3 ebx=00000000 ecx=012dfc68 edx=012dfe48 esi=33eddca5 edi=01189070
eip=76ec9bc0 esp=012dfc50 ebp=012dfc54 iopl=0         nv up ei pl nz na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010206
ntdll!RtlInitUnicodeStringEx+0x1f:
76ec9bc0 668b10          mov     dx,word ptr [eax]        ds:0023:33eddca3=????
0:006> kbn 100
 # ChildEBP RetAddr  Args to Child              
00 012dfc54 7589e830 012dfc68 33eddca3 00002000 ntdll!RtlInitUnicodeStringEx+0x1f
01 012dfc78 00e01516 33eddca3 018c0a70 00000000 kernel32!OutputDebugStringW+0x16
02 012dfc98 6b523dc4 012dfce0 00d4fdd0 012dfccc 
ghttpmod!MyGlobalModule::OnGlobalTraceEvent+0x86
03 012dfca8 6b523cbf 00002000 012dfce0 01192aac 
iiscore!VIRTUAL_MODULE::GlobalDoWork+0x13a
04 012dfccc 6b52a532 00002000 012dfce0 6b528dc1 
iiscore!W3_SERVER::GlobalNotify+0x98
(省略)
10 012dff14 76e9e4b6 00d34aa8 64ef8f68 00000000 kernel32!BaseThreadInitThunk+0xe
11 012dff54 76e9e489 71d81e4c 00d34aa8 00000000 ntdll!__RtlUserThreadStart+0x23
12 012dff6c 00000000 71d81e4c 00d34aa8 00000000 ntdll!_RtlUserThreadStart+0x1b
0:006> du 33eddca3
33eddca3  "????????????????????????????????"
33eddce3  "????????????????????????????????"
(省略)
33eddf23  "????????????????????????????????"
33eddf63  "????????????????????????????????"
0:006> !vprot 33eddca3
BaseAddress:       33edd000
AllocationBase:    00000000
RegionSize:        35cd3000
State:             00010000  MEM_FREE
Protect:           00000001  PAGE_NOACCESS

上記ログから私の今作りかけのモジュール ghttpmod.dll から、 ghttpmod!MyGlobalModule::OnGlobalTraceEvent でトレースを出力する際に 解放済みのメモリにアクセスしてしまったことがわかります。

ここではクラッシュした状況をチラ見しただけですが、こんな簡単な診断でもクラッシュにいたるメソッド名までは特定できています。 「なんか変だな。動かないぞ！ここかな？ここかな？ちょっと設定を変えてみよう」 などと、闇雲に右往左往するのとは次元の違う方法だ、ということはお分かりいただけましたでしょうか？

デバッグ手順のまとめ

以上をまとめると、W3WP.EXE の起動直後にデバッグする場合は次のようになります。

1. デバッグツールをインストールする
2. シンボルパスを設定する
3. W3WP.EXE 起動後にデバッガをアタッチするよう Image File Execution Options を設定しする。
   この時、後にリモートデバッグクライアントが接続できるよう、パイプをあけておく
4. IIS に HTTP リクエストを送信する (W3WP.EXE が起動する)
5. 上記であけたパイプに接続し、リモートデバッグを開始する

補足:  このようなデバッグ手法に興味のある方は、 .NET&Windows プログラマのためのデバッグテクニック徹底解説 や Advanced Windows Debugging を読むと良いでしょう。最初の本の方が入門者向けです。