Iis error 502

by Richard Marr

Tools Used in this Troubleshooter:

• IIS Failed Request Tracing
• Network Monitor
• Winhttp Tracing

This material is provided for informational purposes only. Microsoft makes no warranties, express or implied.

HTTP 502 — Overview

When working with IIS Application Request Routing (ARR) deployments, one of the errors that you may see is «HTTP 502 — Bad Gateway». The 502.3 error means that — while acting as a proxy — ARR was unable to complete the request to the upstream server and send a response back to the client. This can happen for multiple reasons — for example: failure to connect to the server, no response from the server, or the server took too long to respond (time out). If you are able to reproduce the error by browsing the web farm from the controller, and detailed errors are enabled on the server, you may see an error similar to the following:

Figure 1 (Click image to expand)

The root cause of the error will determine the actions you should take to resolve the issue.

502.3 Timeout Errors

The error code in the screenshot above is significant because it contains the return code from WinHTTP, which is what ARR uses to proxy the request and identifies the reason for the failure.

You can decode the error code with a tool like err.exe. In this example, the error code maps to ERROR_WINHTTP_TIMEOUT. You can also find this information in the IIS logs for the associated website on the ARR controller. The following is an excerpt from the IIS log entry for the 502.3 error, with most of the fields trimmed for readability:

The win32 status 12002 maps to the same ERROR_WINHTTP_TIMEOUT error reported in the error page.

What exactly timed-out?

We investigate this a bit further by enabling Failed Request Tracing on the IIS server. The first thing we can see in the failed request trace log is where the request was sent to in the ARR_SERVER_ROUTED event. The second item I have highlighted is what you can use to track the request on the target server, the X-ARR-LOG-ID. This will help if you are tracing the target or destination of the HTTP request:

The following example shows how this might look on the target server’s Failed Request Tracing logs; you can validate that you have found the correct request by matching up the «X-ARR-LOG_ID» values in both traces.

In the above example, we can see that the ARR server disconnected before the HTTP response was sent. The timestamp for GENERAL_FLUSH_RESPONSE_END can be used as a rough guide to find the corresponding entry in the IIS logs on the destination server.

Note that IIS on the destination server logged an HTTP 200 status code, indicating that the request completed successfully. Also note that the win32 status has changed to 64, which maps to ERROR_NETNAME_DELETED. This generally indicates that the client (ARR being the ‘client’ in this case) had disconnected before the request completed.

What happened?

Only the ARR server is reporting a timeout, so that is where we should look first.

In the IIS log entry from the ARR server, we can see that the time-taken is very close to 30 seconds, but the member server log shows that it took 45 seconds (45208 ms) to send the response. This suggests that ARR is timing the request out, and if we check the proxy timeout in the server farm’s proxy settings, we will see that it is set to 30 seconds by default.

So in this case we can clearly see that the ARR timeout was shorter than the execution of the request. Therefore, you would want to investigate whether this execution time was normal or whether you would need to look at why the request was taking longer than expected. If this execution time was expected and normal, increasing the ARR timeout should resolve the error.

Other possible reasons for ERROR_WINHTTP_TIMEOUT include:

• ResolveTimeout: This occurs if name resolution takes longer than the specified timeout period.
• ConnectTimeout: This occurs if it takes longer than the specified timeout period to connect to the server after the name resolved.
• SendTimeout: If sending a request takes longer than this time-out value, the send operation is canceled.
• ReceiveTimeout: If a response takes longer than this time-out value, the request is canceled.

Looking at the first two examples, ResolveTimeout and ConnectTimeout, the troubleshooting methodology outlined above would not work. This is because you would not see any traffic on the target server and therefore would not know the error code. Thus in this case of ResolveTimeout or ConnectTimeout you would want to capture a WinHTTP trace for additional insight. See the WinHTTP/WEBIO Tracing section of this troubleshooter as well as the following blogs for additional examples on troubleshooting and tracing:

• 502.3 Bad Gateway «The operation timed out» with IIS Application Request Routing (ARR)
• Winhttp Tracing Options for Troubleshooting with Application Request Routing

502.3 Connection Termination Errors

502.3 errors are also returned when the connection between ARR and the member server is disconnected mid-stream. To test this type of problem, create a simple .aspx page that calls Response.Close(). In the following example there is a directory called «time» which is configured with a simple aspx page as the default document of that directory. When browsing to the directory, ARR will display this error:

Figure 2 (Click image to expand)

The error 0x80072efe corresponds to ERROR_INTERNET_CONNECTION_ABORTED. The request can be traced to the server that actually processed it using the same steps used earlier in this troubleshooter, with one exception; while Failed Request Tracing on the destination server shows the request was processed on the server, the associated log entry does not appear in the IIS logs. Instead, this request is logged in the HTTPERR log as follows:

[!code-consoleMain]

The built-in logs on the destination server do not provide any additional information about the problem, so the next step would be to gather a network trace from the ARR server. In the example above, the .aspx page called Response.Close() without returning any data. Viewing this in a network trace would show that a Connection: close HTTP header was coming from the destination server. With this information you could now start an investigation into why the Connection: close header was sent.

The error below is another example of an invalid response from the member server:

Figure 3 (Click image to expand)

In this example, ARR started to receive data from the client but something went wrong while reading the request entity body. This results in the 0x80072f78 error code being returned. To investigate further, use Network Monitor on the member server to get a network trace of the problem. This particular error example was created by calling Response.Close() in the ASP.net page after sending part of the response and then calling Response.Flush(). If the traffic between the ARR server and the member servers is over SSL, then WinHTTP tracing on Windows Server 2008 or WebIO tracing on Windows Server 2008 R2 may provide additional information. WebIO tracing is described later in this troubleshooter.

502.4 No appropriate server could be found to route the request

The HTTP 502.4 error with an associated error code of 0x00000000 generally indicates that all the members of the farm are either offline, or otherwise unreachable.

Figure 4 (Click image to expand)

The first step is to verify that the member servers are actually online. To check this, go to the «servers» node under the farm in the IIS Manager.

Figure 5 (Click image to expand)

Servers that are offline can be brought back online by right-clicking on the server name and choosing «Add to Load Balancing». If you cannot bring the servers back online, verify the member servers are reachable from the ARR server. The «trace Messages» pane on the «servers» page may also provide some clues about the problem. If you are using Web Farm Framework (WFF) 2.0, you may receive this error if the application pool restarts. You will need to restart the Web Farm Service to recover.

WinHTTP/WebIO Tracing

Usually, Network Monitor will provide you with the information you need to identify exactly what is timing out, however there are times (such as when the traffic is SSL encrypted) that you will need to try a different approach. On Windows 7 and Windows Server 2008R2 you can enable WinHTTP tracing using the netsh tool by running the following command from an administrative command prompt:

[!code-consoleMain]

Then, reproduce the problem. Once the problem is reproduced, stop the tracing by running the following command from the command prompt:

[!code-consoleMain]

The stop command will take a few seconds to finish. When it is done, you will find a net.etl file and a net.cab file in C:temp. The .cab file contains event logs and additional data that may prove helpful in analyzing the .etl file.

To analyze the log, open it in Netmon 3.4 or later. Make sure you have set up your parser profile as described here. Scroll through the trace until you find the w3wp.exe instance where ARR is running by correlating with the «UT process name» column. Right click on w3wp and choose «Add UT Process name to display filter». This will set the display filter similar to:

[!code-consoleMain]

You can further filter the results by changing it to the following:

[!code-consoleMain]

You will need to scroll through the output until you find the timeout error. In the example below, a request timed out because it took more than 30 seconds (ARR’s default timeout) to run.

In this next example, the content server was completely offline:

Other Resources

• ERR.EXE
• Winhttp Error Codes
• Failed Request Tracing
• Winhttp Tracing
• Network Monitor

When working with ARR deployments one of the errors you might see is  502.3  Bad Gateway. The 502.3 means while acting as a proxy ARR was unable to complete the request to the upstream server and subsequently send a response back to the client. This can happen for multiple reasons including , failure to connect to the server , no response from the server, or server took too long to respond (time out). 

For the purposes of this post we are going to look at a timeout error and the data that can be gathered to help isolate the cause.

If you are looking at this post then you probably have already seen this error or something similar. This is shown in the browser when detailed errors are enabled in IIS.

Another way to identify the source of the 502.3  is with  Failed Request Tracing   logs in IIS configured to capture Status code 502.

From the message the key details are the ErrorCode  which you can use to map to to the Winhttp error message, which in this case  is ERROR_WINHTTP_TIMEOUT ( Reference WinHttp Error Codes). You will also see in the next line that this is translated to  “The operation timed out”.  Note that both the 0x80072ee2 and 2147954402 map to the same error  ERROR_WINHTTP_TIMEOUT.

Now that we know its a timeout we need to determine what type of timeout occurred. Here is a list of the timeouts that can occur in Winhttp ( which if you haven’t guessed already is what ARR uses to proxy requests)

• ResolveTimeout : This occurs if name resolution takes longer than the specified timeout period.
• ConnectTimeout : This occurs if it takes longer than the specified timeout period to connect to the server after the name resolved. 
• SendTimeout  :     If sending a request takes longer than this time-out value, the send is canceled.
• ReceiveTimeout :  If a response takes longer than this time-out value, the request is canceled.

To identify what type of timeout we can use Winhttp’s built in logging,These can be enabled from the command line on the ARR server using NETSH.  

• Winhttp Traces:

Following  the example below you can search your log for WinHttpOpenRequest to find your request. The calls to WinHttpSetTimeouts  are setting the 4 timeout values  based on your ARR time settings found in the Proxy Configuration page of your ARR Server Farm or in the Server Proxy settings. Next we find WinHttpSendRequest then WinHttpReceiveResponse , so we know we are now in the receive stage. Finally we see that the error in is in RecvResponse so we know this is a ReceiveTimeout. For a different failure such as ResolveTimeout  we would not see the log make it to WinHttpReceiveResponse and the failure would be logged earlier.

10:23:45.100 ::WinHttpOpenRequest(0x35a970, "GET", "/sleep/default.aspx", "HTTP/1.0", "", 0x0, 0x00000080)
 …………
10:23:45.100 ::WinHttpSetTimeouts(0x2e42d80, 30000, 30000, 30000, 30000)
10:23:45.100 ::WinHttpSetTimeouts() returning TRUE
………… 

10:23:45.100 ::WinHttpSendRequest(0x2e42d80, "Accept: */*rnAccept-Encoding: gzip, deflaternAccept-Language: en-CArnHost: contoso.com", 479, 0x0, 0, 0, 24794c0)
………… 

10:24:15.397 ::Completing WinHttpSendRequest() with success; Request Handle = 02E42D80, Context = 024794C0, Buffer = 00000000 (0x0), Buffer Length = 0
10:24:15.397 ::WinHttpReceiveResponse(0x2e42d80, 0x0)
………… 
10:24:15.397 ::sys-recver failed to receive headers; error = ? (1460)
10:24:15.397 ::ERROR_WINHTTP_FROM_WIN32 mapped (?) 1460 to (ERROR_WINHTTP_TIMEOUT) 12002
10:24:15.397 ::sys-recver returning ERROR_WINHTTP_TIMEOUT (12002) from RecvResponse()
10:24:15.397 ::sys-req completes recv-headers inline (sync); error = ERROR_WINHTTP_TIMEOUT (12002)

Now that we know this is receive timeout we can look at the content server and see how long the request took.

• IIS logs on the  Content Server: 

Examine the IIS logs on the  content server and check the sc-status and sc-win32-status and time-taken fields.  This will give you an idea of whether the request processed successfully ( sc-status = 200)  and the time-taken to see if this exceeds your ARR timeout and if this is the expected execution time for your web page . You can determine from this whether you need to troubleshoot a long running application or simply increase the ARR timeout settings. Checking the Win32 field for errors such as 1236 (ERROR_CONNECTION_ABORTED) or  64 (ERROR_NETNAME_DELETED) indicate that something happened on the network layer such as  a connection reset. 

Using our example the IIS logs here show that the Request  took ~35 seconds (time-taken=35615) , the request was processed successfully on the server (sc-status=200) , but  there was a problem sending the request (sc-win32-status=64) which means the connection was gone when the content server tried to send the request.  This was because the client (ARR) has already timed-out and closed the TCP connection.

#Software: Microsoft Internet Information Services 7.0
#Version: 1.0
#Date: 2010-06-23 20:11:33
#Fields: 

date time            cs-method cs-uri-stem         s-port  sc-status sc-substatus sc-win32-status time-taken
2010-06-23 20:11:33  GET       /sleep/default.aspx 80      200       0            64               35615

Summary

So in this case we can see that the request took >35 seconds  which is longer than the default timeout in ARR. When this occurs ARR  ( or Winhttp underlying ARR)  will close the connection to the content server which is what cause the Win32 error 64.

Now its up to you to determine whether its acceptable that your page is running for 35 seconds  and you just need to increase time outs in ARR.

Since the application issues are beyond the scope of this blog I’ll leave you with two command lines for setting ARR  timeouts for either a  Server Proxy  configuration or Server Farms.

Server Proxy : appcmd.exe set config  -section:system.webServer/proxy /timeout:»00:00:45″  /commit:apphost

Server Farm :  appcmd.exe set config  -section:webFarms /[name=’ArrFarm’].applicationRequestRouting.protocol.timeout:»00:00:45″  /commit:apphost

References

WinHttpSetTimeouts Function

Netsh Commands for Windows Hypertext Transfer Protocol (WINHTTP)

Failed Request Tracing in IIS (FREB)

UPDATE : New Post for Winhttp Tracing Methods

ARR on IIS.NET