Uploaded image for project: 'Log4net'
  1. Log4net
  2. LOG4NET-583

RolingFileAppender+InterProcessLock is locked after rolling log files

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.0.8
    • Fix Version/s: None
    • Component/s: Appenders
    • Labels:
      None
    • 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("/", "_");

      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.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              zpanov Eugene Panov
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: