You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Emmo Emminghaus (Jira)" <ji...@apache.org> on 2019/11/14 19:34:00 UTC
[jira] [Commented] (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:comment-tabpanel&focusedCommentId=16974560#comment-16974560 ]
Emmo Emminghaus commented on LOG4NET-583:
-----------------------------------------
Same Experience... same result:
Deadlock in FileAppender.FileOpen().
My suggestion:
Use a different name for the {color:#172b4d}File Rolling{color} mutex...
Then you have the same behavior when using the MinimalLock… IT WORKS PERFECT!
PS: I hope such a simple solution does not need another 2 years.
> 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
> Priority: Major
>
> 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
> {color:red}m_mutexForRolling = new Mutex(false, m_baseFileName.Replace("\\", "_").Replace(":", "_").Replace("/", "_") + "_MutexForRolling");{color}
> 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.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)