Friday, August 17, 2007

Samples: Trace IIS Requests and Responses

I'll be posting a series of samples on Filter.NET covering common uses one would give to an ISAPI Filter. Your comments and suggestions are welcome.

Trace Request

ISAPI filters have a series of events (11 to be exact), and these are all mapped into Filter.NET along with their properties. One such event is the native SF_NOTIFY_PREPROC_HEADERS which maps to the managed PreProcHeaders event.

The PreProcHeaders event is triggered by IIS when the HTTP headers have arrived (IIS reads TCP/IP packets until it sees a double CRLF), and allows an ISAPI Filter to view, change or remove headers. As such, this is an excellent opportunity for an ISAPI to trace the incoming request headers.

During this event, we not only have access to all request headers sent, but we also have access to the
server variables which IIS makes available containing much more useful information. ALL_RAW is one of them, with all headers sent in the request.

I think its time we give it a try then:




using System;
using System.Diagnostics;
using KodeIT.Web;

namespace FilterDotNet.Samples
{
class TraceRequest : IHttpFilter
{
void IHttpFilter.Init(IFilterEvents events)
{
events.PreProcHeaders += new EventHandler(OnPreProcHeaders);
}

void OnPreProcHeaders(object sender, PreProcHeadersEventArgs e)
{
RequestHeadersEvent context = e.Context;
string requestHeaders = String.Format("{0} {1} {2}\r\n{3}",
context.Method,
context.Url,
context.Version,
context.ServerVariables[ServerVariable.ALL_RAW]);

Trace.WriteLine(requestHeaders);
}

void IHttpFilter.Dispose() { }
}
}



Looks simple, right?

To install the sample, just register the assembly on Filter.NET configuration file - KodeIT.Web.dll.config - reset IIS and you're done. Open up
DebugView from Microsoft (formerly SysInternals), make a request to IIS and watch ...

Trace Response

No, I didn't forget about the http response :) Neither did IIS, and thats why there is an event useful for just that, to retrieve the full http response sent by IIS. The native event is SF_NOTIFY_SEND_RAW_DATA and the managed event is SendRawData.

When this event is triggered, IIS presents us with an array of bytes that will be sent to the client, and we can view and change those bytes. Right now, we're just interested in viewing them, so lets do exactly that:



using System;
using System.Diagnostics;
using System.Text;
using KodeIT.Web;

namespace FilterDotNet.Samples
{
class TraceResponse : IHttpFilter
{
void IHttpFilter.Init(IFilterEvents events)
{
events.SendRawData += new EventHandler(OnSendRawData);
}

void OnSendRawData(object sender, RawDataEventArgs e)
{
Trace.WriteLine(ASCIIEncoding.ASCII.GetString(e.Context.GetData()));
}

void IHttpFilter.Dispose() { }
}
}



This can also be part of the first managed filter instead of being a separate one. Again, compile it, register it, open DebugView, make a request to IIS and watch the responses sent by IIS.

3 comments:

Perry Way said...

Hi Tiago,

Thank you so much for this fine example of how to wrap the C++ ISAPI and port to C#.

Recently at my work we were confronted with the need to track the bandwidth used by domain over a period of time. I was about to create an ISAPI filter in C++ or Delphi but one of my coworkers mentioned he thought one could write a filter in C#, to which I retorted "No you can't!" and technically I am right. However, with your wrapper, one can "hook up" C# to your generic wrapper, which is really cool. It took me a while to find this place by Googling every word combination I could think of.

Anyhow, so with that background out of the way, I've downloaded and installed your filter and have created my own class library to hook up to it. Inside my class library I am utilizing a threaded class to serve as a period pulse that will then store the accumulated request/response size along with the domain name. This part works wonderfully with one day of debugging and heavy testing.

However, I've noticed one problem which seems to be an inherent problem internal to Dot Net, or perhaps the OS even. This problem occurs upon boot-up of Windows. When the IIS service starts it will have a severe error that pops up a notification when one logs onto the machine quickly. If one waits to log in later, it crashes IIS.

I've done some extensive testing on this and have pretty much focused the problem to a reference of System.Threading.Thread class. I have tested including and not including all the other componentry involved in this filter. I had originally thought that the problem might be ADO.Net since references to SQL Server were made within the thread. But no, it's not the database end of things at all.

Now mind you, this is merely a reference being made. I have tested this extensively. If you don't start the thread, but it's been referenced, then it throws this fatal exception to IIS. And like I said, if you happen to be there to respond to it interactively, then the popup happens and if you click on a button reasonably quick, then nothing bad happens to IIS. If you wait.. IIS crashes. Interestingly enough, the filter still works though. Every part of it works.

Now, if you cycle IIS interactively after you have booted up safely, then the filter works fine! There is not one single error! It is only upon bootup that the error occurs.

Anyhow I am curious if you've encountered something similar to this. For the moment I am pausing to reconsider coding the filter we need using C++, because this filter needs to be threaded for a variety of reasons. I do not want to make database calls within the context of the filter's thread, for good reasons as I'm sure you can imagine. I also don't want to block subsequent requests being made because I'm busy logging some data periodically. So the thread is vitally important for this task.

Do you have any thoughts on this matter? I am curious what you think...

Once again, thanks for being so open with your work to let the world have a go at it. You write very nice code and I like your naming conventions. We think alike there....

Perry

Tiago Halm said...

Perry,

Thanks so much, its quite conforting to hear compliments like those.

As for the issue you're seeing, its strange you find this issue on boot up, since IIS itself (I mean the AppPools, not HTTP.sys) only start upon receiving the first HTTP request handled by HTTP.sys - the kernel driver listening for requests.

Next steps would be to examine the event log (Application and System) for the Warnings and Errors related to IIS. Also, look into HTTPERR (should be in %SYSTEMROOT%\system32\LogFiles\HTTPERR). Other things to do would be to setup Network Monitor to start listening on boot to examine the requests you're getting before and after the crash.

My suspicion is that you're getting a request that crashes the filter. If this is the cause its not related to Windows boot up, and it can happen at any time, as long as its the first request.

Anyhow, try to reproduce the issue without the "boot up", I believe its not related to that.

If you can follow up the discussion on codeplex (http://www.codeplex.com/filterdotnet) it would be great because others can probably fill in some details.

thanks again for the comment!

Tiago Halm

Perry Way said...

Hi Tiago, I just now noticed you replied, 6 days later hehe. Because of other factors, my project is on hold for a few weeks but I will go to the codeplex site to carry on this discussion. Thanks! Perry