デバッグ版wininet.dllの利用方法とログの見方

前回のポストで、IEの問題の切り分けの方法として、デバッグ版wininet.dllが使えるケースがあると書きました。
wininet.dllはIE内でHTMLやCSSなんかのデータを取得する際に利用しているモジュールです。


現在は、「F12開発者ツール」「DynaTrace」でネットワークも簡易に確認出来るようになっていますし、重要性は薄れてきていますが、
個人的に実際に役に立ったケースとしては、

  • showModalDialog時
  • 右クリックメニューからのファイル保存の動作確認時
  • 通信されないときの、障害切り分け。

がありました。


問題は、ログの出力内容の理解に時間がかかると思っています（実際にかかりました）。
そこで、私の方で分かったを書いておきます。

デバッグ版wininet.dllの利用について

デバッグ版wininet.dllは、公式にはIE7までしか公開されていないようです。
無理やりIE7用wininet.dllをIE9でも使用が出来るということを確認していますが、不安定な動作となりました(それでもそこそこ使えたはず）。
デバッグ版wininet.dllでなくても「WinInet ETW(Event Tracing on Windows)」の機能を利用すれば、どこまで処理が進んだかの情報を得ることは出来ます。


有料のサブスクリプションに加入すれば、チェックビルド版OSが利用出来るためwininet.dllについてもデバッグ版(DBGフラグ尽き)になっています。
それを利用すればIE8,IE9以降でも同じ機能が使えます。
IE8、IE9でデバッグ版wininet.dllを利用したい場合は、基本的にはこの方法になってしまう認識です。
ただし、チェックビルド版OSは、最近リリースされたWin7SP1のものでもASSERTで落ちまくるので、通常ブラウジングには向いていないようです。


デバッグ版wininet.dllは、IE9がリリースされた現在でも調査に有効なケースがある認識です。
通信周りの処理はそんなに変わっていないためです。
（Exportされた関数を見ても１０個ぐらいしか増えていなかった記憶があります）


wininetのIEの中の位置づけは以下で確認が出来ます。
Internet Explorer のアーキテクチャ


wininetの主な機能は、http://msdn.microsoft.com/en-us/library/aa383630(VS.85).aspxで確認出来ます。
利用方法は、デバッグ バージョンの Wininet.dll を使用するなどに書かれています。

ログ出力形式について

wininetでログを取るモードにすると、次のようなログが大量に出ます。
関数名の引数や戻り値が簡単に確認出来ます。これが利点です。

ログの中で出力される関数仕様はAbout WinINet配下のリファレンスで確認です。


・デバッグ版wininet.dllには、urlmon.dll(URL Moniker)のデバッグ版も付属されていますが、urlmonの方は、どうやらいくつかの設定系の関数しかログ出力されないようです。重要な情報をメインに出力されるようになっているようです。


・ログのうち半分ぐらいは、GetUrlCacheEntryInfoAやFindNextUrlCacheEntryAなどのキャッシュの走査のイテレート処理?で埋まるようで、あまり気にせず読み飛ばしています。

ログ出力オプションについて

※これ以降の内容は、通常用途では蛇足かもしれません。


隠し機能？として、何をログに出力するかのオプションが指定可能です。
フラグのデフォルト値は、出力されるログの頭に出てくるのですが、次のようになっていました。

InternetDebugErrorLevel = Info [0]
InternetDebugControlFlags = 0x00403f4f
InternetDebugCategoryFlags = 0xffffffff
InternetDebugBreakFlags = 0x00000000
InternetDebugIndentIncrement = 2


この値の意味は、PC向けのMSDNサイトには見当たりませんでしたが、
Windows Mobile(Phone)のMSDNサイトには記載されており、その内容と同一の指定出来ることが分かりました。


たとえば、関数の引数の出力は「Parameter List (0x00000008)」なので、デフォルトで出力されるようになっています。
OFFにしたければInternetDebugControlFlags = 0x00403f47を設定すればよいことになります。
デフォルトでほとんどの情報がログに出力されるので、あまり大した話ではないです。


たとえば、「Flush Output」をONにするため、「set wininetcontrol=0x00403fcf」という指定をして起動すると、
重くなりすぎて、１ページの読み込みに１分近くかかってしまうようになってしまいました。
このフラグはレジストリや環境変数でも設定可能です。
※ちなみに全部ONにしてやろうとControlFlagsを0xffffffffにすると、逆に何も出なくなるので注意です（「No Debug output」フラグがONになるため）。
ええ、実際やりましたよ。


ご参考程度に、私は次のような感じで起動用バッチファイルを作ってログを採取しています。

@echo off
set wininetlog=1
set wininetcontrol=0x00f0ff4f
set wininetcategory=0xffffffff
set urlmonlog=1
"C:\Program Files\Internet Explorer\iexplore.exe"

非同期ID(Async ID）について

urlmonのログ出力とwininetのログ出力フォーマットはよく見比べてみると１箇所だけ違いがあります。
wininetの方のログには「非同期ID」が出力されるようになっています。


私は「非同期ID」とは、wininetは非同期処理で複数スレッドで処理を行うため、担当を分かりやすくするため、「一連の連続した処理を行う単位」にそれぞれ、、<--->という名前をつけたものという理解をしています。


これについては、デバッグ版wininet.dllに付属のヘルプファイル(inetdbg.txt)に説明が書かれており、抜粋すると、

To handle asynchronous requests WinInet creates a worker thread. This thread calls callback functions and also performs scheduling of submitted requests. The log file reflects the status of the asynchronous requests via its ID as follows:
1. - call from the application thread.
2. - async worker thread calling back into the app; any WinInet API
requests during this time treated as though from the app context
3. <-----> - internal call performed by WinInet for the purpose of
scheduling asynchronous requests.
4. - where XXXXX is a decemal number, reflecting the asynchronous ID.


IEでログを採取した場合、ログの中に確認出来るのは、、、<--->の３つだけでした。
４番目のという形式は確認出来ていません。


非同期IDの意味はログを採取すれば大体分かると思いますが、
SDKに付与されてくるサンプルや次のMSDNサイトをコンパイル＆実行してみて確認するのも理解が深まるものと思っています。
Asynchronous Example Application


実際は同じスレッドが担当することもありますが、こちらではおよそ７割方は専用スレッド(つまり<--->)で送受信処理がされました。
非同期なので、当然でしょうけども、ログが入り乱れて出る場合もありました(時によって変わります）。
IO（通信)処理の最適化のために、このような作りをしている認識です。


このAsync ID (InternetDebugControlFlagsでいう0x00400000)はデフォルトでログに出力されるようになっています。


同期にしろ非同期にしろ、wininetでは１ホスト当たりの同時接続数の限界(RFC2616)を超えないような制御がされおり、
これはFlash/SilverLightなどのプラグインや、.netのAPIでも同じ制限がかかるようです。
その辺の制御もこの「非同期ID」を見ることで、wininet内がどのような処理を行っているか想像がつきやすくなるのではないでしょうか。


非同期なのでキャンセル時は神経質な動作をしているようです。
※プログラミング.NET Framework 第３版 p803、p812も参照


タイマについて

ログ出力に慣れるために、例としてIEの受信タイマについて触れておきます。


IEの受信タイマ値は、60分（http://support.microsoft.com/kb/181050/ja）ですが


IEは、wininetがデフォルトで持っているタイマ値30秒を上書して使っているようで、
ログの中を一部切り出すと次のように出力されます。

01:51:35.525 00000448: 001 InternetSetOptionW(0x0, INTERNET_OPTION_RECEIVE_TIMEOUT (6), 0x455d054 [0x36ee80], 4)
01:51:35.525 00000448: 002 InternetSetOptionA(0x0, INTERNET_OPTION_RECEIVE_TIMEOUT (6), 0x455d054 [0x36ee80], 4)
01:51:35.525 00000448: 002 InternetSetOptionA() returning TRUE
01:51:35.525 00000448: 001 InternetSetOptionW() returning TRUE


InternetSetOption関数は、通信の設定周りを行うときに呼び出す関数のようです。
その第３引数、0x36ee80の部分がその値で、10進に直すと「3600000」となりちょうど60分になります。
これは、上記サイトの内容と一致しています。
タイマ値を保持しているレジストリを変更すれば、その変更した値が適用されるんじゃないかと思っています。


あと、上記ログのようにwininetは、W関数からA関数が呼ばれるようになっているようなので注意です。


個人的に、IEの受信タイマ60分って本当に60分かなと思い、実験してみた所、
59分50秒sleepするCGIと、
60分10秒sleepするCGIに投げてみて、
本当に60分になっていることを確認しています。
ただ、１ホスト辺りの同時接続数の上限を超えた場合の待ち時間は５分のようなので、それを超えない範囲になります。