Home / server / Questions / 70857
In Process
Hafthor
Asked: 2009-10-03 09:42:50 +0800 CST

IIS6 Log time recording problems

  • 772

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?

iis-6

1 Answers

  1. The only thing I know that will make the headers show up in the middle of the log file is the web site being stopped or the settings for the log file being changed, as in this section of the first log:

    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

    Also, I'm not understanding whhat you mean in your comments after the log sections. Can you explain? What do you mean the problem coincides with you deploying the app and renaming ping.aspx? I'm confused, sorry.

    • 0