Debugging the IIS7 integrated pipeline with failed request tracing

I spent a fair amount of time in 2011 helping to move websites from IIS6 to IIS7 at work and was delighted to find out that IIS7 has some really nice tools you can use to peer into the matrix when things go wrong.

The one I found most useful was failed request tracing, a tool designed to show what has happened inside the integrated pipeline for a particular request. It logs every event that fires so you can trace the journey of a request and diagnose problems with HTTP modules or HTTP handlers.

The featured is called failed request tracing, but don’t worry, it can trace any request.

Using failed request tracing

Failed request tracing comes with IIS7 but is an optional module that is not installed by default. You can switch it on through the windows component dialog. If its installed you’ll see a failed request tracing rules item in the IIS manager under the website.

Failed request tracing is switched on at the site level in IIS manager. It needs to be turned on in two places. You need to enable it for the site and then set up one or more request filters.

The IIS manager stores the changes in the site’s web.config file in the system.webserver section, so you can also make them directly there. If you do use the IIS manager to configure failed request tracing, make sure you don’t accidentally check in the changes.

  1. <system.webServer>
  2.     <tracing>
  3.         <traceFailedRequests>
  4.             <add path="*">
  5.                 <traceAreas>
  6.                     <add provider="ASPNET"
  7.                              areas="Infrastructure,Module,Page,AppServices"
  8.                              verbosity="Verbose" />
  9.                 </traceAreas>
  10.                 <failureDefinitions statusCodes="200" />
  11.             </add>
  12.         </traceFailedRequests>
  13.     </tracing>
  14. </system.webServer>

Once you have everything set up, you just run your pages and the logs are written to c:\inetpub\logs\FailedReqLogFiles. They are XML with an XSLT that makes them pretty. I found they only really worked in IE.

Once you are done, there’s no problem manually deleting the files you don’t want any more. Just be careful to either delete the whole directory or to leave the XSLT because failed request tracing won’t regenerate the XSLT unless the directory isn’t there any more. If you don’t delete the files, they will eventually be overwritten when IIS hits the limit on the number of files to generate.

Reading the logs

The problem with failed request tracing is that the amount of data it captures feels a bit overwhelming, but there are a few views I’ve found really helpful.

Sometimes the summary view has all the information you need to know. It will tell you who the request was authenticated by, how long it took, what the status code was and which app pool it ran under.

If one of your modules is acting strangely or isn’t kicking in, the module notifications gives a fairly succinct story of which events fired for which modules in which order. If you need more detail, check out the complete request trace.

If your request isn’t being served properly, you might want to know which handler picked it up. The complete request trace in the request details tab shows which handlers were rejected and which ones were tried in the MapRequestHandler phase of the pipline.

If your request is slow, the performance view lists the slowest steps at the top so you can quickly figure out which module is to blame.

Makes the IIS7 integrated pipeline less of a black box

Failed request tracing is an awesomely useful tool. It would have been much harder to figure out what was going wrong in our code designed to run in a classic app pool if we didn’t have this.

It helped us figure out that the Sitecore module was corrupting static files once they’d been gziped by looking at what order the modules inside the pipeline fired in. We found it helpful to confirm that performance problems were outside the application by seeing how long the pipeline took to run. It also helped us figure out we needed to turn on runAllManagedModulesForAllRequests to get postback working for extension free Sitecore urls because we could see the modules just weren’t firing.

Posted on 18 Jul 12 by Helen Emerson (last updated on 15 Jul 12).
Filed under IIS7, Sysadmin, Tools, Web development