ARR での 502 エラーのトラブルシューティング
この記事は、アプリケーション要求ルーティング (ARR) の 502 エラーに関連する問題を解決するのに役立ちます。
適用対象: インターネット インフォメーション サービス
HTTP 502 - 概要
IIS アプリケーション要求ルーティング (ARR) のデプロイを使用する場合、"HTTP 502 - Bad Gateway" というエラーが表示されることがあります。 502.3 エラーは、プロキシとして機能しているときに、ARR がアップストリーム サーバーへの要求を完了してクライアントに応答を送信できなかったことを意味します。 この問題は、複数の理由で発生する可能性があります。 たとえば、サーバーに接続できない、サーバーからの応答がない、サーバーが応答に時間がかかりすぎた (タイムアウト) などです。 コントローラーから Web ファームを参照してエラーを再現でき、サーバーで 詳細なエラー が有効になっている場合は、次のエラー メッセージのようなエラーが表示されることがあります。
エラーの根本原因によって、問題を解決するために何を行う必要があるかが決まります。
502.3 タイムアウト エラー
ARR では、前のスクリーンショットのエラー コードを使用して要求をプロキシし、WinHTTP からのリターン コードが含まれているため、エラーの原因を特定します。
ツール err.exeを使用してエラー コードをデコードできます。 この例では、エラー コードは ERROR_WINHTTP_TIMEOUT にマップされます。 この情報は、ARR コントローラーの関連 Web サイトの IIS ログでも確認できます。 502.3 エラーの IIS ログ エントリからの抜粋を次に示します。ほとんどのフィールドは読みやすくするためにトリミングされています。
| sc-status | sc-substatus | sc-win32-status | time-taken |
|---|---|---|---|
| 502 | 3 | 12002 | 29889 |
win32 status 12002 は、エラー ページで報告されたのと同じ ERROR_WINHTTP_TIMEOUT エラーにマップされます。
厳密には何がタイムアウトしたのか?
このタイムアウトは、IIS サーバーで Failed Request Tracing を有効にすることで確認できます。 失敗した要求トレース ログで確認できる最初のポイント。これは、ARR_SERVER_ROUTED イベントで要求が送信された場所です。 2 番目のポイントは X-ARR-LOG-ID で、ターゲット サーバーでの要求の追跡に使用できます。 これは、HTTP 要求のターゲットまたは宛先をトレースするのに役立ちます。
77. ARR_SERVER_ROUTED RoutingReason="LoadBalancing", Server="192.168.0.216", State="Active", TotalRequests="3", FailedRequests="2", CurrentRequests="1", BytesSent="648", BytesReceived="0", ResponseTime="15225" 16:50:21.033
78. GENERAL_SET_REQUEST_HEADER HeaderName="Max-Forwards", HeaderValue="10", Replace="true" 16:50:21.033
79. GENERAL_SET_REQUEST_HEADER HeaderName="X-Forwarded-For", HeaderValue="192.168.0.204:49247", Replace="true" 16:50:21.033
80. GENERAL_SET_REQUEST_HEADER HeaderName="X-ARR-SSL", HeaderValue="", Replace="true" 16:50:21.033
81. GENERAL_SET_REQUEST_HEADER HeaderName="X-ARR-ClientCert", HeaderValue="", Replace="true" 16:50:21.033
82. GENERAL_SET_REQUEST_HEADER HeaderName="X-ARR-LOG-ID", HeaderValue="dbf06c50-adb0-4141-8c04-20bc2f193a61", Replace="true" 16:50:21.033
83. GENERAL_SET_REQUEST_HEADER HeaderName="Connection", HeaderValue="", Replace="true" 16:50:21.033
次の例は、ターゲット サーバーの失敗した要求トレース ログでこれがどのように表示されるかを示しています。 両方のトレースの "X-ARR-LOG-ID" 値を照合することで、正しい要求が見つかったことを検証できます。
185. GENERAL_REQUEST_HEADERS Headers="Connection: Keep-Alive Content-Length: 0 Accept: */* Accept-Encoding: gzip, deflate Accept-Language: en-US Host: test Max-Forwards: 10 User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0) X-Original-URL: /time/ X-Forwarded-For: 192.168.0.204:49247 X-ARR-LOG-ID: dbf06c50-adb0-4141-8c04-20bc2f193a61
<multiple entries skipped for brevity>
345. GENERAL_FLUSH_RESPONSE_END BytesSent="0", ErrorCode="An operation was attempted on a nonexistent network connection. (0x800704cd)" 16:51:06.240
前の例では、HTTP 応答が送信される前に ARR サーバーが切断されていることがわかります。 GENERAL_FLUSH_RESPONSE_END のタイムスタンプは、宛先サーバー上の IIS ログ内の対応するエントリを検索するための大まかなガイドとして使用できます。
| date | time | s-ip | cs-method | cs-uri-stem | cs-uri-query | s-port | cs-username | sc-status | sc-substatus | sc-win32-status | time-taken |
|---|---|---|---|---|---|---|---|---|---|---|---|
| 2011-07-18 | 16:51:06 | 192.168.0.216 | GET | /時間/ | - | 80 | - | 200 | 0 | 64 | 45208 |
宛先サーバー上の IIS が HTTP 200 状態コードをログに記録し、要求が正常に完了したことを示します。 また、win32 の状態が 64 に変更され、ERROR_NETNAME_DELETEDにマップされます。 通常、この状態コードは、要求が完了する前にクライアント (この場合は ARR が "クライアント" である) が切断されたことを示します。
原因
ARR サーバーからタイムアウトが報告されました。これは、最初に確認する必要がある場所です。
メンバー サーバー ログは応答が 45 秒 (45208 ミリ秒) で送信されたことを示しますが、ARR サーバーからの IIS ログ エントリは、所要時間が 30 秒に非常に近いことを示します。 これは、ARR が要求をタイムアウトしていることを示し、サーバー ファームのプロキシ設定のプロキシ タイムアウトを調べることで確認できます。 既定では、30 秒に設定されています。
そのため、この場合、ARR タイムアウトが要求の実行よりも短かったことがわかります。 そのため、この実行時間が一般的であったか、要求に予想以上の時間がかかっていた理由を調べるために必要かどうかを確認することをお勧めします。 この実行時間が予想され、標準的なものであった場合は、ARR タイムアウトを増やすと、エラーが解決されます。
ERROR_WINHTTP_TIMEOUT のその他の考えられる理由は次のとおりです。
ResolveTimeout: 名前解決に指定されたタイムアウト期間より長い時間がかかる場合に発生します。ConnectTimeout: 名前が解決された後に、指定されたタイムアウト期間を超えてサーバーに接続する時間が長い場合に発生します。SendTimeout: 要求の送信にこのタイムアウト値よりも長い時間がかかる場合に発生します。 送信操作は取り消されます。ReceiveTimeout: 応答がこのタイムアウト値よりも長くかかる場合に発生します。 要求がキャンセルされた。
最初の 2 つの理由 ( ResolveTimeout と ConnectTimeout) を確認すると、前に説明したトラブルシューティング手法は機能しません。 これは、ターゲット サーバーにトラフィックが表示されないため、エラー コードが認識されないためです。 そのため、この ResolveTimeout や ConnectTimeout の場合は、WinHTTP トレースをキャプチャして追加の分析情報を得ることができます。 トラブルシューティングとトレースの他の例については、 WinHTTP または WEBIO トレース セクションと次のブログを参照してください。
- 502.3 ゲートウェイが無効です IIS アプリケーション要求ルーティング (ARR) で "操作がタイムアウトになりました"
- アプリケーション要求ルーティングを使用したトラブルシューティング用の Winhttp トレース オプション
502.3 接続終了エラー
ARR とメンバー サーバー間の接続がストリームの途中で切断された場合も、502.3 エラーが返されます。 この種の問題をテストするには、 Response.Close()を呼び出す.aspx ページを作成します。 次の例では、"time" という名前のディレクトリがあります。このディレクトリには、既定のドキュメントとして .aspx ページが構成されています。 ディレクトリを参照しようとすると、ARR に次のエラー メッセージが表示されます。
エラー 0x80072efe は、ERROR_INTERNET_CONNECTION_ABORTED に対応しています。 要求は、このトラブルシューティング ツールで前に使用したのと同じ手順を使用して実際に処理したサーバーにトレースできます。ただし、1 つの例外があります。 転送先サーバーの失敗した要求トレースでは、サーバーで処理された要求が表示されますが、関連付けられているログ エントリは IIS ログに表示されません。 代わりに、この要求は次のように HTTPERR ログに記録されます。
HTTP/1.1 GET /time/ - 1 Connection_Dropped DefaultAppPool
移行先サーバーの組み込みログでは問題に関する追加情報が提供されないため、次の手順では ARR サーバーからネットワーク トレースを収集します。 前の例では、データを返さずに Response.Close() 呼び出された.aspx ページ。 ネットワーク トレースでこれを表示すると、 Connection: close HTTP ヘッダーが宛先サーバーから送信されたことが示されます。 この情報を使用して、 Connection: close ヘッダーが送信された理由の調査を開始できます。
次のエラーは、メンバー サーバーからの無効な応答のもう 1 つの例です。
この例では、ARR はクライアントからデータを受信し始めましたが、要求エンティティ本文の読み取り中に問題が発生しました。 その結果、0x80072f78エラー コードが返されました。 さらに調査するには、メンバー サーバーの Network Monitor を使用して、問題のネットワーク トレースを取得します。 この特定のエラー例は、応答の一部を送信した後、ASP.net ページでResponse.Close()を呼び出し、Response.Flush()を呼び出すことによって作成されました。 ARR サーバーとメンバー サーバー間のトラフィックが SSL 経由の場合、Windows Server 2008 での WinHTTP トレースまたは Windows Server 2008 R2 の WebIO トレースによって追加情報が提供される場合があります。 WebIO トレースについては、このトラブルシューティング ツールで後述します。
502.4 要求をルーティングするための適切なサーバーが見つかりませんでした
http 502.4 エラーと関連するエラー コード0x00000000は、通常、ファームのすべてのメンバーがオフラインであるか、それ以外の場合は到達不能であることを示します。
最初の手順では、メンバー サーバーがオンラインであることを確認します。 これを確認するには、IIS マネージャーのファームの下にある Servers ノードに移動します。
![IIS マネージャーのサーバー ファームの下にある [サーバー] ノードに移動する方法を示すスクリーンショット。](media/troubleshooting-502-errors-in-arr/servers-node-under-service-farm.png)
オフライン サーバーを元に戻すには、サーバー名を右クリックし、 [負荷分散に追加] を選択。 サーバーをオンラインに戻さない場合は、ARR サーバーからメンバー サーバーに到達できるかどうかを確認します。 Servers ページの trace Messages ペインで、問題に関するいくつかの手掛かりを探します。 Web Farm Framework (WFF) 2.0 を使用している場合は、アプリケーション プールの再起動時にこのエラーが発生する可能性があります。 回復するには、Web ファーム サービスを再起動する必要があります。
WinHTTP または WebIO トレース
通常、 WireShark などのパケット キャプチャ ツールを使用するとタイムアウトの正確な特定に必要な情報が提供されます。ただし、(トラフィックが SSL で暗号化されている場合など)、別のアプローチを試す必要がある場合があります。 Windows 7 および Windows Server 2008 R2 以降では、管理コマンド プロンプトから次のコマンドを実行することで、netsh ツールを使用して WinHTTP トレースを有効にすることができます。
netsh trace start scenario=internetclient capture=yes persistent=no level=verbose tracefile=c:\temp\net.etl
その後、問題を再現します。 問題が再現されたら、次のコマンドを実行してトレースを停止します。
netsh trace stop
stop コマンドの完了には数秒かかります。 完了すると、 net.etl ファイルと net.cab ファイルが C:\tempで見つかります。 上記のコマンドを実行する前に、 C:\temp フォルダーが存在することを確認する必要があります。 .cab ファイルには、.etl ファイルの分析に役立つ可能性があるイベント ログやその他のデータが含まれています。
ログを分析するには、
Netmon 3.4 以降で開きます。
パーサー プロファイルが設定されていることを確認します。 これを実現するには、 Tools>Options メニューを開き、 Parser Profiles タブ >Windows プロファイルを選択し、 [アクティブとして設定 ] ボタンを選択して変更を適用します。
UT プロセス名列と関連付けることで、ARR が実行されているw3wp.exe インスタンスが見つかるまでトレースをスクロールします。
w3wp を右クリックし、 [UT プロセス名の追加] を選択してフィルターを表示します。 これにより、表示フィルターが次のように設定されます。
UTProcessName == "w3wp.exe (1432)"
次のように変更すると、結果をさらにフィルター処理することができます。
UTProcessName == "w3wp.exe (<pid>)" AND ProtocolName == "WINHTTP_MicrosoftWindowsWinHttp"
タイムアウト エラーが発生するまで、出力をスクロールする必要があります。 次の例では、要求の実行に 30 秒 (ARR の既定のタイムアウト) を超える時間がかかったため、タイムアウトしました。
336 2:32:22 PM 7/22/2011 32.6380453 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::sys-recver starts in _INIT state
337 2:32:22 PM 7/22/2011 32.6380489 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::current thread is not impersonating
340 2:32:22 PM 7/22/2011 32.6380584 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::sys-recver processing WebReceiveHttpResponse completion (error-cdoe = ? (0x5b4), overlapped = 003728F0)
341 2:32:22 PM 7/22/2011 32.6380606 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::sys-recver failed to receive headers; error = ? (1460)
342 2:32:22 PM 7/22/2011 32.6380800 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::ERROR_WINHTTP_FROM_WIN32 mapped (?) 1460 to (ERROR_WINHTTP_TIMEOUT) 12002
343 2:32:22 PM 7/22/2011 32.6380829 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::sys-recver returning ERROR_WINHTTP_TIMEOUT (12002) from RecvResponse()
344 2:32:22 PM 7/22/2011 32.6380862 w3wp.exe (1432) WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:32:23.123 ::sys-req completes recv-headers inline (sync); error = ERROR_WINHTTP_TIMEOUT (12002)
次の例では、コンテンツ サーバーは完全にオフラインでした。
42 2:26:39 PM 7/22/2011 18.9279133 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::WinHttpReceiveResponse(0x11d23d0, 0x0) {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
43 2:26:39 PM 7/22/2011 18.9279633 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::sys-recver starts in _INIT state {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
44 2:26:39 PM 7/22/2011 18.9280469 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::current thread is not impersonating {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
45 2:26:39 PM 7/22/2011 18.9280776 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::sys-recver processing WebReceiveHttpResponse completion (error-cdoe = WSAETIMEDOUT (0x274c), overlapped = 003728F0) {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
46 2:26:39 PM 7/22/2011 18.9280802 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::sys-recver failed to receive headers; error = WSAETIMEDOUT (10060) {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
47 2:26:39 PM 7/22/2011 18.9280926 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::ERROR_WINHTTP_FROM_WIN32 mapped (WSAETIMEDOUT) 10060 to (ERROR_WINHTTP_TIMEOUT) 12002 {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
48 2:26:39 PM 7/22/2011 18.9280955 WINHTTP_MicrosoftWindowsWinHttp WINHTTP_MicrosoftWindowsWinHttp:12:26:39.704 ::sys-recver returning ERROR_WINHTTP_TIMEOUT (12002) from RecvResponse() {WINHTTP_MicrosoftWindowsWinHttp:4, NetEvent:3}
その他のリソース
サードパーティの情報に関する免責事項
この資料に記載されているサードパーティ製品は、マイクロソフトと関連のない他社の製品です。 明示的か黙示的かにかかわらず、これらの製品のパフォーマンスや信頼性についてマイクロソフトはいかなる責任も負わないものとします。