A bad ISAPI Filter and ETW traces
My previous post talked about creating a simple ISAPI filter. Now let’s create some nuisance J We want to make this ISAPI a bad one. Then we will start ETW tracing and figure out how to isolate the things which are real *bad*. We know that this Filter will cause issues, but how do you figure out still remains to be seen!
PS: Do NOT try this on a production environment. I cannot guarantee the working of this code. And, try this at your own risk J
<Code Example>
#include <stdio.h>
#include <stdlib.h>
#include <afx.h>
#include <afxisapi.h>
BOOL WINAPI __stdcall GetFilterVersion(HTTP_FILTER_VERSION *pVer)
{
/* Specify the types and order of notification */
pVer->dwFlags = (SF_NOTIFY_PREPROC_HEADERS | SF_NOTIFY_AUTHENTICATION |
SF_NOTIFY_URL_MAP | SF_NOTIFY_SEND_RAW_DATA | SF_NOTIFY_LOG | SF_NOTIFY_END_OF_NET_SESSION );
pVer->dwFilterVersion = HTTP_FILTER_REVISION;
strcpy(pVer->lpszFilterDesc, "A BAD ISAPI Filter");
CFile myFile("G:\\mylist.html", CFile::modeCreate | CFile::modeWrite);
myFile.SeekToEnd();
char myText[40];
strcpy(myText,"<B>GetFilterVersion </B><BR><BR>");
myFile.Write(myText,strlen(myText));
myFile.Close();
return TRUE;
}
DWORD WINAPI __stdcall HttpFilterProc(HTTP_FILTER_CONTEXT *pfc, DWORD NotificationType, VOID *pvData)
{
int i;
CFile myFile("G:\\mylist.html", CFile::modeWrite);
myFile.SeekToEnd();
myFile.Write("This is a bad Filter ",strlen("This is a bad Filter "));
myFile.Close();
return SF_STATUS_REQ_NEXT_NOTIFICATION;
}
</Code Example>
This code is supposed to induce some delay as you could see! Build the solution and configure the ISAPI DLL on any website on your IIS Server. And let’s take an ETW trace to find out what exactly is going on behind the scenes.
To take an ETW trace follow the steps mentioned below:
{1fbecc45-c060-4e7c-8a0e-0dbd6116181b} 0 5 IIS: SSL Filter
{3a2a4e84-4c21-4981-ae10-3fda0d9b0f83} 0xFFFFFFFE 5 IIS: WWW Server
{06b94d9a-b15e-456e-a4ef-37c984a2cb4b} 0 5 IIS: Active Server Pages (ASP)
{dd5ef90a-6398-47a4-ad34-4dcecdef795f} 0 5 Universal Listener Trace
{a1c2040e-8840-4c31-ba11-9871031a19ea} 0 5 IIS: WWW ISAPI Extension
{d55d3bc9-cba9-44df-827e-132d3a4596c2} 0 5 IIS: WWW Global
{3b7b0b4b-4b01-44b4-a95e-3c755719aebf} 0 5 IIS: Request Monitor
{DC1271C2-A0AF-400f-850C-4E42FE16BE1C} 0 5 IIS: IISADMIN Global
{AFF081FE-0247-4275-9C4E-021F3DC1DA35} 0 5 ASP.NET Events
{C92CF544-91B3-4dc0-8E11-C580339A0BF8} 0 5 NTLM Security Protocol
{dd5ef90a-6398-47a4-ad34-4dcecdef795f} 0 5 HTTP Service Trace
{f33959b4-dbec-11d2-895b-00c04f79ab69} 0 5 Active Directory: NetLogon
{bba3add2-c229-4cdb-ae2b-57eb6966b0c4} 0 5 Active Directory: Kerberos
1. Copy the above text to a notepad and save it as iistrace.guid.
2. Now open up a command prompt and change directory to the folder where you have stored iistrace.guid file.
3. Type “logman start iistrace_etl -pf iistrace.guid -ets” (without the quotes) and press Enter.
NOTE: You must type the above command, as opposed to copy-pasting from this page.
4. Browse to any of the page in the website where you have put our ISAPI Filter.
- Type “logman stop iistrace_etl -ets” (without the quotes) to stop tracing.
NOTE: You must type the above command, as opposed to copy-pasting from this page.
- At this point, we should have an iistrace_etl.etl file in that folder.
iistrace_etl.etl is the ETW trace file. You can use Log Parser to convert to a TEXT file.
C:\Program Files\IIS Resources\Log Parser 2.2\Samples\Scripts> cscript.exe DumpTraceReqs.js iistrace_etl.etl > MyTrace.txt
Open the MyTrace.txt in a Notepad and review the ETW trace.
Here is the ETW trace taken in my machine for the execution of a simple time.asp page on a website which has our BAD ISAPI Filter.
IISFilter: FILTER_START - W3 filter starts
FilterName: G:\BAD_ISAPI\BadISAPI\debug\BadISAPI.dll
ContextIDSeq: 1
Timestamp: 23:58:50.680.227300
IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS notification
ContextIDSeq: 1
Timestamp: 23:58:50.680.227300
IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS notification
ContextIDSeq: 1
Timestamp: 23:59:50.868.882900
IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 1
Timestamp: 23:59:50.868.882900
Note the difference in the time taken field between the two steps. It is more than 1 minute!! And, the time taken field in IIS logs showed me 300490!
Now, let’s change the loop count to be 500000 and see the time difference!! Yeah, you want to rebuild the DLL.
IISFilter: FILTER_START - W3 filter starts
FilterName: G:\BAD_ISAPI\BadISAPI\debug\BadISAPI.dll
ContextIDSeq: 1
Timestamp: 00:18:02.655.469800
IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS notification
ContextIDSeq: 1
Timestamp: 00:18:02.655.469800
IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS notification
ContextIDSeq: 1
Timestamp: 00:20:48.939.912400
IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 1
Timestamp: 00:20:48.939.912400
The difference now have become nearly 2.5 minutes!! And IIS logs showed me 819718. Yeah, this is really a BAD ISAPI.
Useful Links
MSDN : Event Notifications
https://msdn2.microsoft.com/fr-fr/library/ms812625.aspx
MSDN : Creating ISPAI Filters
https://msdn2.microsoft.com/en-us/library/ms525164.aspx
MSDN : Modifying Response Headers using ISAPI Filters