FreeAndNil opened a new issue, #279:
URL: https://github.com/apache/logging-log4net/issues/279
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):
```csharp
protected virtual void AdjustFileBeforeAppend()
{
// ...
_mutexForRolling?.WaitOne(); // Waiting for Mutex while holding LockObj
// ...
}
```
src/log4net/Appender/FileAppender.cs (Line 1216):
```csharp
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.
```csharp
// (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.
```csharp
if (!_mutexForRolling.WaitOne(5000))
{
ErrorHandler.Error("Rollover timeout - skipping to prevent deadlock.");
return;
}
```
RollingFileAppenderDeadlockTest.cs
```csharp
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);
}
}
}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
