1

While investigating some missing log files, I found that quite frequently we had short periods with two log files, created with about a second of each other, directly after a recycle.

We have a scheduled recycle at 4am.

Each log file starts with the INFO Heartbeat - Initializing line and includes the "Sitecore started" line (Sitecore.NET 8.2 (rev. 170728))

In the startup info section we see:

4776 04:00:06 INFO Microsoft.NET version info

4776 04:00:06 INFO

4776 04:00:06 INFO UTC offset: 02:00:00

4776 04:00:06 INFO Machine name: *********

4776 04:00:06 INFO App pool ID: Correct app pool

4776 04:00:06 INFO

4776 04:00:06 INFO Process ID: 3296

4776 04:00:06 INFO Windows identity info

4776 04:00:06 INFO Managed pipeline mode: Integrated

The process ID is different for each log file.

One of the log files stops within a minute, in almost all cases with the shutdown message

836 04:00:41 WARN Sitecore shutting down
836 04:00:41 WARN Shutdown message: HostingEnvironment initiated shutdown

The other continues until the file rolls over at midnight.

We can also see that there are sometimes external resource conflicts (e.g. an attempt to write to a data file fails as it is in use by another process) that appear to be between the instances.

Our hypothesis for the case of missing log files is that we are seeing two instances of the single Sitecore application started within the same app pool , one locks resources (the log file itself?) that the other can't access, breaking logging for that instance until the next recycle and then the instance with the resource lock is killed by the IIS after a minute.

So does anyone have any experience of this, or ideas of how and where to investigate?

For the record - the App pool only has our single Sitecore instance in it (multisite), has only one worker process and is set to allow overlapped recycling.

EDIT: I can now confirm that for a short period we actually have three process IDs in the app pool.

We can see in the event log that when this happens the recycle has occurred a couple of seconds early, and then at the correct scheduled time (two seconds later) the new process asks to be recycled.

With overlapped recycling this leaves two processes finishing their requests while the third starts up (and will continue to the next scheduled recycle).

Missing log files are caused by the second process gaining a lock on the timestamped logfile so the third can't write to it.

Extra log files are caused when the log timestamps for the second and third processes differ, so each gets its own log file.

An answer to a similar question on Serverfault.com suggests that time synchronization on the VMWare platform may be the root cause, and that this is a general issue unconnected with Sitecore itself.

https://serverfault.com/questions/372873/does-iis-sometimes-allocate-more-worker-processes-than-configured

Improve this question
5
  • Can I ask that you clarify? You have 2 instances, in separate App Pools, pointing to the same IIS root directory?
    – Mark Cassidy ♦
    Commented Sep 5, 2018 at 10:09
  • Nope. One instance only. On recycle it seems to start twice in two separate processes in the same app pool, before one is killed off
    – James Walford
    Commented Sep 5, 2018 at 11:06
  • 3
    We have seen this exact same behavior. It's due to the "DisableOverlapSetting" on the app pool (medium.com/@ShamreshKhan/…). Setting this to true ensures a clean cutover to the new app pool. We do this as part of a scripted event (PowerShell), but you can change the setting directly in IIS as well. We tried digging to find the root of the issue but came up empty-handed.
    – jrap
    Commented Sep 5, 2018 at 12:43
  • 1
    It was also extremely inconsistent- sometimes we saw the behavior, other times we didn't, so it wasn't something we could confidently send to Sitecore support. From Microsoft (msdn.microsoft.com/en-us/library/ms525803(v=vs.90).aspx) "If your application cannot run in a multi-instance environment, you must configure only one worker process for an application pool (which is the default value), and disable the overlapped recycling feature if application pool recycling is being used."
    – jrap
    Commented Sep 5, 2018 at 12:46
  • Yes, overlapped recycling is my prime suspect at the moment, though we don't want to disable it if we don't have to. We have a 90 second shutdown time limit on the app pool, and the new logs appear well within that though. We can see that the process ID of the instance shutting down is different to both of the two new processes started. It may be that in shutting down we trigger some sort of recycle event somehow.
    – James Walford
    Commented Sep 5, 2018 at 14:32

1 Answer 1

Reset to default
1

We've seen this as well. IISRESET was tried as well with no luck. Checking Data\diagnostics\configuration_history\ we saw that files were being changed, and that McAfee on the client's server was reading core files, prompting a restart.

Improve this answer
1
  • That was an interesting place to look. We have only one double config dump, but some of the logs show resource locking conflicts on the dump file. We can't find any differences in the config dumps though.
    – James Walford
    Commented Sep 7, 2018 at 14:18

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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