Tracing in IIS 6.0 and Windows Server 2003 SP 1

Wednesday, November 15, 2006

On Thursday, July 14th, 2005 I admittingly hurried together a presentation termed “IIS 6.0 Tracing: Inside and Out.” However, I had everything put together just right to hit a home run in this webcast until “production” came about. No one out there ever runs into problems only in production do they…?

I did, and it was a crash and burn, but my friendly attendees for the webcast didn’t damage me to bad on my survey. I do owe them an apology for certain —

Tracing in Service Pack 1 was greatly extended versus that which was included on RTM of Windows 2K3 and IIS 6.0. It is a little known fact that if users of IIS 6.0 start to play with tracing, they will quickly fall in love with the data it provides.

I was going to demo the following -

Looking at a IIS 6.0 Trace Log (to learn how to read)
Run the IISReqMon provider and capture the currently executing requests when stressing the web server using Web Capacity tool (WCat)
Install a filter into IIS that re-maps a URL request for /default.htm to /home/index.html but have faulty ACLs on the index.htm. This would be tough to follow as you would think the 401.3 was occurring on default.htm but the ACLs look good. Not when using tracing…
Filter down the data file to only trace a specific file, in this case, default.aspx (using the TraceURIPrefix metabase property)
All was well until I couldn’t get the analysis tools to comb the data. I could certainly get the data in the ETL trace logs but I couldn’t finish the job by showing where in the log file the problem occurred. This doesn’t help customers too much have confidence that it (tracing) really works — trust me, it does!

For some technical details, here is the steps I took on demo 2 -

I downloaded Trace Diagnostics 1.0
I installed Trace Diagnostics 1.0 using tracediag.msi which includes options to install IISTrace.exe and IISReqMon.exe
I then moved IISReqMon to the folder where I wanted the ETL (tracing log file) created
I started my stress application which would make calls to default.aspx for 30 seconds
I issued IISREQMON /a “DefaultAppPool”
This should work as IISREQMON automates the setting up of the IISREQMON provider.

NOTE:

You could also do this yourself using LogMan - logman.exe start IISRequests -p “IIS: Request Monitor” -ets

Either way, I ended up flopping with no data. This should work according to the documentation and the testing I did after the presentation with IISREQMON.

Ahh…the trial and tribulations of being front and center.

The 2nd demo used a C++ filter that woudl re-map URL requests that matched a string in a .ini file located in the Windows directory.

// ReMap.c -> Sample ISAPI filter to remap requested URL's
// Wade A. Hilmo, March 1997

#define _WIN32_WINNT 0x0400

#include <windows.h>
#include <httpfilt.h>

BOOL WINAPI GetFilterVersion(PHTTP_FILTER_VERSION pVer)
{
pVer->dwFilterVersion = HTTP_FILTER_REVISION;
lstrcpy(pVer->lpszFilterDesc, "ReMap ISAPI Filter Sample");
pVer->dwFlags = SF_NOTIFY_ORDER_DEFAULT | SF_NOTIFY_PREPROC_HEADERS;

return TRUE;
}

DWORD WINAPI HttpFilterProc(PHTTP_FILTER_CONTEXT pfc, DWORD NotificationType, LPVOID pvNotification)
{

PHTTP_FILTER_PREPROC_HEADERS pHeaders = pvNotification;
char szRequestedUrl[MAX_PATH], szMappedUrl[MAX_PATH], *szQueryString;
DWORD dwBuffSize;

// Get Requested URL
dwBuffSize = MAX_PATH;
pHeaders->GetHeader(pfc, "url", szRequestedUrl, &dwBuffSize);

// Trim and save query string if present
szQueryString = strchr(szRequestedUrl, '?');
if (szQueryString)
{
*szQueryString = 0;
szQueryString++;
}

// Check for mapping
GetPrivateProfileString("URL Mappings", szRequestedUrl, "", szMappedUrl, MAX_PATH, "ReMap.ini");
if (!lstrlen(szMappedUrl)) // Mapping not found - do not process further
return SF_STATUS_REQ_NEXT_NOTIFICATION;

// If we have a query string, append it to the mapped URL
if (szQueryString)
{
lstrcat(szMappedUrl, "?");
lstrcat(szMappedUrl, szQueryString);
}

// If remap specifies protocol, use 302 status code and send new url
// in a Location header.
if (!strnicmp(szMappedUrl, "http://", 7))
{
char szStatus[1024], szLocation[MAX_PATH + 32];

wsprintf(szStatus, "302 Object Moved");
wsprintf(szLocation, "Location: %s\r\n\r\n", szMappedUrl);
dwBuffSize = lstrlen(szStatus);
pfc->AddResponseHeaders(pfc, szLocation, 0);
pfc->ServerSupportFunction(pfc, SF_REQ_SEND_RESPONSE_HEADER, szStatus, (DWORD)&dwBuffSize, 0);

return SF_STATUS_REQ_FINISHED;
}

// Update URL header - this effectively redirects a request on the local machine
pHeaders->SetHeader(pfc, "url", szMappedUrl);

return SF_STATUS_REQ_NEXT_NOTIFICATION;
}

After setting up this filter, I edited the .ini file in the Windows directory called “remap.ini” with this -

[URL Mappings]
/default.htm=/home/index.html

Off to the races I went… I made sure that my “currently logged on user” would have deny access to the index.html file. This is not a “realistic” scenario, but it is close enough to one that represents a random Windows user not having the privaleges necessary to access the file. The demo was set and rocking…

I started the demo by doing a WCat script that would hit /default.htm. This would just create a lot of data and simulate what “looked” like a real ETL log file. Little did I know…

After creating the stress application and loading it, I started the tracing -

logman.exe start AuthZFailure -pf MyAuthZProviderTrace.etl -ets

In my provider file, I was setting the following to make sure I captured all data for requests to the server -

“IIS: WWW Server” 0xFFFFFFE 5

This meant get all functional areas for WWW Server (0xFFFFFFE means all) and do a verbosity of 5. This should produce a ETL file called AuthZFailure.etl in my current directory. Using a sample script from Log Parser 2.2 (part of the IIS Diagnostics Toolkit), I formatted the file to readable text that aligned requests based on request id. Well…I thought I did. It turns out that the file was so large that DumpTraceReq.js couldn’t parse it correctly. I was sad…

It should have shown a file like this -

Request n.1: http://remap:80/default.htm {00000000-0000-0000-0977-0060000000fc} 2005-6-14 21:8:17

IISGeneral: GENERAL_REQUEST_START - IIS starts processing a new request
    SiteId: 1747269497
    AppPoolId: DefaultAppPool
    ConnId: 1073772296
    RawConnId: 0
    RequestURL: http://remap:80/default.htm
    RequestVerb: GET
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_START - W3 filter starts
    FilterName: D:\WINDOWS\Microsoft.NET\Framework\v1.1.4322\aspnet_filter.dll
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS notification
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS notification
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_END - W3 filter ends
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_START - W3 filter starts
    FilterName: D:\websites\site3\ReMap.dll    [ChrisAd] Filter is loaded
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS notification
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
    HeaderName: url
    HeaderValue: /home/index.html              [Chrisad} Filter changes the URL to index.html
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS notification
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_END - W3 filter ends
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get metadata
    RequestURL: /home/index.html
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
    PhysicalPath: d:\websites\site3\home\index.html
    AccessPerms: Read+Script
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
    PhysicalPath: d:\websites\site3\home\index.html
    ErrorCode: 0x00000000
    URLInfoFromCache: 0
    URLInfoAddedToCache: 0
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_START - W3 filter starts
    FilterName: D:\WINDOWS\Microsoft.NET\Framework\v1.1.4322\aspnet_filter.dll
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_URL_MAP_START - IIS starts URL_MAP notification
    AccessPerms: 0x00000201
    MatchingPath: 17
    MatchingURL: 0
    ScriptMapEntry:
    OrigURL: /home/index.html
    OrigPath: d:\websites\site3\home\index.html
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_URL_MAP_END - IIS ends URL_MAP notification
    AccessPerms: 0x00000201
    FinalURL: /home/index.html
    FinalPath: d:\websites\site3\home\index.html
    MatchingPath: 17
    MatchingURL: 0
    ScriptMapEntry:
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISFilter: FILTER_END - W3 filter ends
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISAuthentication: AUTH_START - IIS authentication starts
    AuthTypeSupported: Anonymous+NT
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISAuthentication: AUTH_REQUEST_AUTH_TYPE - Authentication type in the request
    RequestAuthType: Anonymous
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISAuthentication: AUTH_SUCCEEDED - IIS authentication succeeds
    NTLMUsed: 0
    AuthType: Anonymous
    RemoteUserName:
    AuthUserName:
    TokenImpersonationLevel: 0x00000002
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISAuthentication: AUTH_END - IIS authentication ends
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISGeneral: GENERAL_STATIC_FILE_HANDLER - IIS processes a static file request
    FileName: d:\websites\site3\home\index.html
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
    FileName: d:\websites\site3\home\index.html
    UserName: IUSR_DEMO-2K3
    DomainName: DEMO-2K3
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
    ErrorCode: 0x80070005
    Successful: 0
    FileFromCache: 0
    FileAddedToCache: 0
    FileDirmoned: 1
    LastModCheckErrorIgnored: 0
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISSecurity: SECURITY_FILE_ACCESS_DENIED - File access is denied
    FileName: d:\websites\site3\home\index.html
    DomainName: DEMO-2K3
    AccountName: IUSR_DEMO-2K3                [ChrisAd] IUSR was denied access to this file
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISGeneral: GENERAL_SEND_CUSTOM_ERROR - IIS sends back a custom error
    HttpStatus: 401
    HttpSubStatus: 3
    FileNameOrURL: D:\WINDOWS\help\iisHelp\common\401-3.htm
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
    FileName: D:\WINDOWS\help\iisHelp\common\401-3.htm
    UserName:
    DomainName:
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
    ErrorCode: 0x00000000
    Successful: 1
    FileFromCache: 0
    FileAddedToCache: 0
    FileDirmoned: 1
    LastModCheckErrorIgnored: 0
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS cacheable
    HttpsysCacheable: 0
    Reason: URL_CHANGE_BY_FILTER
    ContextIDSeq: 1
    Timestamp: 21:08:17.875.000000

IISGeneral: GENERAL_REQUEST_END - IIS ends processing a request
    HttpStatus: 401
    HttpSubStatus: 3
    BytesSent: 1824
    BytesReceived: 236
    ContextIDSeq: 1
    Timestamp: 21:08:17.890.625000

Total time: 0 msecs

Using information in this file, I could successfully track down the actual access denied. This would be an ACL for IUSR (name given) on index.html. Life would be so easy…

Oh well…For now, those who attended should know that I will re-record this presentation with demo’s being happy. Until then, happy playing with tracing as it really does work!!!

~Chris

No Comments