IIS - Troubleshooting using logs

23 März 2015

When having any problems with IIS web sites or application, the various logs can be very helpful. Lets look at all them.

The IIS logs

by default these are per site per day under C:\inetpub\logs\LogFiles\WSVCx where x is the ID of the site.

ls iis:\sites

shows you all sites with their IDs. By default the logs are only accessible to elevated administrators.

In many cases the most important information for troubleshooting is at the end of the row, if you keep the default fields, the two numbers after the last dash show the http status (such as 200 or 404) and next to it the substatus which shows an IIS-specific status and gives more details about the request.

 ...Gecko/20100101+Firefox/35.0 - 404 0 2 62
 ...Gecko/20100101+Firefox/35.0 - 200 0 0 687
 ...Gecko/20100101+Firefox/35.0 - 500 19 0 251

For a list of these substatus codes check this KB article

There are actually some substatus codes that IIS uses that are not listed in that article:

 401.503 - (IP address rejected) Unauthorized
 403.503 - (IP address rejected) Forbidden
 404.503 - (IP address rejected) NotFound
 500.20  - Server error: URL authorization scope cannot be found.
 500.21  - Internal Server Error Handler "ScriptHandlerFactory" has a bad module "ManagedPipelineHandler" in its module list
 500.22  - An ASP.NET setting has been detected that does not apply in Integrated managed pipeline mode.
 500.23  - An ASP.NET setting has been detected that does not apply in Integrated managed pipeline mode.

These logs are written by the kernel-mode part of IIS http.sys, they are not written continuously but buffered for a while and then flushed to the files.

Sometimes the files have a size of 0 bytes suggesting they are empty, but they may not, as long as they are open for writing, Windows doesn't always update the file size. So just check them anyways.

If the entries you expect are not there yet, they may still be buffered, to write the buffer to the files issue the following command as an elevated admin:

netsh http flush logbuffer

I wrote a small script to quickly review these logs:

Quick way to query IIS logs for 40x and 50x requests

HTTPERR log

The entries in the IIS log are all coming from the user-mode part of IIS, usually the working processes handling the sites. Sometimes there are requests that never make it into the user-mode and are already handled by http.sys

These logs are in %SystemRoot%\System32\LogFiles\HTTPERR and may have some clues.

Some explanation about possible errors can be found in this KB article

Failed Request Trace log

The failed request tracing is a wonderful feature in IIS which gives us a lot of inside into a request.

First check whether this feature is enabled:

Get-WindowsOptionalFeature -Online | Where {$_.FeatureName -match "IIS-HttpTracing"}

if disabled, enable it:

Enable-WindowsOptionalFeature -Online -FeatureName IIS-HttpTracing

Next you have to enable it for the site in question:

Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST'  -filter "system.applicationHost/sites/site[@name='SiteName']/traceFailedRequestsLogging" -name "enabled" -value "True"

now, you have to configure it to trace certain requests. Say you are interested in the ASP.NET pages that create a 500 error:

Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests" -name "." -value @{path='*.aspx'}
Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*.aspx']/traceAreas" -name "." -value @{provider='ASPNET';areas='Infrastructure,Module,Page,AppServices';verbosity='Verbose'}
Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*.aspx']/failureDefinitions" -name "statusCodes" -value "500-503"

or turn on tracing for all request (don't use on production servers)

Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests" -name "." -value @{path='*'}
Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*']/traceAreas" -name "." -value @{provider='ASP';verbosity='Verbose'}
Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*']/traceAreas" -name "." -value @{provider='ASPNET';areas='Infrastructure,Module,Page,AppServices';verbosity='Verbose'}
Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*']/traceAreas" -name "." -value @{provider='ISAPI Extension';verbosity='Verbose'}
Add-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*']/traceAreas" -name "." -value @{provider='WWW Server';areas='Authentication,Security,Filter,StaticFile,CGI,Compression,Cache,RequestNotifications,Module,FastCGI,WebSocket';verbosity='Verbose'}
Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST/SiteName'  -filter "system.webServer/tracing/traceFailedRequests/add[@path='*']/failureDefinitions" -name "statusCodes" -value "200-503"

Note these PowerShell commands depend on certain modules installed, you should just take them as an example. As usually you can also set all this through the GUI.

After setup and hitting the page in question, you will find a bunch of files in %SystemDrive%\inetpub\logs\FailedReqLogFiles\W3SVCx, copy those files onto your workstation because you shouldn't use IE on the server.

Click on the *.xml files to review the various requests.

When done, turn it back off:

Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST'  -filter "system.applicationHost/sites/site[@name='SiteName']/traceFailedRequestsLogging" -name "enabled" -value "False"

The Windows event log

The windows event log is always a good place to look at if something goes wrong.

Your application framework such as ASP or ASP.NET log warnings and errors into the old Windows Application log.

In your application pool advanced settings Recycling - Generate Recycle Event Log Entry you can specify when to create events for AppPool recycling. These events are also in the Application Event Log with the source WAS

Http.sys trace

To get more inside into the http.sys process, you can enable tracing, again be very careful doing this on a production machine.

To start the trace, run:

logman.exe start httptrace -p Microsoft-Windows-HttpService 0xFFF -o httptrace.etl -ets

Perform some requests you want to investigate, then stop the trace:

logman.exe stop httptrace -ets

convert into a csv file:

tracerpt httptrace.etl -of csv -o httptrace.csv /y

or maybe better into a event log file which you can open in Event Viewer:

tracerpt httptrace.etl -of evtx -o httptrace.evtx /y

Realtime IIS logs

If you have IIS 8.5 or higher (Server 2012 R2, Windows 8.1, Windows 10) you have an option to look at the IIS traffic in nearly real-time.

Enable Event Tracing for Windows (ETW) for your site:

Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST'  -filter "system.applicationHost/sites/site[@name='SiteName']/logFile" -name "logTargetW3C" -value "File,ETW"

to turn ETW logging back off:

Set-WebConfigurationProperty -pspath 'MACHINE/WEBROOT/APPHOST'  -filter "system.applicationHost/sites/site[@name='SiteName']/logFile" -name "logTargetW3C" -value "File"

To view the ETW data you can use Microsoft Message Analyzer, which you can download here, install it on your workstation not your server.

Start a New Session, use Live Trace as the Data source. Select the target server and provide credentials to connect. In the ETW Providers section add a new provider Microsoft-Windows-IIS-Logging and start the session.

Now within seconds you should see any requests to your site. The interesting information is in the Summary column.

You may have to configure WinRM to get remote sessions to work.

Health Monitoring for ASP.NET

If you have many unexpected Application Domain restarts for your asp.net site, you can enable health monitor to write additional events to the Windows Application log.

Open your root web.config file such as

%systemroot%\Microsoft.NET\Framework64\v4.0.30319\Config\web.config 

Find the <system.web><healthMonitoring><rules> node and add the following node below:

<add name="Application Lifetime Events Default" eventName="Application Lifetime Events"
    provider="EventLogProvider" profile="Default" minInstances="1"
    maxLimit="Infinite" minInterval="00:01:00" custom="" />

Now you should see ASP.NET Web Events in your Windows Application log. They may tell you why your application domain was restarted.

ApplicationShutdownReason Enumeration

ASP.NET Case Study: Lost session variables and appdomain recycles
Using ASP.NET Health Monitoring Events

Advanced Logging Extension

Advanced Logging is an extension provided by Microsoft and allows you to create a secondary log file for requests with additional fields not available in the normal logs (even though in IIS 8.5+ you can add custom fields) you can also configure which requests to log rather than filter them later.

Unless you need to know certain http headers and/or server variables, I don't think Avanced logging is very useful for troubleshooting.

Tags: IIS | IT Pro | Tools


Pages in this section

Categories

ASP.Net | Community | Development | IIS | IT Pro | Security | SQL (Server) | Tools | Web | Work on the road | Windows