8

This is possibly not sitecore related, but since it is a sitecore setup, I'm counting on your expertise

We have a strange event happening on one of our clients website The website goes down for about an 25 mins every night

  • No error's in the sitecore logs at that time
  • The worker process is running since we have events in the logs during the outage like the cacheclearer and index job.

IIS logs however show a gap during that time:

2016-12-27 02:13:04 10.69.2.5 GET /SomeUrl
#Software: Microsoft Internet Information Services 7.5
#Version: 1.0
#Date: 2016-12-27 02:37:25
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken
2016-12-27 02:37:25 10.69.2.5 GET /SomeUrl

So my questions are:

  • Any Idea what causes IIS to write a log header line in the middle of the log?
  • If it is a recycle, they why does Sitecore keep running?
Improve this question
  • Just some more info: - There was no release prior to the nightly downtimes starting – Rik Dec 27 '16 at 7:40
  • 5
    If it's a timed app pool recycle event - check in the IIS App Pool settings - and assuming overlapped recycling is on, one app pool is "gracefully" shut down while a new one is started; that allows Sitecore to spin down which can take a few minutes (not 25 though). This is accompanied by a new Sitecore log file and the IIS headers you are showing in your snip above. If the Sitecore logs roll over at the same time it's definitely a recycle. The new IIS log header is only written when an actual request is received, which might be rare at 2:30am. – Richard Hauer Dec 27 '16 at 8:59
  • did you read this forum, it seems IIS restarting the logging process and not restarting the IIS service forums.iis.net/t/… – Balaji Kuppuswamy Dec 27 '16 at 9:09
  • Richard, we have only 1 sitecore log file spanning hours before and after the event. The appool recycle is timed at 8:00, downtime is at 3:05, – Rik Dec 27 '16 at 12:30
  • 1
    Could it be Windows Updates by chance? 2AM hour is usually the window that Microsoft uses for system updates. – Pete Navarra Dec 27 '16 at 14:14
1

Things to check:

Sitecore logs:

  • Do they roll-over at this instant, signifying an application restart?

IIS Logs

  • IIS Logs - You've left out most of the columns in the log, what does the "time-taken" column show for the one (or several) entries after the delay?
  • Is time-taken the same before and after for the same requests, or are they drastically different? If afterwards they're huge then feels like you've got some sort of request locking threads.

Try running a Microsoft Performance Monitor capture during this time looking specifically for:

  • ASP.NET Apps / Requests Executing
  • ASP.NET Apps / Requests/Sec
  • ASP.net v4 / Requests Current
  • ASP.net v4 / Requests Queued
  • Memory / Pages/sec

This may help show you that requests are coming in but being queued due to saturation or some sort of locking events.

enter image description here

Event Viewer

  • Anything in the Application or System event logs at or around this time?
Improve this answer

Not the answer you're looking for? Browse other questions tagged or ask your own question.