Event Tracing in HTTP.sys: Part 2 - Anatomy of an Event

Continuing the series on Http.sys ETW Tracing, we will dissect an event as displayed in the default XML format. To review creating an ETW trace, see Capturing a Trace

Pictured is an example of a typical event in a trace. Note how the event is wrapped in an <Event> element. This particular event happens to be our Parse event:

 <Event xmlns="https://schemas.microsoft.com/win/2004/08/events/event">
   <System>
      <Provider Name="Microsoft-Windows-HttpService" Guid="{dd5ef90a-6398-47a4-ad34-4dcecdef795f}" />
      <EventID>2</EventID>
      <Version>0</Version>
      <Level>4</Level>
      <Task>1</Task>
      <Opcode>12</Opcode>
      <Keywords>0x8000000000000002</Keywords>
      <TimeCreated SystemTime="2006-09-06T16:59:22.251258100Z" />
      <Correlation ActivityID="{80000002-0001-fb00-0000-000000000000}" />
      <Execution ProcessID="4" ThreadID="1276" ProcessorID="1" KernelTime="15" UserTime="0" />
      <Channel>Microsoft-Windows-HttpService/Trace</Channel>
      <Computer />
   </System>
   <EventData>
      <Data Name="RequestObj">0xFFFFFA8001BB5320</Data>
      <Data Name="HttpVerb">4</Data>
      <Data Name="Url">https://localhost:80/RequestQueueTests/</Data>
   </EventData>
   <RenderingInfo Culture="en-US">
      <Level>Information </Level>
      <Opcode>Parse </Opcode>
      <Keywords>
         <Keyword>Flagged on all HTTP events dealing with request processing </Keyword>
      </Keywords>
      <Task>HTTP Request Trace Task </Task>
      <Message>Parsed request (request pointer 0xFFFFFA8001BB5320, method 4) with URI https://localhost:80/. </Message>
      <Channel>HTTP Service Channel </Channel>
      <Provider>Microsoft-Windows-HttpService </Provider>
   </RenderingInfo>
</Event> 

The <event> node has three sub-nodes, <System>, <EventData>, and <RenderingInfo>. Each contains specific data. The <System> node holds information such as the name of the traced component and the event time stamp. The <EventData> node holds information specific to the event. The Http.sys dev decides what information should be logged for each of our events. The <RenderingInfo> node holds much of the same information as the <System> node, but in a more readable form. Also, this node holds the <Message> sub-node, which describes the event. Below is complete description of the elements contained under each sub-node.

The System node

• Provider: This contains the name and the Guid of the component responsible for the event.
• EventID: Each event has a unique EventID associated with it. In the case of Http.sys, we have 65 unique events.
• Version: Beyond scope of this post.
• Level: This is the verbosity level of the event. Each event has a verbosity level, LogAlways, Critical, Error, Warning, Informational, and Verbose numbered from 0 to 5 respectively. I generally trace with the highest verbosity level to collect the maximum amount of data.
• Task: Beyond scope of this post.
• Opcode: A numeric value representing the name of the particular event, short for “Operational Code”.
• Keywords: Keywords are tags attached to events in order to group various events based on their use.
• TimeCreated: This is the timestamp of the event. It includes the data in YYYY-MM-DD format and the time in HH:MM:SS.SSSSSSSSS format.
• Correlation: This includes the ActivityID for the request.
• Execution: Beyond scope of this post.
• Channel: Again, this is the name of the trace provider.
• Computer: Beyond scope of this post.

The EventData node

• Data: Each request has it’s own unique data. Typically, a data node includes the name of the data (show as the value of the Name attribute) and the data itself.

The RenderingInfo node

• Level: Like the Level element under the <System> node, this is the verbosity of the event. However, instead of the numeric level, this gives the name of the level, such as Error or Informational.
• Opcode: This is the same Opcode as above, only not rendered in it’s numeric form. Here it is displayed via the friendly name of the event. Hereafter, I will refer to the opcode as the “EventName”.
• Keywords: Keywords are used to group events into groups.
• Task: NA.
• Message: This is a friendly, more readable message describing the event.
• Channel: Beyond scope of this post.
• Provider: This is the name of the provider.

I know this amount of information appears overwhelming, especially considering a typical trace can have hundreds or even thousands of events and be several megabytes in size. Consequently, when using ETW, I “cherry-pick” a few bits of information from the XML file:

The event name, or opcode element, under the <RenderingInfo> node and all the Data elements under the <EvenData> node.

When sorted in a table format it’s easy to follow one event to another. We’ll go over the best ways to do this (using a script, xslt, etc...) in a separate post.

In the next ETW post, I’ll go over an ETW trace for a typical HTTP transaction with multiple events.

-Jeff Balsley