IIS6 Log time recording problems
- by Hafthor
On three separate occasions on two separate servers at nearly the same times, 6.9 hours seemingly went by without any data being written to the IIS logs, but, on closer inspection, it appears that it was all recorded all at once.
Here's the facts as I know them:
Windows Server 2003 R2 w/ IIS6
Logging using GMT, server local time GMT-7.
Application was still operating and I have SQL data to prove that
Time gaps appear in log file, not across two
# headers appear at gap
Load balancer pings every 30 seconds
No caching
Here's info on a particular case:
an entry appears for 2009-09-21 18:09:27
then #headers
the next entry is for 2009-09-22 01:21:54, and so are the next 1600 entries in this log file and 370 in the next log file.
about half of the ~2000 entries on 2009-09-22 01:21:54 are load balancer pings (est. at 2/min for 6.9hrs = 828 pings)
then entries are recorded as normal.
I believe that these events may coincide with me deploying an ASP.NET application update into those machines.
Here's some relevant content from the logs in question:
ex090921.log line 3684
2009-09-21 17:54:40 GET /ping.aspx - 80 404 0 0 3733 122 0
2009-09-21 17:55:11 GET /ping.aspx - 80 404 0 0 3733 122 0
2009-09-21 17:55:42 GET /ping.aspx - 80 404 0 0 3733 122 0
2009-09-21 17:56:13 GET /ping.aspx - 80 404 0 0 3733 122 0
2009-09-21 17:56:45 GET /ping.aspx - 80 404 0 0 3733 122 0
#Software: Microsoft Internet Information Services 6.0
#Version: 1.0
#Date: 2009-09-21 18:04:37
#Fields: date time cs-method cs-uri-stem cs-uri-query s-port sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken
2009-09-22 01:04:06 GET /ping.aspx - 80 404 0 0 3733 122 3078
2009-09-22 01:04:06 GET /ping.aspx - 80 404 0 0 3733 122 109
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 278 122 3828
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 278 122 0
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 278 122 0
... continues until line 5449
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 277 122 0
<eof>
ex090922.log
#Software: Microsoft Internet Information Services 6.0
#Version: 1.0
#Date: 2009-09-22 00:00:16
#Fields: date time cs-method cs-uri-stem cs-uri-query s-port sc-status sc-substatus sc-win32-status sc-bytes cs-bytes time-taken
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 277 122 0
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 277 122 0
... continues until line 367
2009-09-22 01:04:06 GET /ping.aspx - 80 200 0 0 277 122 0
2009-09-22 01:04:30 GET /ping.aspx - 80 200 0 0 277 122 0
... back to normal behavior
Note the seemingly correct date/time written to the #header of the new log file.
Also note that /ping.aspx returned 404 then switched to 200 just as the problem started. I rename the "I'm alive page" so the load balancer stops sending requests to the server while I'm working on it. What you see here is me renaming it back so the load balancer will use the server. So, this problem definitely coincides with me re-enabling the server.
Any ideas?
