Ir al contenido

Entradas etiquetadas como ‘Application Request Routing’

8
Feb

Winhttp Tracing Options for Troubleshooting with Application Request Routing

Since  there are multiple ways to gather this in the Windows 2008 and 2008R2 I thought this might be helpful to outline this for the different platforms and how to gather this for fellow ARR troubleshooters.

Windows 2008

1. Start the Tracing . From a command prompt run the following command:

netsh winhttp set tracing trace-file-prefix=”C:TEMPWinHttpLog” level=verbose format=hex state=enabled max-trace-file-size=1048576000

2.Recycle the IIS Application Pool.

3. Reproduce the issue.

4. Stop the Tracing. From a command prompt run the following command:

netsh winhttp set tracing state=disabled

5. Review the trace with Notepad or any Text editor.

NOTE: The Identity of the  IIS application pool will require write access to the  log location  c:Temp in this example:

This type of tracing is process bitness specific, so if you are looking at a 32 bit process running from 64 bit OS, you need to use: c:windowssyswow64cmd.exe, rather than using the regular 64 bit cmd.exe (start a run a cmd.exe)

Windows 2008 R2

Method 1

This method will output the Winhttp API calls , but not raw data for network communication. From a command prompt run the following command:

1. Start the tracing

netsh winhttp set tracing trace-file-prefix=”C:TempTest3″ level=verbose format=hex

netsh winhttp set tracing output=file max-trace-file-size=512000 state=enabled

2.Recycle the IIS Application Pool.

3. Reproduce the issue.

4. Stop the Tracing. From a command prompt run the following command:

netsh winhttp set tracing state=disabled

5. Review the trace with Notepad or any Text editor.

NOTE: The Identity of the IIS application pool will require write access to the log location c:Temp in this example:

This type of tracing is process bitness specific, so if you are looking at a 32 bit process running from 64 bit OS, you need to use: c:windowssyswow64cmd.exe, rather than using the regular 64 bit cmd.exe (start a run a cmd.exe)

Method 2

To get the raw data communication at network layer and the Winhttp  Api calls.

1. Start the tracing: From a command prompt run the following command:

netsh trace start scenario=InternetClient capture=yes report=yes

Note the etl file location for example:

Trace File:         C:UsersAppDataLocalTempNetTracesNetTrace.etl

2.Recycle the IIS Application Pool.

3. Reproduce the issue.

4. Stop the tracing: From a command prompt run the following command:

netsh trace stop

5. Read the Trace by opening it in Netmon 3.4.

Method 3

The ETW format for winhttp API is available on windows 2008 R2 and win7 via the Event Viewer

1.  Open event viewer. Go to “View” menu –> make sure “Show Analytic and debug logs” is checked.

2. Open “Applications and Services logs” — > Open “Microsoft” — > Open “Windows –> Winhttp –> Diagnostic.

3. Highlight “Diagnostic” under Winhttp tree and right click mouse, then click “enable log”.

4.  Reproduce the issue then you can review the logs.

References

Netsh Commands for Network Trace in Windows Server 2008 R2 and Windows 7

http://technet.microsoft.com/en-us/library/dd878517(v=WS.10).aspx

Obtained from this link

8
Feb

502.3 Bad Gateway “The operation timed out” with IIS Application Request Routing (ARR)

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

Obtained from this link

Uso de cookies

Este sitio web utiliza cookies cookies propias y de terceros partes para mejorar la experiencia de usuario. Si continua navegando, consideramos que acepta su uso. Puede obtener más información en nuestra Política de cookies.

ACEPTAR
Aviso de cookies

Última actualización 18/10/2017 20:49