Rozwiązywanie problemów z błędami 502 w usłudze ARR

Ten artykuł ułatwia rozwiązywanie problemów związanych z błędami 502 w routingu żądań aplikacji (ARR).

Dotyczy: Internet Information Services

HTTP 502 — omówienie

Podczas pracy z wdrożeniami routingu żądań aplikacji usług IIS (ARR), jednym z błędów, które mogą być widoczne, jest "HTTP 502 — zła brama". Błąd 502.3 oznacza, że podczas działania jako serwer proxy usługa ARR nie mogła ukończyć żądania do nadrzędnego serwera i wysłać odpowiedź z powrotem do klienta. Ten problem może wystąpić z wielu powodów. Na przykład niepowodzenie nawiązania połączenia z serwerem, brak odpowiedzi z serwera lub zbyt długo trwało reagowanie (przekroczenie limitu czasu). Jeśli możesz odtworzyć błąd, przeglądając farmę internetową z kontrolera, a szczegółowe błędy są włączone na serwerze, może zostać wyświetlony błąd podobny do następującego komunikatu o błędzie:

Główna przyczyna błędu określa, co należy zrobić, aby rozwiązać ten problem.

Błędy przekroczenia limitu czasu 502.3

Funkcja ARR używa kodu błędu na powyższym zrzucie ekranu do serwera proxy żądania i określenia źródła błędu, ponieważ zawiera kod powrotny z WinHTTP.

Kod błędu można zdekodować za pomocą narzędzia err.exe. W tym przykładzie kod błędu jest mapowy na ERROR_WINHTTP_TIMEOUT. Te informacje można również znaleźć w dziennikach usług IIS dla skojarzonej witryny internetowej na kontrolerze ARR. Poniżej przedstawiono fragment wpisu dziennika usług IIS dla błędu 502.3 z większością pól przyciętych do czytelności:

Stan win32 12002 jest mapowany na ten sam błąd ERROR_WINHTTP_TIMEOUT zgłoszony na stronie błędu.

Co dokładnie przekroczono limit czasu?

Możesz sprawdzić ten limit czasu, włączając śledzenie nieudanych żądań na serwerze usług IIS. Pierwszy punkt widoczny w dzienniku śledzenia żądań, do którego wysłano żądanie w zdarzeniu ARR_SERVER_ROUTED. Drugim punktem jest identyfikator X-ARR-LOG-ID, którego można użyć do śledzenia żądania na serwerze docelowym. Pomaga to śledzić miejsce docelowe lub docelowe żądania 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

W poniższym przykładzie pokazano, jak może to wyglądać na dziennikach śledzenia niepomyślnych żądań serwera docelowego. Możesz sprawdzić, czy znaleziono poprawne żądanie, pasując do wartości "X-ARR-LOG-ID" w obu śladach.

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

W poprzednim przykładzie widać, że serwer ARR został rozłączony przed wysłaniem odpowiedzi HTTP. Sygnatura czasowa GENERAL_FLUSH_RESPONSE_END może służyć jako przybliżony przewodnik, aby znaleźć odpowiedni wpis w dziennikach usług IIS na serwerze docelowym.

Usługi IIS na serwerze docelowym zarejestrowały kod stanu HTTP 200 wskazujący, że żądanie zostało ukończone pomyślnie. Ponadto stan win32 został zmieniony na 64, który mapuje na ERROR_NETNAME_DELETED. Ten kod stanu zazwyczaj wskazuje, że klient (ARR jest "klientem" w tym przypadku) rozłączony przed ukończeniem żądania.

Przyczyna

Serwer ARR zgłosił przekroczenie limitu czasu, czyli miejsce, w którym należy najpierw wyglądać.

Chociaż dziennik serwera członkowskiego wskazuje, że odpowiedź została wysłana w ciągu 45 sekund (45208 ms), wpis dziennika usług IIS z serwera ARR wskazuje, że czas potrzebny jest bardzo blisko 30 sekund. Oznacza to, że usługa ARR przekracza limit czasu żądania i można to potwierdzić, sprawdzając limit czasu serwera proxy w ustawieniach serwera proxy farmy serwerów. Domyślnie jest ustawiona na 30 sekund.

W tym przypadku można wyraźnie zobaczyć, że przekroczenie limitu czasu usługi ARR było krótsze niż wykonanie żądania. W związku z tym możesz sprawdzić, czy ten czas wykonywania był typowy lub jeśli trzeba sprawdzić, dlaczego żądanie trwa dłużej niż oczekiwano. Jeśli ten czas wykonywania był oczekiwany i normalny, zwiększenie limitu czasu ARR powinno usunąć błąd.

Inne możliwe przyczyny ERROR_WINHTTP_TIMEOUT to:

• ResolveTimeout: występuje, jeśli rozpoznawanie nazw trwa dłużej niż określony okres limitu czasu.
• ConnectTimeout: występuje, jeśli połączenie z serwerem po rozpoznaniu nazwy trwa dłużej niż określony limit czasu.
• SendTimeout: występuje, jeśli wysłanie żądania trwa dłużej niż ta wartość limitu czasu. Operacja wysyłania jest anulowana.
• ReceiveTimeout: występuje, jeśli odpowiedź trwa dłużej niż ta wartość limitu czasu. Żądanie zostało anulowane.

Podczas obserwowania dwóch pierwszych powodów ResolveTimeout i ConnectTimeoutmetody opisanej wcześniej metodologii rozwiązywania problemów nie będą działać. Jest to spowodowane tym, że nie widzisz żadnego ruchu na serwerze docelowym i w związku z tym nie znasz kodu błędu. Dlatego w tym przypadku ResolveTimeout lub ConnectTimeout możesz chcieć przechwycić ślad WinHTTP w celu uzyskania dodatkowych szczegółowych informacji. Zobacz sekcję śledzenia WinHTTP lub WEBIO i w następujących blogach, aby zapoznać się z innymi przykładami dotyczącymi rozwiązywania problemów i śledzenia:

• 502.3 Zła brama "Upłynął limit czasu operacji" z routingiem żądań aplikacji usług IIS (ARR)
• Opcje śledzenia Winhttp dotyczące rozwiązywania problemów z routingiem żądań aplikacji

Błędy zakończenia połączenia 502.3

Błędy 502.3 są również zwracane, gdy połączenie między usługą ARR a serwerem członkowskim jest rozłączone w połowie strumienia. Aby przetestować ten typ problemu, utwórz stronę .aspx, która wywołuje metodę Response.Close(). W poniższym przykładzie istnieje katalog o nazwie "time", który jest skonfigurowany ze stroną .aspx jako dokument domyślny w tym katalogu. Podczas próby przeglądania katalogu usługa ARR wyświetla następujący komunikat o błędzie:

0x80072efe błędu odpowiada ERROR_INTERNET_CONNECTION_ABORTED. Żądanie można prześledzić do serwera, który faktycznie go przetworzył, wykonując te same kroki, które były używane wcześniej w tym narzędziu do rozwiązywania problemów, z jednym wyjątkiem. Śledzenie żądań niepomyślnych na serwerze docelowym pokazuje żądanie przetworzone na serwerze, ale skojarzony wpis dziennika nie jest wyświetlany w dziennikach usług IIS. Zamiast tego to żądanie jest rejestrowane w dzienniku HTTPERR w następujący sposób:

HTTP/1.1 GET /time/ - 1 Connection_Dropped DefaultAppPool

Wbudowane dzienniki na serwerze docelowym nie zawierają żadnych dodatkowych informacji na temat problemu, więc następnym krokiem będzie zebranie śledzenia sieci z serwera ARR. W poprzednim przykładzie strona .aspx wywoływana Response.Close() bez zwracania żadnych danych. Wyświetlenie tego w śladzie sieci spowoduje wyświetlenie, że Connection: close nagłówek HTTP pochodzi z serwera docelowego. Dzięki tym informacjom możesz rozpocząć badanie, dlaczego Connection: close nagłówek został wysłany.

Następujący błąd to kolejny przykład nieprawidłowej odpowiedzi z serwera członkowskiego:

W tym przykładzie usługa ARR zaczęła odbierać dane od klienta, ale wystąpił problem podczas odczytywania treści jednostki żądania. Spowodowało to zwrócenie kodu błędu 0x80072f78. Aby dokładniej zbadać problem, użyj monitora sieciowego na serwerze członkowskim, aby uzyskać ślad sieci problemu. Ten konkretny przykład błędu został utworzony przez wywołanie na Response.Close() stronie ASP.net po wysłaniu części odpowiedzi, a następnie wywołaniu metody Response.Flush(). Jeśli ruch między serwerem ARR a serwerami członkowskimi odbywa się za pośrednictwem protokołu SSL, śledzenie WinHTTP w systemie Windows Server 2008 lub śledzenie funkcji WebIO w systemie Windows Server 2008 R2 może dostarczyć dodatkowe informacje. Śledzenie webIO zostało opisane w dalszej części tego narzędzia do rozwiązywania problemów.

502.4 Nie można odnaleźć odpowiedniego serwera w celu kierowania żądania

Błąd HTTP 502.4 ze skojarzonym kodem błędu 0x00000000 zazwyczaj wskazuje, że wszystkie elementy członkowskie farmy są w trybie offline lub w inny sposób niedostępne.

Pierwszym krokiem jest sprawdzenie, czy serwery członkowskie są w trybie online. Aby to sprawdzić, przejdź do węzła Serwery w farmie w Menedżerze usług IIS.

Aby przywrócić serwery w trybie offline, kliknij prawym przyciskiem myszy nazwę serwera i wybierz polecenie Dodaj do równoważenia obciążenia. Jeśli nie możesz przywrócić serwerów w trybie online, sprawdź, czy serwery członkowskie są dostępne z serwera ARR. Sprawdź okienko śledzenia Wiadomości na stronie Serwery, aby wyszukać pewne wskazówki dotyczące problemu. Jeśli używasz programu Web Farm Framework (WFF) 2.0, może wystąpić ten błąd po ponownym uruchomieniu puli aplikacji. Aby odzyskać, należy ponownie uruchomić usługę farmy sieci Web.

Śledzenie WinHTTP lub WebIO

Zazwyczaj narzędzia do przechwytywania pakietów, takie jak WireShark , udostępniają informacje potrzebne do zidentyfikowania dokładnie tego, co przekracza limit czasu. Istnieją jednak czasy (np. gdy ruch jest szyfrowany za pomocą protokołu SSL), które należy podjąć, aby spróbować użyć innego podejścia. Począwszy od systemów Windows 7 i Windows Server 2008 R2, można włączyć śledzenie WinHTTP przy użyciu narzędzia netsh, uruchamiając następujące polecenie w wierszu polecenia administracyjnego:

netsh trace start scenario=internetclient capture=yes persistent=no level=verbose tracefile=c:\temp\net.etl

Następnie odtwórz problem. Po odtworzeniu problemu zatrzymaj śledzenie, uruchamiając następujące polecenie:

netsh trace stop

Wykonanie stop polecenia zajmuje kilka sekund. Po zakończeniu znajdziesz plik net.etl i plik net.cab w pliku C:\temp. Przed uruchomieniem powyższych poleceń należy upewnić się, że C:\temp folder istnieje. Plik .cab zawiera dzienniki zdarzeń i inne dane, które mogą okazać się przydatne podczas analizowania pliku etl.

Aby przeanalizować dziennik,

1. Otwórz go w programie Netmon 3.4 lub nowszym.

2. Upewnij się, że skonfigurowaliśmy profil analizatora. Aby to osiągnąć, otwórz menu Narzędzia>Opcje, wybierz kartę >Profile analizatora w systemie Windows, a następnie wybierz przycisk Ustaw jako aktywny, aby zastosować zmiany.

3. Przewiń ślad do momentu znalezienia wystąpienia w3wp.exe , w którym działa usługa ARR, korelując z kolumną nazwy procesu UT.

4. Kliknij prawym przyciskiem myszy pozycję w3wp i wybierz polecenie Dodaj nazwę procesu UT, aby wyświetlić filtr. Spowoduje to ustawienie filtru wyświetlania podobnego do:

   UTProcessName == "w3wp.exe (1432)"
   

Możesz dalej filtrować wyniki, zmieniając je na następujące:

UTProcessName == "w3wp.exe (<pid>)" AND ProtocolName == "WINHTTP_MicrosoftWindowsWinHttp"

Musisz przewinąć dane wyjściowe do momentu znalezienia błędu przekroczenia limitu czasu. W poniższym przykładzie upłynął limit czasu żądania, ponieważ uruchomienie żądania trwało ponad 30 sekund (domyślny limit czasu usługi 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) 

W poniższym przykładzie serwer zawartości był całkowicie w trybie offline:

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} 

Inne zasoby

• Narzędzie wyszukiwania błędów
• Kody błędów Winhttp
• Śledzenie żądań, które zakończyło się niepowodzeniem
• Śledzenie Winhttp
• Microsoft Network Monitor

Zastrzeżenie dotyczące innych firm

Produkty innych firm omówione w tym artykule są wytwarzane przez producentów niezależnych od firmy Microsoft. Firma Microsoft nie udziela żadnych gwarancji, dorozumianych ani żadnego innego rodzaju, w odniesieniu do wydajności lub niezawodności tych produktów.