IIS6 Log time recording problems

Posted by Hafthor on Server Fault See other posts from Server Fault or by Hafthor
Published on 2009-10-02T17:42:50Z Indexed on 2010/03/12 13:08 UTC
Read the original article Hit count: 782

Filed under:
|

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?

© Server Fault or respective owner

Related posts about iis6

Related posts about logging