Debugging IIS7 requests with windows event tracing

Previously I wrote about debugging the integrated pipeline with failed request tracing but I’ve also run into problems that occur either too early or too late in IIS to be captured by failed request tracing. These are usually problems that involve the connection between HTTP.sys and the IIS7 application pools (and in my case have been all related to application request routing).

For these types of problems, windows event tracing can show where the request has gone wrong. This is the built-in operating system event tracing that supplies messages to the windows event viewer, turning on logging that is usually off by default.

Using windows event tracing

You turn on the HTTP.sys logging using the logman start command. Then you need to do whatever is needed to generate some request for it to log.

c:\> logman start httptrace -p Microsoft-Windows-HttpService 0xFFFF -o trace-output.etl -ets
The command completed successfully.

After you have finished making requests, you need to turn off the logger. This will create a binary file with all the output, which you can translate into XML (or CSV).

c:\> logman stop httptrace -ets
The command completed successfully.

c:\> tracerpt.exe trace-output.etl -of XML -o trace-output.xml

Input
----------------
File(s):
     trace-output.etl

100.00%

Output
----------------
DumpFile:           trace-output.xml

The command completed successfully.

After you have finished there will be a trace-output.etl and trace-output.xml file in the current directory.

Understanding the output

The file that gets generated is not particularly pretty to look at, but contains lots of information about what happened to your request. I usually search for the path that I entered or the port that my request came in on (if it’s not 80) to skip straight to the right place in the file.

About the third thing that happens is the incoming request is assigned a connectionId. This makes it very convenient to find all the events that happen to your request afterwards because they all contain the connectionId.

  1. <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  2.     <System>
  3.         …
  4.     </System>
  5.     <EventData>
  6.         <Data Name="RequestId">0xF500000080000024</Data>
  7.         <Data Name="ConnectionId">0xF500000060000023</Data>
  8.         <Data Name="ConnectionObj">0xFFFFFA80019BE870</Data>
  9.     </EventData>
  10.     <RenderingInfo Culture="en-GB">
  11.         …
  12.         <Task>HTTP Connection Trace Task </Task>
  13.         <Message>Connection ID (0xF500000060000023) assigned to connection
  14.                           and request (request ID 0xF500000080000024) will be parsed. </Message>
  15.         …
  16.     </RenderingInfo>
  17. </Event>

If you are having problems getting your requests to arrive at an IIS7 application pool, here’s an example of a message logged when the request is passed off to an IIS application pool:

  1. <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  2.     …
  3.     <EventData>
  4.         <Data Name="RequestObj">0xFFFFFA80023AB550</Data>
  5.         <Data Name="RequestId">0xF500000080000024</Data>
  6.         <Data Name="SiteId">       2</Data>
  7.         <Data Name="RequestQueueName">FailedRequestTracingDemo</Data>
  8.         <Data Name="Url">http://localhost:8082/</Data>
  9.         <Data Name="Status">       0</Data>
  10.     </EventData>
  11.     <RenderingInfo Culture="en-GB">
  12.         <Level>Information </Level>
  13.         <Opcode>Deliver </Opcode>
  14.         …
  15.         <Message>Delivered request to server application (request pointer 0xFFFFFA80023AB550,
  16.                           request ID 0xF500000080000024, site ID 2) from request queue FailedRequestTracingDemo
  17.                           for URI http://localhost:8082/ with status 0. </Message>
  18.         <Channel>HTTP Service Channel </Channel>
  19.         <Provider>Microsoft-Windows-HttpService </Provider>
  20.     </RenderingInfo>
  21. </Event>

If your request is going wrong after the app pool has finished with it (and you can tell this by turning on failed request tracing), look for a message like this which says that the response was generated successfully and gives some information about what was sent back to the client:

  1. <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  2.     …
  3.     <EventData>
  4.         <Data Name="RequestId">0xF500000080000024</Data>
  5.     </EventData>
  6.     <RenderingInfo Culture="en-GB">
  7.         <Level>Information </Level>
  8.         <Opcode>FastRespLast </Opcode>
  9.         …
  10.         <Message>Server application passed the last response (corresponding to request ID
  11.                           0xF500000080000024). </Message>
  12.         <Channel>HTTP Service Channel </Channel>
  13.         <Provider>Microsoft-Windows-HttpService </Provider>
  14.     </RenderingInfo>
  15. </Event>
  16. <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  17.  …
  18.  <EventData>
  19.   <Data Name="RequestId">0xF500000080000025</Data>
  20.   <Data Name="ConnectionId">0xF500000060000023</Data>
  21.   <Data Name="StatusCode">304</Data>
  22.   <Data Name="Verb">GET</Data>
  23.   <Data Name="HeaderLength">4294965376</Data>
  24.   <Data Name="EntityChunkCount">0</Data>
  25.   <Data Name="CachePolicy">       0</Data>
  26.  </EventData>
  27.  <RenderingInfo Culture="en-GB">
  28.   <Level>Information </Level>
  29.   <Opcode>FastResp </Opcode>
  30.   …
  31.   <Task>HTTP Request Trace Task </Task>
  32.   <Message>Server application passed response (request ID 0xF500000080000025, connection
  33.                     ID 0xF500000060000023, method GET, header length 4294965376, number of entity
  34.                     chunks 0, cache policy 0) with status code 304. </Message>
  35.   …
  36.  </RenderingInfo>
  37. </Event>

Hopefully this is something that most developers will never need to know because you have to be doing something a bit strange to mess things up at this level, but I’ve found it’s a pretty useful tool to have in my IIS7 debugging toolkit. It’s also appeals to my nerdy nature to be able to take a peek under the covers and see what IIS is actually doing when it processes my request.

Posted on 23 Jul 12 by Helen Emerson (last updated on 15 Jul 12).
Filed under IIS7, Tools