Why are log4net threads stuck on a wait?

Question

Last week one of our test servers ran out of disk space on the log drive. After freeing up disk space, I still have several threads with call stacks that seem to be stuck inside of log4net AppenderSkeleton.DoAppend, which is confusing since I'm expecting log4net to be thread safe.

1. Am I reading the stack correct in seeing the threads as being stuck?
2. Is the stack indicating that the thread is stuck at 'lock(this)' or elsewhere? My guess is elsewhere, since I would expect to see something like, Monitor.Enter if it was stuck at lock(this).
3. One of the threads seems to show DoAppend in the middle of rolling over to a new file. Could it be that all of the DoAppend threads are blocked on the creation of this file? However, I would expect these threads to become unblocked after we freed disk space.

Any help understanding why log4net seems to be stuck across so many threads is appreciated.

Here is an example call stack showing a thread blocked at a wait inside of DoAppend:

ntdll.dll!_NtWaitForMultipleObjects@20() + 0x15 bytes
ntdll.dll!_NtWaitForMultipleObjects@20() + 0x15 bytes
KERNELBASE.dll!_WaitForMultipleObjectsEx@20() + 0x36 bytes kernel32.dll!_WaitForMultipleObjectsExImplementation@20() + 0x8e bytes [Managed to Native Transition]
log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0x3e bytes log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes
log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

Here is the source from log4net AppenderSkeleton.DoAppend

public void DoAppend(LoggingEvent loggingEvent) 
{
    // This lock is absolutely critical for correct formatting
    // of the message in a multi-threaded environment.  Without
    // this, the message may be broken up into elements from
    // multiple thread contexts (like get the wrong thread ID).

    lock(this)
    {
        if (m_closed)
        {
            ErrorHandler.Error("Attempted to append to closed appender named ["+m_name+"].");
            return;
        }

        // prevent re-entry
        if (m_recursiveGuard)
        {
            return;
        }

        try
        {
            m_recursiveGuard = true;

            if (FilterEvent(loggingEvent) && PreAppendCheck())
            {
                this.Append(loggingEvent);
            }
        }
        catch(Exception ex)
        {
            ErrorHandler.Error("Failed in DoAppend", ex);
        }
#if !MONO && !NET_2_0
        // on .NET 2.0 (and higher) and Mono (all profiles), 
        // exceptions that do not derive from System.Exception will be
        // wrapped in a RuntimeWrappedException by the runtime, and as
        // such will be catched by the catch clause above
        catch
        {
            // Catch handler for non System.Exception types
            ErrorHandler.Error("Failed in DoAppend (unknown exception)");
        }
#endif
        finally
        {
            m_recursiveGuard = false;
        }
    }
}

Here are my log4net settings:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>
  <log4net xsi:noNamespaceSchemaLocation="log4net.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="g:\logfiles\mySerivceName\" />
      <appendToFile value="true" />
      <rollingStyle value="Date" />
      <datePattern value="'myServiceName.'yyyy-MM-dd-HH'-00.log'"/>
      <staticLogFileName value="false" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%3thread] [%-50.50stacktrace] %message %newline"/>
      </layout>
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="INFO" />
        <levelMax value="FATAL" />
      </filter>
    </appender>
    <appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
        <to value="[email protected]" />
        <from value="servicename@localnetwork" />
        <subject value="${COMPUTERNAME} - Error Generated" />
        <smtpHost value="mySmtpServerIpAddress" />
        <bufferSize value="2" />
        <lossy value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level [%3thread] [%-50.50stacktrace] %message %newline" />
        </layout>
        <filter type="log4net.Filter.LevelRangeFilter">
            <levelMin value="ERROR" />
            <levelMax value="FATAL" />
        </filter>
    </appender>
    <root>
      <level value="DEBUG"/>
      <appender-ref ref="RollingFileAppender" />
    </root>
  </log4net>
</configuration>

The DoAppend stack that is rolling over to a new file

mscorlib.dll!System.Text.StringBuilder.Append(char value) Line 953 + 0xb bytes
  mscorlib.dll!System.IO.PathHelper.Append(char value) Line 139 + 0x18 bytes
  mscorlib.dll!System.IO.Path.NormalizePath(string path, bool fullCheck, int maxPathLength, bool expandShortPaths) Line 620
  mscorlib.dll!System.IO.Path.GetDirectoryName(string path) Line 170 + 0x24 bytes
  log4net.dll!log4net.Appender.FileAppender.LockingModelBase.CreateStream(string filename, bool append, System.IO.FileShare fileShare) + 0x35 bytes     
  log4net.dll!log4net.Appender.FileAppender.ExclusiveLock.OpenFile(string filename, bool append, System.Text.Encoding encoding) + 0x2d bytes      
  log4net.dll!log4net.Appender.FileAppender.OpenFile(string fileName, bool append) + 0x1ac bytes  
  log4net.dll!log4net.Appender.RollingFileAppender.OpenFile(string fileName, bool append) + 0x189 bytes 
  log4net.dll!log4net.Appender.FileAppender.SafeOpenFile(string fileName, bool append) + 0x2d bytes     
  log4net.dll!log4net.Appender.FileAppender.PrepareWriter() + 0x13 bytes  
  log4net.dll!log4net.Appender.TextWriterAppender.PreAppendCheck() + 0x32 bytes 
  log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0xe0 bytes 
  log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes      
  log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes      
  log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

Here is another call stack on the same machine, different process, also hung:

clr.dll!AwareLock::Contention() + 0x10d bytes
[Managed to Native Transition]
log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0x3e bytes log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes
log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

And in this second process on the same machine, there is also a thread that seems to be blocked trying to rollover.

MSVCR120_CLR0400.dll!_memcpy() + 0x21e bytes
[Managed to Native Transition]
mscorlib.dll!System.Buffer._Memcpy(byte* dest, byte* src, int len) Line 484 + 0x20 bytes C# mscorlib.dll!System.Buffer.Memcpy(byte* dest, byte* src, int len) Line 401 C# mscorlib.dll!string.FillStringChecked(string dest, int destPos, string src) Line 1523 + 0xf bytes C# mscorlib.dll!string.ConcatArray(string[] values, int totalLength) Line 3340 C# mscorlib.dll!string.Concat(object[] args) Line 3180 + 0xa bytes C# log4net.dll!log4net.Appender.FileAppender.OpenFile(string fileName, bool append) + 0x162 bytes
log4net.dll!log4net.Appender.RollingFileAppender.OpenFile(string fileName, bool append) + 0x189 bytes
log4net.dll!log4net.Appender.FileAppender.SafeOpenFile(string fileName, bool append) + 0x2d bytes
log4net.dll!log4net.Appender.FileAppender.PrepareWriter() + 0x13 bytes
log4net.dll!log4net.Appender.TextWriterAppender.PreAppendCheck() + 0x32 bytes
log4net.dll!log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent loggingEvent) + 0xe0 bytes log4net.dll!log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa0 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent loggingEvent) + 0xa9 bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x4a bytes
log4net.dll!log4net.Repository.Hierarchy.Logger.Log(System.Type callerStackBoundaryDeclaringType, log4net.Core.Level level, object message, System.Exception exception) + 0x5e bytes
log4net.dll!log4net.Core.LogImpl.Info(object message) + 0x27 bytes

Answer 1

I have seen this behavior of log4net multiple times here on stack overflow. When you run out of diskspace the fileappender seems to start blocking. I guess this is a bug in the appender, so logging this as bug seems right for this case.