by Mark Trescowthick - GUI Computing
We like to document solutions here at AVDF Central. Seems to us that an eZine which documents problems is sort of missing the point! In many ways, this article is the exception which proves the rule, though.
The Real Problem
About three months back an IIS 3 server on an Intranet we run started to stop randomly.
And I do mean "randomly" - it would run for a few minutes, hours or days, depending on how it felt, the weather, the price of tea in China or whatever and then the service would just stop. No logs, no nothing.
After a lot of digging, we're really no closer to the reason why this should be, and we've tried everything under the Sun. The really odd problem is that we can't replicate the problem on our development server - even after we have file-by-file matched the two.
We believe that the problem relates to the Sybase database that is being accessed, and that what's happening is that there is a GPF in (probably) ASP.DLL - but that's all guesswork. We'd like to run IIS under the VC++ Debugger to see just what's going on, but this is a production server, so that's not really an option.
The Introduced Problem
When I first started looking at this, my thought was to look at the IIS logs and see if any one URL (or operation) was always implicated. But the last URL logged was, in many cases, so innocuous that it just couldn't be right.
As I'm wont to do in these cases, I called for help. Gary Wisniewski suggested that, while he'd been developing an ISAPI filter he'd discovered that the folks who wrote IIS 3 had been very concerned with performance. He mentioned to me that, for example, cookies supposedly written at the start of a page are in fact cached until the page is complete in order to make File I/O more efficient.
That made sense in terms of performance, but it also suggested a possible line of attack on the Real Problem - maybe the IIS Log was being cached too...
Next stop weas the office of Jim Karabatsos. I'd just been using his URLMapper ISAPI filter (documented in this issue) and wondered if he couldn't modify it ever so slightly to allow us to collect our own (uncached) log of what was going on.
His response was 'easy!', and so it proved to be. The source is available for download.
The DLL works pretty much the same as URLMapper, so there's not much point in detailing it again here.
The registry hive for this one is HKLM\Software\GUI\URLLogger, with two keys :
LogFileExt is the extension to be used for the log files (the default is "LOG"), and there is no need for the leading dot.
LogFileRoot is the complete string for the log file name, to which the filter will add a date-time stamp, a period and the LogFileExt to generate log file names.
Using the keys:
LogFileRoot=D:\My Documents\IISLOG_ LogFileExt=LOGthe filter will create logs named D:\My Documents\IISLOG_yymmdd.hhmm.LOG
It creates a new file for each 10-minute interval during which at least one event is logged. This means that it will create a maximum of 144 files per day. That makes manipulating the results a little harder, but given that URLLogger opens, reads to the end of the current log, adds a line then closes it was deemed that performance was more important than convenience.
I've seen a number of articles on detailed site logging and all of them of suggested that the best way to do custom logging is to write an ISAPI filter - and nearly all have suggested that this is too hard for ASP-type people, that it's something that must remain in the domain of C++ types. Jim's ISAPI filter even I can understand, so I guess that's not the case any more. It would be a simple matter to beef up the logging it does to support some pretty sophisticated stats.
No folks, can't give you that right now.
The Logger worked, but actually didn't advance things much at all. We're still pretty certain it's Sybase that is the culprit, though, and I'd advise staying away from the IIS 3 / Sybase combination if you have any choice in the matter. We're now aware of at least three servers exhibiting the same behaviour, and the only thing any of them have in common is Sybase. One even uses JScript rather than VBScript.
Anyone with any insight is most welcome to contact me!
The fundamental lesson here, though, is that IIS logs will give you a perfect picture of what's going right on your server. Just don't expect them to show you what isn't!