Jaa

Event Tracing in Http.sys: Part 3 - Typical Request

  • Artikkeli

Now that you are somewhat familiar with a single ETW event, let’s illustrate what a typical HTTP request looks like. Here, I’ve made a simple HTTP request to a web server, IIS7 in this case.

I’ve taken the liberty of pulling out all important data from the XML file.  You may notice that I've placed all the Data in the same cell for each event, this is simply to save space in this web format.

Event Name Data
ConnConnect

ConnectionObj=0x840C9008LocalAddr=[::1]:80RemoteAddr=[::1]:50438
ConnIdAssgn

RequestId=0xFB00000080000004ConnectionId=0xFB00000060000003ConnectionObj=0x840C9008
RecvReq

RequestId=0xFB00000080000004ConnectionId=0xFB00000060000003RemoteAddr=[::1]:50438
Parse

RequestObj=0x840D8A38HttpVerb=4Url=https://localhost:80/
Deliver

RequestObj=0x840D8A38RequestID=0xFB00000080000004RequestQueueName=DefaultAppPoolUrl=https://localhost:80/
FastResp

RequestId=0xFB00000080000004ConnectionId=0xFB00000060000003StatusCode=200Verb=GETEntityChunkCount=0CachePolicy=0
FastSend

RequestId=0xFB00000080000004HttpStatus=200
ConnCleanup

ConnectionObj=0x840C9008

 

The first part of almost any Http.sys event trace are a series of events that shows we’ve received a request:

  • ConnConnect - The first Http.sys event one will see is ConnConnect. This signals that a new connection has been initiated by a client. We log the memory address of the ConnectionObj here, the Local Address and port that received the request as well as the Remote Address, where the HTTP request originated. Here you can see that I’ve sent a request from localhost:Port 50438 to localhost:Port 80.
  • ConnIdAssgn – Http.sys will next assign a ConnectionId and a RequestId to the new incoming connection/request. We assign both these identifiers because a connection could have multiple HTTP requests associated with it. Notice that the ConnectionObj is the same for the first two events indicating that we are dealing with one connection.
  • RecvReq – This event asserts that’s we received the request and are about to parse it.

The rest of the trace can be interpreted as follows.

  • Parse – After Http.sys parses a request, we log the Parse event. With it comes the memory address of the HTTP_REQUEST object, the requested URL and the HTTP Verb. Here we are logging the enum value of the verb from our HTTP_VERB enum located in our public header file http.h.
  • Deliver – When the user mode application calls HttpReceiveHttpRequest() we hand them the parsed request (in the for of an HTTP_REQUEST structure) and log this event. Along with the RequestObject and RequestId, we also log the Url and the name of the RequestQueue where we’ve delivered the request. For IIS, their default queue is named “DefaultAppPool”.
  • FastResp – The FastResp event means the server application, in this case it’s IIS, has passed the given data to Http.sys for delivery (with HttpSendHttpResponse()). Here the application is responding to the request with requestId=0xFB00000080000004 on Connection with Id 0xFB00000060000003 with the Verb being GET. IIS is responding with status code 200, is not caching the send and is sending no entity chunks.
  • FastSend – Http.sys has queued the response, status 200, for the given requestId for sending
  • ConnCleanup – Cleanup has begun for the given request object. This is a result of a TCP Reset or mutual TCP Fins.

In the next ETW posts, we will discuss diagnosing typical Http.sys problems using Event Tracing.

-Jeff Balsley