3

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?

Hafthor
  • 380
  • 2
  • 7
  • 13
  • Is there any type of load balancer or content caching mechanism in front of the web servers? – joeqwerty Oct 02 '09 at 17:50
  • Load balancer, but no caching – Hafthor Oct 02 '09 at 18:03
  • So both servers show missing log entries? Could the load balancer be causing a problem with access to the servers or with the logging? If it's possible I might suggest taking the load balancer out of the mix and running on just one server to see if the problem persists. The other thing you could do would be to run a network capture on both servers and compare it to the log files. If you don't see traffic in the log files but you do in the capture then you can focus your efforts on the servers, otherwise you would then focus on something in front of the servers. – joeqwerty Oct 02 '09 at 18:16
  • I don't think activity wasn't occurring nor do I think it wasn't being recorded, it just recorded 6.9 hours of activity all at once. SQL transactions show the server being fully operational during that time. – Hafthor Oct 02 '09 at 18:22
  • Can you post a small section of the log file illustrating the problem? – joeqwerty Oct 02 '09 at 20:00

1 Answers1

0

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.

splattne
  • 28,508
  • 20
  • 98
  • 148
joeqwerty
  • 109,901
  • 6
  • 81
  • 172