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.