You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Eugene Panov (JIRA)" <ji...@apache.org> on 2017/12/04 15:20:00 UTC
[jira] [Updated] (LOG4NET-583) RolingFileAppender+InterProcessLock
is locked after rolling log files
[ https://issues.apache.org/jira/browse/LOG4NET-583?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Eugene Panov updated LOG4NET-583:
---------------------------------
Affects Version/s: 2.0.8
Environment: 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("/", "_");
{color:red}m_mutex = new Mutex(false, mutexFriendlyFilename);
{color} }
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:
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.
Component/s: Appenders
Summary: RolingFileAppender+InterProcessLock is locked after rolling log files (was: RolingFileAppender+InterProcessLock is )
> RolingFileAppender+InterProcessLock is locked after rolling log files
> ---------------------------------------------------------------------
>
> Key: LOG4NET-583
> URL: https://issues.apache.org/jira/browse/LOG4NET-583
> Project: Log4net
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.0.8
> Environment: Windows Server 2008 R2 Standart, IIS 7.5
> Reporter: Eugene Panov
>
> 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("/", "_");
> {color:red}m_mutex = new Mutex(false, mutexFriendlyFilename);
> {color} }
> 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:
> 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.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)