Deadlock in RollingFileAppender via lock inversion

[FreeAndNil]

The RollingFileAppender in log4net contains a Deadlock vulnerability (CWE-833). This issue arises from a Lock Inversion between the internal LockObj (Monitor) and the OS-level named mutex _mutexForRolling.

When triggered, the application process enters an indefinite hang state. Since log4net is often configured as a central logging provider, this blockage prevents all threads from writing logs, effectively causing a Permanent Denial of Service (DoS) requiring a manual process restart.

The deadlock is caused by an inconsistent locking order (AB-BA inversion) across two execution paths:

Path A (Logging Flow):
    A thread calls DoAppend().
    It acquires the LockObj (Monitor).
    It calls AdjustFileBeforeAppend().
    It attempts to acquire the _mutexForRolling (Mutex).

Path B (Rollover Flow):
    A thread acquires the _mutexForRolling (Mutex) during a rollover event or initialization (e.g., ExistingInit).
    It calls SafeOpenFile() -> OpenFile().
    It attempts to acquire the LockObj (Monitor).

Deadlock State:

Thread A holds LockObj and is blocked waiting for _mutexForRolling.
Thread B holds _mutexForRolling and is blocked waiting for LockObj.

Impacted function

The vulnerability resides in the interaction between RollingFileAppender and its base class FileAppender.

src/log4net/Appender/RollingFileAppender.cs (Line 524):

protected virtual void AdjustFileBeforeAppend()
{
    // ...
    _mutexForRolling?.WaitOne(); // Waiting for Mutex while holding LockObj
    // ...
}

src/log4net/Appender/FileAppender.cs (Line 1216):

protected virtual void OpenFile(string fileName, bool append)
{
    // ...
    lock (LockObj) // Waiting for LockObj while holding Mutex
    {
        // ...
    }
}

Reproduction Steps

Initialize a RollingFileAppender with MaximumFileSize set to a small value (e.g., "1KB") to trigger frequent rollovers.
Simulate high-concurrency logging where one thread triggers a rollover while another thread is already inside a DoAppend call.
Observe that both threads hang indefinitely, and the application becomes unresponsive.

Deterministic Unit Test (PoC)

The snippet below shows the core logic. The full source code (including a cascading thread exhaustion test) is provided in the Appendix at the bottom of this report.

// (Core logic snippet for quick review)
// See Appendix for full executable code
Thread threadA = new Thread(() => {
    appender.DoAppend(logEvent); // Takes LockObj
});

Thread threadB = new Thread(() => {
    appender.TriggerAdjust(); // Takes Mutex
});

// Force Race Condition
threadA.Start(); appender.InAdjust.WaitOne();
threadB.Start(); appender.InRename.WaitOne();

// Deadlock Trigger
appender.ContinueAdjust.Set();
appender.ContinueRename.Set();

Thread Dump

Analysis of the captured thread dump confirms the deadlock state:

Thread A (Blocked on Mutex):

OS Thread Id: 0x14fa6
System.Threading.WaitHandle.WaitOne(Int32)
log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()
log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)

Thread B (Blocked on Monitor):

OS Thread Id: 0x14fa7
System.Threading.Monitor.Enter(System.Object)
log4net.Appender.FileAppender.OpenFile(System.String, Boolean)
log4net.Appender.RollingFileAppender.RollOverTime(Boolean)

Remediation

The synchronization logic should be refactored to ensure a consistent locking order. Implementing a timeout for the mutex acquisition would allow the application to recover gracefully.

if (!_mutexForRolling.WaitOne(5000)) 
{
    ErrorHandler.Error("Rollover timeout - skipping to prevent deadlock.");
    return;
}

RollingFileAppenderDeadlockTest.cs

using System;
using System.IO;
using System.Reflection;
using System.Threading;
using log4net.Appender;
using log4net.Core;
using log4net.Layout;
using NUnit.Framework;

namespace log4net.Tests.Appender
{
    [TestFixture]
    public class RollingFileAppenderDeadlockTest
    {
        private void Log(string message)
        {
            Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} {message}");
        }

        private class DeadlockRollingFileAppender : RollingFileAppender
        {
            public ManualResetEvent InAdjust = new ManualResetEvent(false);
            public ManualResetEvent ContinueAdjust = new ManualResetEvent(false);
            public ManualResetEvent InRename = new ManualResetEvent(false);
            public ManualResetEvent ContinueRename = new ManualResetEvent(false);
            public RollingFileAppenderDeadlockTest Test;

            // We need to call the protected AdjustFileBeforeAppend
            public void TriggerAdjust()
            {
                AdjustFileBeforeAppend();
            }

            protected override void AdjustFileBeforeAppend()
            {
                Test.Log($"Thread {Thread.CurrentThread.ManagedThreadId}: Entering AdjustFileBeforeAppend");
                // If we are Thread A (holding LockObj), we signal and wait
                if (Thread.CurrentThread.Name == "ThreadA")
                {
                    Test.Log("Thread A: Signalling InAdjust and waiting for ContinueAdjust");
                    InAdjust.Set();
                    ContinueAdjust.WaitOne();
                    Test.Log("Thread A: Continuing to base.AdjustFileBeforeAppend (will try to take _mutexForRolling)");
                }
                base.AdjustFileBeforeAppend();
            }

            protected override void RollOverRenameFiles(string baseFileName)
            {
                Test.Log($"Thread {Thread.CurrentThread.ManagedThreadId}: Entering RollOverRenameFiles");
                // If we are Thread B (holding _mutexForRolling), we signal and wait
                if (Thread.CurrentThread.Name == "ThreadB")
                {
                    Test.Log("Thread B: Signalling InRename and waiting for ContinueRename");
                    InRename.Set();
                    ContinueRename.WaitOne();
                    Test.Log("Thread B: Continuing to base.RollOverRenameFiles");
                }
                base.RollOverRenameFiles(baseFileName);
            }
        }

        [Test]
        public void TestDeadlock()
        {
            Log("Main: Starting test");

            string filename = "deadlock_test.log";
            if (File.Exists(filename)) File.Delete(filename);
            File.WriteAllText(filename, "initial content");

            DeadlockRollingFileAppender appender = new DeadlockRollingFileAppender();
            appender.Test = this;
            appender.File = filename;
            appender.Layout = new PatternLayout("%message%newline");
            appender.StaticLogFileName = true;
            appender.MaxSizeRollBackups = 1;
            appender.MaximumFileSize = "1"; // Force rollover

            appender.ActivateOptions();

            LoggingEvent loggingEvent = new LoggingEvent(typeof(RollingFileAppenderDeadlockTest), null, "TestLogger", Level.Info, "Test message", null);

            Thread threadA = new Thread(() =>
            {
                try
                {
                    Log("Thread A: Calling DoAppend (will take LockObj)");
                    appender.DoAppend(loggingEvent);
                    Log("Thread A: DoAppend returned");
                }
                catch (Exception ex)
                {
                    Log($"Thread A: Exception: {ex.Message}");
                }
            });
            threadA.Name = "ThreadA";

            Thread threadB = new Thread(() =>
            {
                try
                {
                    Log("Thread B: Calling TriggerAdjust (will take _mutexForRolling)");
                    appender.TriggerAdjust();
                    Log("Thread B: TriggerAdjust returned");
                }
                catch (Exception ex)
                {
                    Log($"Thread B: Exception: {ex.Message}");
                }
            });
            threadB.Name = "ThreadB";

            // 1. Thread A takes LockObj and waits
            threadA.Start();
            appender.InAdjust.WaitOne();
            Log("Main: Thread A is holding LockObj");

            // 2. Thread B takes _mutexForRolling and waits
            threadB.Start();
            appender.InRename.WaitOne();
            Log("Main: Thread B is holding _mutexForRolling");

            Log("Main: Both threads are primed for deadlock. Releasing them...");

            // 3. Release both
            appender.ContinueAdjust.Set();
            appender.ContinueRename.Set();

            Log("Main: Waiting for threads to finish (timeout 10s)");

            bool threadAFinished = threadA.Join(10000);
            bool threadBFinished = threadB.Join(10000);

            Log($"Main: Thread A finished: {threadAFinished}");
            Log($"Main: Thread B finished: {threadBFinished}");

            if (!threadAFinished || !threadBFinished)
            {
                Log("Main: Deadlock detected!");
                Assert.Pass("Deadlock detected successfully!");
            }
            else
            {
                Log("Main: No deadlock occurred.");
                Assert.Fail("Deadlock did not occur.");
            }

            if (File.Exists(filename)) File.Delete(filename);
        }

        [Test]
        public void TestCascadingThreadExhaustion()
        {
            Log("Main: Starting Cascading Failure Test");
            string filename = "cascading_test.log";
            if (File.Exists(filename)) File.Delete(filename);
            File.WriteAllText(filename, "initial content");

            DeadlockRollingFileAppender appender = new DeadlockRollingFileAppender();
            appender.Test = this;
            appender.File = filename;
            appender.Layout = new PatternLayout("%message%newline");
            appender.ActivateOptions();

            // 1. Trigger deadlock state
            Thread threadA = new Thread(() => {
                appender.DoAppend(new LoggingEvent(typeof(RollingFileAppenderDeadlockTest), null, "TestLogger", Level.Info, "Thread A", null));
            });
            threadA.Name = "ThreadA";

            Thread threadB = new Thread(() => {
                appender.TriggerAdjust();
            });
            threadB.Name = "ThreadB";

            threadA.Start();
            appender.InAdjust.WaitOne();
            threadB.Start();
            appender.InRename.WaitOne();

            // Both threads are now holding one lock and waiting for the other (once released)
            appender.ContinueAdjust.Set();
            appender.ContinueRename.Set();

            // 2. Start 10 more threads attempting to log
            int extraThreads = 10;
            Thread[] threads = new Thread[extraThreads];
            bool[] blocked = new bool[extraThreads];

            for (int i = 0; i < extraThreads; i++)
            {
                int index = i;
                threads[i] = new Thread(() =>
                {
                    Log($"Extra Thread {index}: Attempting to log");
                    appender.DoAppend(new LoggingEvent(typeof(RollingFileAppenderDeadlockTest), null, "TestLogger", Level.Info, $"Message {index}", null));
                    blocked[index] = false;
                });
                blocked[i] = true;
                threads[i].Start();
            }

            Log("Main: Waiting to see if extra threads are blocked");
            Thread.Sleep(2000);

            int blockedCount = 0;
            for (int i = 0; i < extraThreads; i++)
            {
                if (blocked[i]) blockedCount++;
            }

            Log($"Main: {blockedCount}/{extraThreads} extra threads are BLOCKED");

            Assert.That(blockedCount, Is.GreaterThan(0), "At least some threads should be blocked by the deadlock");

            // Cleanup
            if (File.Exists(filename)) File.Delete(filename);
        }
    }
}

[FreeAndNil]

@gdziadkiewicz do you have time to take a look at this?

[gdziadkiewicz]

Yes, looking at it

[gdziadkiewicz]

@FreeAndNil I was able to reproduce the issue using the provided test code, but my understanding is that this situation is only possible because TriggerAdjust calls the protected method AdjustFileBeforeAppend, which is accessible via inheritance from RollingFileAppender and can be invoked on demand. This does not appear to be a realistic usage scenario unless a consumer derives from RollingFileAppender and (arguably) misuses it.

For consumers using RollingFileAppender as-is, I don’t see a path where AdjustFileBeforeAppend can be reached without already holding LockObj. It is only invoked from RollingFileAppender.Append (protected), which in turn is called from AppenderSkeleton.DoAppend (public), where the lock is taken.

In ExistingInit, there is indeed a call to RollOverTime (via RollOverIfDateBoundaryCrossing) that could attempt to acquire LockObj, but this only occurs when ExistingInit(true) is used, which is not the case here.

That said:

1. Do we have any reports of this occurring in real-world usage? Details would help me investigate more.

2. I haven’t yet measured the performance impact of adding a lock to AdjustFileBeforeAppend, but doing so would make the test cases pass and would harden the class against misuse via inheritance. If the analysis above is correct, this should not change observable behaviour, since the lock is already held in normal execution paths.

[FreeAndNil]

@gdziadkiewicz this issue was reported as "security vulnerability" via yeswehack.com.
There a no real world problems, yet.

What you you think about the following paths?

Lock order A (logging path)

// AppenderSkeleton.cs
public virtual void DoAppend(LoggingEvent loggingEvent)
{
  lock (LockObj)
  {
      Append(loggingEvent);
  }
}

// RollingFileAppender.cs
protected override void Append(LoggingEvent loggingEvent)
{
  ...
  AdjustFileBeforeAppend();
  ...
}

protected virtual void AdjustFileBeforeAppend()
{
  _mutexForRolling?.WaitOne();
}

DoAppend()                
  lock(LockObj)
    Append()             
      AdjustFileBeforeAppend()
         _mutexForRolling.WaitOne()

Holds LockObj -> waits for _mutexForRolling

Lock order B (rollover path)

// RollingFileAppender.cs
protected virtual void RollOverTime(bool fileIsOpen)
{
  _mutexForRolling?.WaitOne();
  try
  {
    RollOverRenameFiles(...);
  }
  finally
  {
    _mutexForRolling?.ReleaseMutex();
  }
}

protected virtual void RollOverRenameFiles(string baseFileName)
{
  SafeOpenFile();
}

// FileAppender.cs
protected void SafeOpenFile()
{
  OpenFile(_fileName, _appendToFile);
}

protected virtual void OpenFile(string fileName, bool append)
{
  lock (LockObj)
  {
    // ...
  }
}

RollOverTime()
  _mutexForRolling.WaitOne()
    RollOverRenameFiles()
      SafeOpenFile()
        OpenFile()
          lock(LockObj)

Holds _mutexForRolling -> waits for LockObj

[gdziadkiewicz]

@FreeAndNil The logging path from your message aligns with what I see on the master branch (1064764), but the rollover path does not. RollOverTime method does not use _mutexForRolling at all, and AdjustFileBeforeAppend is the only method using the _mutexForRolling.

---

Additionally, although unrelated to the interaction between lock and mutex, RollOverTime(bool isFileOpen) only ends up calling lock(LockObj) when called with true, and this happens only inside AdjustFileBeforeAppend , which means that there will never be problems with getting that lock (as AdjustFileBeforeAppend already secured it).

[FreeAndNil]

@gdziadkiewicz thanks a lot for your analysis.
I didn't see this on my first look.
I will close this.