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 の起動直後にデバッグする場合は次のようになります。
- デバッグツールをインストールする
- シンボルパスを設定する
- W3WP.EXE 起動後にデバッガをアタッチするよう Image File Execution Options を設定しする。
この時、後にリモートデバッグクライアントが接続できるよう、パイプをあけておく - IIS に HTTP リクエストを送信する (W3WP.EXE が起動する)
- 上記であけたパイプに接続し、リモートデバッグを開始する
補足:
このようなデバッグ手法に興味のある方は、
.NET&Windows プログラマのためのデバッグテクニック徹底解説
