[LOG4NET-583] RolingFileAppender+InterProcessLock is locked after rolling log files

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.0.8
• Component/s: Appenders
• Environment: Windows Server 2008 R2 Standart, IIS 7.5
• Assignee: Unassigned
• Reporter: Eugene Panov
• Created: 04/Dec/17 14:28
• Updated: 30/Apr/21 03:23

Description

We are using log4net for logging http requests to HttpHandlers.
RollingFileAppender is locked after rolling log files by date or by size.

Here is the dump of locked thread:
[[HelperMethodFrame_1OBJ] (System.Threading.WaitHandle.WaitOneNative)] System.Threading.WaitHandle.WaitOneNative(Microsoft.Win32.SafeHandles.SafeWaitHandle, UInt32, Boolean, Boolean)
mscorlib_ni!System.Threading.WaitHandle.WaitOne(Int64, Boolean)+23
log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()+47
log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)+18
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+c5
log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+9a
log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+8a
log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)+6f
log4net.Core.LogImpl.ErrorFormat(System.String, System.Object, System.Object, System.Object)+10e
FileManager.SaveReceivedDeviceLog(System.Web.HttpPostedFile, System.String)+1e1
upload_log_file.ProcessRequest(System.Web.HttpContext)+110
System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()+257
System_Web_ni!System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)+ab
System_Web_ni!System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)+511
System_Web_ni!System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)+72
System_Web_ni!System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)+269
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+411
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+2b
System_Web_ni!DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)+24
System_Web_ni!DomainNeutralILStubClass.IL_STUB(IntPtr, System.Web.RequestNotificationStatus ByRef)+4b
[[NDirectMethodFrameStandalone] (System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion)] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatusByRef)
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+540
System_Web_ni!System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+2b
System_Web_ni!DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)+24

I found that there are two places with mutex instanciation in the code:

In FileAppender.cs:

public override void ActivateOptions()
{
if (m_mutex == null)
{
string mutexFriendlyFilename = CurrentAppender.File
.Replace("
", "_")
.Replace(":", "_")
.Replace("/", "_");

m_mutex = new Mutex(false, mutexFriendlyFilename); }
else

{ CurrentAppender.ErrorHandler.Error("Programming error, mutex already initialized!"); }

}

and

in RollingFileAppender.cs:

// initialize the mutex that is used to lock rolling
m_mutexForRolling = new Mutex(false, m_baseFileName.Replace("
", "").Replace(":", "").Replace("/", "_") + "_MutexForRolling");

It looks like these mutexes are used for differnt purposes but they have the same name.
Suppose they should have different names.

But really locking is caused by the following code:

protected override void WriteHeader()
{
if (m_stream != null)
{
if (m_stream.AcquireLock())
{
try

{ base.WriteHeader(); }

finally

{ m_stream.ReleaseLock(); }

}
}
}

public bool AcquireLock()
{
bool ret = false;
lock (this)
{
if (m_lockLevel == 0)

{ // If lock is already acquired, nop m_realStream = m_lockingModel.AcquireLock(); }

if (m_realStream != null)

{ m_lockLevel++; ret = true; }
}
return ret;
}


m_realStream = m_lockingModel.AcquireLock(); - this line executes th following function:

public override Stream AcquireLock()
{
if (m_mutex != null)
{
// TODO: add timeout?
m_mutex.WaitOne();

// increment recursive watch
m_recursiveWatch++;

// should always be true (and fast) for FileStream
if (m_stream != null)
{

if (m_stream.CanSeek)
{ m_stream.Seek(0, SeekOrigin.End); }
}
else
{ // this can happen when the file appender cannot open a file for writing }
}
else
{ CurrentAppender.ErrorHandler.Error("Programming error, no mutex available to acquire lock! From here on things will be dangerous!"); }
return m_stream;
}

if m_stream == null then m_mutex.WaitOne(); is executed
but m_lockLevel is not incremented
if (m_realStream != null)
{ m_lockLevel++; ret = true; }

And mutex will not be released:
public void ReleaseLock()
{
lock (this)
{
m_lockLevel--;
if (m_lockLevel == 0)

{ // If already unlocked, nop m_lockingModel.ReleaseLock(); m_realStream = null; }

}
}

It cause locking of any other threads that try to append to the log.