ARR での 502 エラーのトラブルシューティング

この記事は、アプリケーション要求ルーティング (ARR) の 502 エラーに関連する問題を解決するのに役立ちます。

適用対象: インターネット インフォメーション サービス

HTTP 502 - 概要

IIS アプリケーション要求ルーティング (ARR) デプロイを使用すると、"HTTP 502 - Bad Gateway" というエラーが発生する可能性があります。 502.3 エラーは、プロキシとして機能しているときに、ARR がアップストリーム サーバーへの要求を完了してクライアントに応答を送信できなかったことを意味します。 この問題は、複数の理由で発生する可能性があります。 たとえば、サーバーに接続できない、サーバーからの応答がない、サーバーが応答に時間がかかりすぎた (タイムアウト) などです。 コントローラーから Web ファームを参照してエラーを再現でき、サーバーで 詳細なエラー が有効になっている場合は、次のようなエラー メッセージが表示されることがあります。

サーバーで詳細なエラーが有効になっているときに表示される詳細な 502 エラーを示すスクリーンショット。

エラーの根本原因によって、問題を解決するために何を行う必要があるかが決まります。

502.3 タイムアウト エラー

ARR では、前のスクリーンショットのエラー コードを使用して要求をプロキシし、WinHTTP からのリターン コードが含まれているため、エラーの原因を特定します。

ツールerr.exeを使用してエラー コードをデコードできます。 この例では、エラー コードは ERROR_WINHTTP_TIMEOUT にマップされます。 この情報は、ARR コントローラーの関連 Web サイトの IIS ログにも表示されます。 502.3 エラーの IIS ログ エントリからの抜粋を次に示します。ほとんどのフィールドは読みやすくするためにトリミングされています。

sc-status sc-substatus sc-win32-status 時間のかかった
502 3 12002 29889

win32 状態 12002 は、エラー ページで報告されたのと同じERROR_WINHTTP_TIMEOUT エラーにマップされます。

何が正確にタイムアウトしましたか?

このタイムアウトをチェックするには、IIS サーバーで [失敗した要求トレース] を有効にします。 失敗した要求トレース ログに表示できる最初のポイントは、要求が 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

次の例は、ターゲット サーバーの Failed Request Tracing ログでこれがどのように表示されるかを示しています。 両方のトレースで "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 時間のかかった
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 つの理由と ConnectTimeoutを確認すると、ResolveTimeout前に説明したトラブルシューティング手法は機能しません。 これは、ターゲット サーバーにトラフィックが表示されないため、エラー コードが認識されないためです。 そのため、この場合 ResolveTimeoutConnectTimeout 、WinHTTP トレースをキャプチャして追加の分析情報を得ることができます。 トラブルシューティングとトレースの他の例については、「 WinHTTP または WEBIO トレース 」セクションと次のブログを参照してください。

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 サーバーからネットワーク トレースを収集します。 前の例では、データを返さずに .aspx ページが呼び出 Response.Close() されています。 これをネットワーク トレースで表示すると、 Connection: close HTTP ヘッダーが宛先サーバーから送信されていたことが示されます。 この情報を使用すると、ヘッダーが送信された理由の調査を Connection: close 開始できます。

次のエラーは、メンバー サーバーからの無効な応答の別の例です。

メンバー サーバーからの無効な応答を示すスクリーンショット。

この例では、ARR はクライアントからデータを受信し始めましたが、要求エンティティ本文の読み取り中に問題が発生しました。 その結果、0x80072f78エラー コードが返されました。 さらに調査するには、メンバー サーバーの ネットワーク モニター を使用して、問題のネットワーク トレースを取得します。 この特定のエラー例は、応答の一部を送信してから を呼び出 Response.Close() した後、 ASP.net ページで を呼び出 Response.Flush()すことによって作成されました。 ARR サーバーとメンバー サーバー間のトラフィックが SSL 経由の場合は、Windows Server 2008 での WinHTTP トレースまたは Windows Server 2008 R2 での WebIO トレースによって追加情報が提供される場合があります。 WebIO トレースについては、このトラブルシューティング ツールで後述します。

502.4 要求をルーティングするための適切なサーバーが見つかりませんでした

http 502.4 エラーと関連付けられたエラー コード0x00000000は、通常、ファームのすべてのメンバーがオフラインであるか、それ以外の場合は到達不能であることを示します。

要求をルーティングするための適切なサーバーが見つからないというメッセージを示すスクリーンショット。

最初の手順は、メンバー サーバーがオンラインであることを確認することです。 これをチェックするには、IIS マネージャーのファームの [サーバー] ノードに移動します。

IIS マネージャーのサーバー ファームの下にある [サーバー] ノードに移動する方法を示すスクリーンショット。

オフライン サーバーを元に戻すには、サーバー名を右クリックし、[ 負荷分散に追加] を選択します。 サーバーをオンラインに戻さない場合は、メンバー サーバーが ARR サーバーから到達可能かどうかを確認します。 [サーバー] ページの [トレース メッセージ] ウィンドウを確認して、問題に関するいくつかの手掛かりを探します。 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 ファイルの分析に役立つ可能性があるイベント ログやその他のデータが含まれています。

ログを分析するには、

  1. Netmon 3.4 以降で開きます。

  2. パーサー プロファイルが設定されていることを確認します。 これを実現するには、[ツール>オプション] メニューを開き、[パーサー プロファイル] タブの [Windows プロファイル] を>選択し、[アクティブに設定] ボタンを選択して変更を適用します。

  3. UT プロセス名列と関連付けることで ARR が実行されている w3wp.exe インスタンスが見つかるまでトレースをスクロールします。

  4. 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} 

その他のリソース

サードパーティの情報に関する免責事項

この資料に記載されているサードパーティ製品は、マイクロソフトと関連のない他社の製品です。 明示的か黙示的かにかかわらず、これらの製品のパフォーマンスや信頼性についてマイクロソフトはいかなる責任も負わないものとします。