Styjun

I'am using the Enterprise Library Logging Application Block Version 6.0 in an application. Today the application crashed at midnight as recoreded in the Event log.

Timestamp: 2019-03-27 00:00:00

Exception Info: System.NullReferenceException
at Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener+StreamWriterRollingHelper.PerformRoll(System.DateTime)
at Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener+StreamWriterRollingHelper.RollIfNecessary()
at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
at System.Threading.TimerQueueTimer.CallCallback()

Setting of the RollingFlatFileTraceListener from the app.config

<add name="Flat File Destination" 
 type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging" 
 listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging" 
 fileName="trace.log" 
 footer="" 
 formatter="Text Formatter" 
 header="" 
 rollFileExistsBehavior="Increment" 
 rollInterval="Midnight" 
 rollSizeKB="50000" 
 timeStampPattern="yyyy-MM-dd" 
 maxArchivedFiles="10" 
 traceOutputOptions="None" 
 filter="All" />

There are log entries in the trace file milliseconds before and after midnight. So there must be Access to the trace file while it is rolled.

I wrote a small test Programm to stress the application logger with the same Settings from my crashed application. While the app was running I often changed the time to some seconds before midnight trying to replicate the exception but was not successfull.

I opened the assemblies of the logging application in Version 5.0 and 6.0.
In Version 6.0 the RollingFlatFileTraceListener has the following constructor:

public RollingFlatFileTraceListener(string fileName, string header = "----------------------------------------", string footer = "----------------------------------------", ILogFormatter formatter = null, int rollSizeKB = 0, string timeStampPattern = "yyyy-MM-dd", RollFileExistsBehavior rollFileExistsBehavior = 0, RollInterval rollInterval = 0, int maxArchivedFiles = 0) : base(fileName, header, footer, formatter)
 
 Guard.ArgumentNotNullOrEmpty(fileName, "fileName");
 this.rollSizeInBytes = rollSizeKB * 1024;
 this.timeStampPattern = timeStampPattern;
 this.rollFileExistsBehavior = rollFileExistsBehavior;
 this.rollInterval = rollInterval;
 this.maxArchivedFiles = maxArchivedFiles;
 this.rollingHelper = new RollingFlatFileTraceListener.StreamWriterRollingHelper(this);
 if (rollInterval == RollInterval.Midnight)
 
 DateTime currentDateTime = this.rollingHelper.DateTimeProvider.CurrentDateTime;
 DateTime date = currentDateTime.AddDays(1).Date;
 this.timer = new Timer((object o) => this.rollingHelper.RollIfNecessary(), null, date.Subtract(currentDateTime), TimeSpan.FromDays(1));
 
 

So with the Setting of the rolling interval to Midnight a separate timer is started to perform the Rolling of the trace file if it is necessary. That was not the case in V5.0.

The method RollIfNecessary is also called by the method TraceData. My assumption is, that there is a threading issue when the method RollIfNecessary is executed. I found no lock in this method.

Can someone confirm my suspicion or had similar Problems?