Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
2.0.8
-
None
-
None
-
Windows Server 2008 R2 Standart, IIS 7.5
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
}
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
finally
{ m_stream.ReleaseLock(); } }
}
}
public bool AcquireLock()
{
bool ret = false;
lock (this)
{
if (m_lockLevel == 0)
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)
}
}
It cause locking of any other threads that try to append to the log.