This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/security-audit-hardening in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 3fd97cb511b2a99b3b4b6957ea606a2e5a6ab804 Author: Jan Friedrich <[email protected]> AuthorDate: Mon Aug 17 23:52:21 2026 +0200 bound the waits for the file locking mutexes InterProcessLock.AcquireLock carried a "TODO: add timeout?" and waited without one, as did RollingFileAppender when deciding whether to roll. Both waits happen while the appender lock is held, so a mutex nobody releases suspended every thread logging through the appender. Both now wait at most LockTimeoutMillis, 10000 by default, with Timeout.Infinite restoring the previous behaviour. An event that cannot get the file lock is reported and dropped; one that cannot get the rolling lock is written to the current file without the roll check, because rolling without the lock would race another process renaming the same files. Two more problems turned up on the way: AbandonedMutexException was unhandled although it means the wait succeeded and this thread owns the mutex. It propagated out of AcquireLock before _recursiveWatch was incremented, so ReleaseLock never released it and the mutex stayed held for good. That needs no attacker, only a process dying mid-write. AdjustFileBeforeAppend released the rolling mutex in a finally without checking that it had been taken. Harmless while the wait could only succeed, but a bounded wait makes it throw, so it is guarded now. The mutex names are left alone. They are derived from the log file path so that separate processes agree on them, and making them unpredictable would break the cross-process coordination they exist for. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]> --- src/changelog/3.4.0/309-bound-file-lock-waits.xml | 17 +++++ src/log4net.Tests/Appender/FileAppenderTest.cs | 80 ++++++++++++++++++++++ src/log4net/Appender/FileAppender.cs | 55 ++++++++++++++- src/log4net/Appender/RollingFileAppender.cs | 64 ++++++++++++++++- .../configuration/appenders/fileappender.adoc | 34 ++++++++- 5 files changed, 244 insertions(+), 6 deletions(-) diff --git a/src/changelog/3.4.0/309-bound-file-lock-waits.xml b/src/changelog/3.4.0/309-bound-file-lock-waits.xml new file mode 100644 index 00000000..fb80fad5 --- /dev/null +++ b/src/changelog/3.4.0/309-bound-file-lock-waits.xml @@ -0,0 +1,17 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="changed"> + <issue id="309" link="https://github.com/apache/logging-log4net/pull/309"/> + <description format="asciidoc"> + bound the waits for the named mutexes used by `FileAppender.InterProcessLock` and by + `RollingFileAppender` when it decides whether to roll. Both waited without a timeout while the + appender lock was held, so a mutex nobody released suspended every thread logging through the + appender. The wait now stops after `LockTimeoutMillis`, 10000 by default, reporting through the + error handler and dropping the event or skipping the roll check; `Timeout.Infinite` restores the + previous behaviour. `AbandonedMutexException` is handled as the successful acquisition it is, + rather than leaving the mutex held, and the rolling lock is no longer released when it was never + taken (audit 1231d72-f015) + </description> +</entry> diff --git a/src/log4net.Tests/Appender/FileAppenderTest.cs b/src/log4net.Tests/Appender/FileAppenderTest.cs index 8537f80d..7fa095c5 100644 --- a/src/log4net.Tests/Appender/FileAppenderTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderTest.cs @@ -30,7 +30,9 @@ using System.IO; using System.Linq; using System.Text; +using System.Threading; using System.Threading.Tasks; +using System.Diagnostics; namespace log4net.Tests.Appender; @@ -183,4 +185,82 @@ public void InterProcessLock_AcquireLock_ReleasesMutexWhenStreamIsNull() File.Delete(tempFile); } } + + /// <summary> + /// The wait for the inter process lock happens while the appender lock is held, so it has to be + /// bounded by default: a lock nobody releases would otherwise suspend all logging for good. + /// </summary> + [Test] + public void LockTimeoutMillisDefaultsToAFiniteValue() + => Assert.That(new FileAppender.InterProcessLock().LockTimeoutMillis, Is.EqualTo(10000)); + + /// <summary> + /// Timeout.Infinite restores waiting indefinitely and 0 gives up at once; any other negative + /// value has no meaning and is rejected rather than reinterpreted. + /// </summary> + [Test] + public void LockTimeoutMillisRejectsNegativeValuesExceptInfinite() + { + FileAppender.InterProcessLock lockingModel = new(); + + Assert.That(() => lockingModel.LockTimeoutMillis = -2, Throws.TypeOf<ArgumentOutOfRangeException>()); + + lockingModel.LockTimeoutMillis = Timeout.Infinite; + Assert.That(lockingModel.LockTimeoutMillis, Is.EqualTo(Timeout.Infinite)); + + lockingModel.LockTimeoutMillis = 0; + Assert.That(lockingModel.LockTimeoutMillis, Is.EqualTo(0)); + } + + /// <summary> + /// When something else holds the lock and does not let go, the event is dropped rather than the + /// logging thread being blocked forever. + /// </summary> + [Test] + [NonParallelizable] + public void AcquireLockGivesUpWhenTheLockIsHeldTooLong() + { + const string appenderFile = "log4net_lock_timeout_test"; + string tempFile = Path.GetTempFileName(); + FileAppender appender = new() { File = appenderFile }; + FileAppender.InterProcessLock lockingModel = new() + { + CurrentAppender = appender, + LockTimeoutMillis = 200 + }; + lockingModel.ActivateOptions(); + lockingModel.OpenFile(tempFile, false, Encoding.UTF8); + + using ManualResetEventSlim held = new(); + using ManualResetEventSlim release = new(); + // A mutex has to be taken and released on one thread, so the holder does both. + Task holder = Task.Run(() => + { + using Mutex contender = new(false, appenderFile); + contender.WaitOne(); + held.Set(); + release.Wait(); + contender.ReleaseMutex(); + }); + + try + { + Assert.That(held.Wait(TimeSpan.FromSeconds(10)), Is.True, "the contending thread never took the mutex"); + + Stream? stream = null; + Stopwatch stopwatch = Stopwatch.StartNew(); + LogLog.ExecuteWithoutEmittingInternalMessages(() => stream = lockingModel.AcquireLock()); + stopwatch.Stop(); + + Assert.That(stream, Is.Null, "the lock was reported as acquired while another thread held it"); + Assert.That(stopwatch.Elapsed, Is.LessThan(TimeSpan.FromSeconds(10))); + } + finally + { + release.Set(); + holder.Wait(TimeSpan.FromSeconds(10)); + lockingModel.OnClose(); + File.Delete(tempFile); + } + } } \ No newline at end of file diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index 993e2974..5887fbfe 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -576,6 +576,42 @@ public class InterProcessLock : LockingModelBase private Mutex? _mutex; private Stream? _stream; private int _recursiveWatch; + private int _lockTimeoutMillis = 10_000; + + /// <summary> + /// Gets or sets the time, in milliseconds, to wait for the lock before giving up on an event. + /// </summary> + /// <value> + /// A number of milliseconds, 0 to fail immediately when the lock is held, or + /// <see cref="Timeout.Infinite"/> to wait for as long as it takes. + /// </value> + /// <remarks> + /// <para> + /// The wait happens while the appender lock is held, so a lock nobody releases would otherwise + /// suspend every thread logging through this appender. An event that cannot get the lock in + /// time is reported and dropped instead. + /// </para> + /// <para> + /// The default value is 10000. Raise it when the file is on storage where the lock is + /// legitimately slow to obtain, such as a network share. + /// </para> + /// </remarks> + /// <exception cref="ArgumentOutOfRangeException"> + /// The value specified is negative and is not <see cref="Timeout.Infinite"/>. + /// </exception> + public int LockTimeoutMillis + { + get => _lockTimeoutMillis; + set + { + if (value < 0 && value != Timeout.Infinite) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + $"The value specified for LockTimeoutMillis is negative and is not {nameof(Timeout)}.{nameof(Timeout.Infinite)}."); + } + _lockTimeoutMillis = value; + } + } /// <summary> /// Open the file specified and prepare for logging. @@ -641,8 +677,23 @@ public override void CloseFile() { if (_mutex is not null) { - // TODO: add timeout? - _mutex.WaitOne(); + bool acquired; + try + { + acquired = _mutex.WaitOne(LockTimeoutMillis); + } + catch (AbandonedMutexException) + { + // Previous owner died without releasing; the wait succeeded and we own the mutex. + acquired = true; + } + + if (!acquired) + { + CurrentAppender?.ErrorHandler.Error( + $"Timeout after {LockTimeoutMillis}ms waiting for the inter process lock on the log file, so the logging event was not written."); + return null; + } // increment recursive watch _recursiveWatch++; diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 55b30078..a15e8f97 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -518,10 +518,32 @@ protected override void Append(LoggingEvent[] loggingEvents) protected virtual void AdjustFileBeforeAppend() { // reuse the file appenders locking model to lock the rolling + bool acquired = false; try { // if rolling should be locked, acquire the lock - _mutexForRolling?.WaitOne(); + if (_mutexForRolling is not null) + { + try + { + acquired = _mutexForRolling.WaitOne(LockTimeoutMillis); + } + catch (AbandonedMutexException) + { + // Previous owner died without releasing; the wait succeeded and we own the mutex. + acquired = true; + } + + if (!acquired) + { + // Rolling without the lock would race another process renaming the same files, so append + // to the current file instead of waiting, which would suspend every logging thread. + ErrorHandler.Error( + $"Timeout after {LockTimeoutMillis}ms waiting for the lock on rolling {File}, so this event was written without checking whether the file should roll."); + return; + } + } + if (_rollDate) { DateTime n = DateTimeStrategy.Now; @@ -541,8 +563,11 @@ protected virtual void AdjustFileBeforeAppend() } finally { - // if rolling should be locked, release the lock - _mutexForRolling?.ReleaseMutex(); + // Only when the wait succeeded: releasing a mutex this thread does not own throws. + if (acquired) + { + _mutexForRolling!.ReleaseMutex(); + } } } @@ -1516,6 +1541,39 @@ protected static DateTime NextCheckDate(DateTime currentDateTime, RollPoint roll /// </summary> private Mutex? _mutexForRolling; + private int _lockTimeoutMillis = 10_000; + + /// <summary> + /// Gets or sets the time, in milliseconds, to wait for the rolling lock before appending without + /// checking whether the file should roll. + /// </summary> + /// <value> + /// A number of milliseconds, 0 to give up immediately when the lock is held, or + /// <see cref="Timeout.Infinite"/> to wait for as long as it takes. + /// </value> + /// <remarks> + /// <para> + /// The wait happens while the appender lock is held, so a lock nobody releases would otherwise + /// suspend every thread logging through this appender. The default value is 10000. + /// </para> + /// </remarks> + /// <exception cref="ArgumentOutOfRangeException"> + /// The value specified is negative and is not <see cref="Timeout.Infinite"/>. + /// </exception> + public int LockTimeoutMillis + { + get => _lockTimeoutMillis; + set + { + if (value < 0 && value != Timeout.Infinite) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + $"The value specified for LockTimeoutMillis is negative and is not {nameof(Timeout)}.{nameof(Timeout.Infinite)}."); + } + _lockTimeoutMillis = value; + } + } + /// <summary> /// The 1st of January 1970 in UTC /// </summary> diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc index e05d8d3e..a64571d0 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc @@ -63,4 +63,36 @@ This example shows how to configure the appender to use the minimal locking mode <conversionPattern value="%date [%thread] %-5level %logger %message%newline" /> </layout> </appender> ----- \ No newline at end of file +---- + +[#fileappender-lock-timeout] +== Waiting for the lock + +`InterProcessLock` coordinates several processes writing to one file through a named mutex. +The wait for it happens while the appender lock is held, so a lock nobody releases would suspend +every thread logging through the appender. + +The wait is therefore bounded by `lockTimeoutMillis`, 10000 by default. +An event that cannot get the lock in time is reported through the error handler and dropped, and the +appender carries on with the next one. +Raise the value when the file is on storage where the lock is legitimately slow to obtain, such as a +network share, or set it to `-1` to wait for as long as it takes. + +[source,xml] +---- +<appender name="FileAppender" type="log4net.Appender.FileAppender"> + <file value="MyApp.log" /> + <appendToFile value="true" /> + <lockingModel type="log4net.Appender.FileAppender+InterProcessLock"> + <lockTimeoutMillis value="10000" /> + </lockingModel> + <layout type="log4net.Layout.PatternLayout"> + <conversionPattern value="%date [%thread] %-5level %logger %message%newline" /> + </layout> +</appender> +---- + +`RollingFileAppender` takes a second mutex around the decision to roll and has its own +`lockTimeoutMillis` for it, with the same default. +An event that cannot get that lock is written to the current file without checking whether it should +roll first, rather than waiting. \ No newline at end of file
