From 642bdd2d2cf1f9c1fa50fafd0caf88260cfb94fb Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:53:01 +0200 Subject: [PATCH 1/3] close the outgoing appenders before activating the new ones #321 - XmlHierarchyConfigurator activated a new appender while the outgoing one still held its file, so ConfigureAndWatch failed with "Unable to acquire lock on file" - regression from 592d18de (#287) - ParseAppender collects into _pendingActivations, which Configure drains once every logger has swapped - the symptom is Windows only: .NET on Linux does not enforce FileShare within a process, so the test asserts the open/close order instead --- CLAUDE.md | 4 + .../321-reconfiguration-appender-overlap.xml | 12 ++ .../XmlConfiguratorReconfigurationTest.cs | 148 ++++++++++++++++++ .../Hierarchy/XmlHierarchyConfigurator.cs | 46 +++++- 4 files changed, 203 insertions(+), 7 deletions(-) create mode 100644 src/changelog/3.5.0/321-reconfiguration-appender-overlap.xml create mode 100644 src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs diff --git a/CLAUDE.md b/CLAUDE.md index 0da68f394..793fa4f75 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -167,6 +167,10 @@ almost always be doing. Reproduced with `[TestCase("one", "\x1b[0m")]`; a single argument holding the same escape is fine, so it takes two arguments and an escape character. `AnsiColorTerminalAppenderTest` names all ten of its cases for that reason, and a filtered run there is 54 ms against 9 s for the suite. +- **A test that needs a folder takes `using AutoTempFolder folder = new();` from + `PeanutButter.Utils`**, as a local in the test method rather than a fixture field. It creates the + folder and deletes it on dispose, so no `[SetUp]`/`[TearDown]` pair and no NUnit1032. Close the + repository or appender before the scope ends, or the delete fails on Windows. - Mark a test `[NonParallelizable]` when it mutates static state (`LogLog.InternalDebugging`, a static field on a test double, a process-wide native registration). - Wrap expected internal logging in `LogLog.ExecuteWithoutEmittingInternalMessages(...)` and capture diff --git a/src/changelog/3.5.0/321-reconfiguration-appender-overlap.xml b/src/changelog/3.5.0/321-reconfiguration-appender-overlap.xml new file mode 100644 index 000000000..3ba6bd696 --- /dev/null +++ b/src/changelog/3.5.0/321-reconfiguration-appender-overlap.xml @@ -0,0 +1,12 @@ + + + + + Stop a reconfiguration from opening a resource the outgoing + appender still holds. Since 3.3.1 the new appenders were activated before the old ones were + closed, so `ConfigureAndWatch` with a `FileAppender` failed to acquire the lock on its own log + file. Activation waits for the swap now (reported by @urs-hart, fixed by @FreeAndNil) + diff --git a/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs b/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs new file mode 100644 index 000000000..b53731c81 --- /dev/null +++ b/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs @@ -0,0 +1,148 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; +using System.Collections.Generic; +using System.IO; +using System.Text; + +using log4net.Appender; +using log4net.Config; +using log4net.Repository; +using log4net.Util; + +using NUnit.Framework; + +using PeanutButter.Utils; + +namespace log4net.Tests.Config; + +/// +/// Reconfiguring must not leave two instances holding one file. +/// +[TestFixture] +[NonParallelizable] +public sealed class XmlConfiguratorReconfigurationTest +{ + /// + /// Records every open and close call, so a test can assert their order. + /// + /// Public because the configurator instantiates it by name. + public sealed class RecordingLock : FileAppender.LockingModelBase + { + /// Open and close calls across all instances, in order. + internal static List Calls { get; } = []; + + private string _tag = "?"; + + /// + public override void ActivateOptions() + { } + + /// + public override void OpenFile(string filename, bool append, Encoding encoding) + { + _tag = CurrentAppender?.Name ?? "?"; + Calls.Add($"open {_tag}"); + } + + /// + public override void CloseFile() => Calls.Add($"close {_tag}"); + + /// + public override Stream? AcquireLock() => Stream.Null; + + /// + public override void ReleaseLock() + { } + + /// + public override void OnClose() + { } + } + + private ILoggerRepository? _repository; + + /// The call log is static, so it carries over between the tests in this fixture. + [SetUp] + public void SetUp() => RecordingLock.Calls.Clear(); + + /// Closes the appenders, in case the test left the repository running. + [TearDown] + public void TearDown() + { + if (_repository is not null) + { + LogLog.ExecuteWithoutEmittingInternalMessages(_repository.Shutdown); + _repository = null; + } + } + + /// + /// Configuring the live repository again is what the file watcher does on every change. The + /// incoming appender used to open the file while the outgoing one still held it. + /// + [Test] + public void ReconfiguringClosesTheOutgoingAppenderBeforeOpeningTheNewOne() + { + using AutoTempFolder folder = new(); + FileInfo configFile = new(Path.Combine(folder.Path, "log.config")); + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + Write(configFile, folder, "first"); + XmlConfigurator.Configure(_repository, configFile); + + Write(configFile, folder, "second"); + XmlConfigurator.Configure(_repository, configFile); + + _repository.Shutdown(); + _repository = null; + }); + + Assert.That(RecordingLock.Calls, + Is.EqualTo(new[] { "open first", "close first", "open second", "close second" })); + } + + /// Writes a configuration naming its single appender after the pass. + private static void Write(FileInfo configFile, AutoTempFolder folder, string appenderName) + { + using (StreamWriter writer = configFile.CreateText()) + { + writer.Write($""" + + + + + + + + + + + + + + """); + } + + configFile.Refresh(); + } +} diff --git a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs index 32df0c2d0..0d270b4e9 100644 --- a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs +++ b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs @@ -149,6 +149,9 @@ public void Configure(XmlElement? element) // A configuration is about to happen, so we can emit the warning again hierarchy.EmittedNoAppenderWarning = false; + // Activate only after every logger has swapped, so nothing opens what the old appender holds. + _deferActivation = true; + /* Building Appender objects, placing them in a local namespace for future reference */ @@ -205,9 +208,24 @@ public void Configure(XmlElement? element) } } + ActivatePendingAppenders(); + // Done reading config } + /// + /// Activates the appenders parsed in this pass, in creation order. + /// + private void ActivatePendingAppenders() + { + _deferActivation = false; + foreach (IOptionHandler optionHandler in _pendingActivations) + { + optionHandler.ActivateOptions(); + } + _pendingActivations.Clear(); + } + /// /// Parse appenders by IDREF. /// @@ -319,7 +337,14 @@ public void Configure(XmlElement? element) if (appender is IOptionHandler optionHandler) { - optionHandler.ActivateOptions(); + if (_deferActivation) + { + _pendingActivations.Add(optionHandler); + } + else + { + optionHandler.ActivateOptions(); + } } LogLog.Debug(_declaringType, $"Created Appender [{appenderName}]"); @@ -406,9 +431,8 @@ protected void ParseChildrenOfLoggerElement(XmlElement catElement, Logger log, b log.EnsureNotNull(); catElement.EnsureNotNull(); - // Phase 1: resolve all new appenders from XML *before* touching the - // live logger. This avoids the window where the logger has no appenders. - List newAppenders = new(); + // Phase 1: resolve from XML before touching the live logger, which keeps its appenders. + List newAppenders = []; foreach (XmlNode currentNode in catElement.ChildNodes) { @@ -442,9 +466,7 @@ protected void ParseChildrenOfLoggerElement(XmlElement catElement, Logger log, b } } - // Phase 2: atomic swap — replace all appenders in one writer lock so - // the logger is never in a zero-appender state for longer than it takes - // to acquire and release the lock (microseconds, not milliseconds). + // Phase 2: swap in one writer lock, closing the outgoing appenders. log.ReplaceAppenders(newAppenders); if (log is IOptionHandler optionHandler) @@ -1052,6 +1074,16 @@ private static Hashtable CreateCaseInsensitiveWrapper(IDictionary dict) /// private readonly Dictionary _appenderBag = new(StringComparer.Ordinal); + /// + /// Appenders parsed in this pass and not activated yet. + /// + private readonly List _pendingActivations = []; + + /// + /// Set by alone: defers activation in . + /// + private bool _deferActivation; + /// /// The fully qualified type of the XmlHierarchyConfigurator class. /// From d512f94832c7e70c79f66a8cbb4ebaf41dabe9cb Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 22:41:29 +0200 Subject: [PATCH 2/3] point the npm changelog entry at its own pull request - the entry claimed #321, which is the FileAppender reconfiguration issue, filed a day after this landed - the Antora dependency work came through #320, so the id, the link and the file name follow that --- ...npm-dependencies.xml => 320-centralize-npm-dependencies.xml} | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) rename src/changelog/3.5.0/{321-centralize-npm-dependencies.xml => 320-centralize-npm-dependencies.xml} (89%) diff --git a/src/changelog/3.5.0/321-centralize-npm-dependencies.xml b/src/changelog/3.5.0/320-centralize-npm-dependencies.xml similarity index 89% rename from src/changelog/3.5.0/321-centralize-npm-dependencies.xml rename to src/changelog/3.5.0/320-centralize-npm-dependencies.xml index 8351a7c10..7fce476ea 100644 --- a/src/changelog/3.5.0/321-centralize-npm-dependencies.xml +++ b/src/changelog/3.5.0/320-centralize-npm-dependencies.xml @@ -3,7 +3,7 @@ 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"> - + The site build now takes its Antora dependencies from the `gha/v0` branch of `logging-parent`, which is where all Apache Logging projects now manage them. The `js-yaml` override and the committed `package-lock.json` are gone with it (reported by From 93ed24f3e4e0d1a251ca520b6e2a89f8535149de Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 22 Sep 2026 16:31:38 +0200 Subject: [PATCH 3/3] discard an appender that fails to activate #321 - deferring ActivateOptions moved it out of the ParseAppender catch - the failure is logged and the appender detached and closed - children are unwired first, so a container does not take them down --- .../XmlConfiguratorReconfigurationTest.cs | 183 +++++++++++++++++- .../Hierarchy/XmlHierarchyConfigurator.cs | 59 +++++- 2 files changed, 237 insertions(+), 5 deletions(-) diff --git a/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs b/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs index b53731c81..777b8de8c 100644 --- a/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs +++ b/src/log4net.Tests/Config/XmlConfiguratorReconfigurationTest.cs @@ -20,10 +20,12 @@ using System; using System.Collections.Generic; using System.IO; +using System.Linq; using System.Text; using log4net.Appender; using log4net.Config; +using log4net.Core; using log4net.Repository; using log4net.Util; @@ -77,11 +79,44 @@ public override void OnClose() { } } + /// Fails to activate, the way an appender does when a required option is missing. + /// Public because the configurator instantiates it by name. + public sealed class ThrowingAppender : AppenderSkeleton + { + /// Whether the configurator closed the appender it could not activate. + internal static bool Closed { get; private set; } + + /// Clears the static state this appender records. + internal static void Reset() => Closed = false; + + /// + public override void ActivateOptions() => throw new InvalidOperationException("no RemoteAddress"); + + /// + protected override void OnClose() => Closed = true; + + /// + protected override void Append(LoggingEvent loggingEvent) + { } + } + + /// Fails to activate while holding an appender that a logger also holds directly. + /// Public because the configurator instantiates it by name. + public sealed class ThrowingForwarder : ForwardingAppender + { + /// + public override void ActivateOptions() => throw new InvalidOperationException("no target"); + } + private ILoggerRepository? _repository; /// The call log is static, so it carries over between the tests in this fixture. [SetUp] - public void SetUp() => RecordingLock.Calls.Clear(); + public void SetUp() + { + RecordingLock.Calls.Clear(); + ThrowingAppender.Reset(); + } /// Closes the appenders, in case the test left the repository running. [TearDown] @@ -121,6 +156,152 @@ public void ReconfiguringClosesTheOutgoingAppenderBeforeOpeningTheNewOne() Is.EqualTo(new[] { "open first", "close first", "open second", "close second" })); } + /// + /// Activation runs after the logger has taken the appender, so a failure has to be caught and + /// the appender taken back off the logger rather than escaping the configuration pass. + /// + [Test] + public void AnAppenderThatCannotActivateIsDetachedAndClosed() + { + using AutoTempFolder folder = new(); + FileInfo configFile = new(Path.Combine(folder.Path, "log.config")); + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + WriteThrowing(configFile); + XmlConfigurator.Configure(_repository, configFile); + }); + + Assert.That(ThrowingAppender.Closed, Is.True); + Assert.That(_repository.GetAppenders(), Is.Empty); + } + + /// + /// The appenders are activated in one loop, so a failure in it must not cost the appenders + /// behind it their activation. + /// + [Test] + public void AFailedActivationDoesNotStopTheOnesBehindIt() + { + using AutoTempFolder folder = new(); + FileInfo configFile = new(Path.Combine(folder.Path, "log.config")); + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + WriteThrowingThenWorking(configFile, folder); + XmlConfigurator.Configure(_repository, configFile); + }); + + Assert.That(RecordingLock.Calls, Is.EqualTo(new[] { "open working" })); + Assert.That(_repository.GetAppenders().Select(a => a.Name), Is.EqualTo(new[] { "working" })); + } + + /// + /// Closing a container closes what it holds, so discarding one that failed to activate must not + /// take down an appender a logger still holds directly. + /// + [Test] + public void DiscardingAContainerLeavesItsChildrenOpen() + { + using AutoTempFolder folder = new(); + FileInfo configFile = new(Path.Combine(folder.Path, "log.config")); + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + WriteThrowingForwarder(configFile, folder); + XmlConfigurator.Configure(_repository, configFile); + }); + + Assert.That(RecordingLock.Calls, Is.EqualTo(new[] { "open working" })); + Assert.That(_repository.GetAppenders().Select(a => a.Name), Is.EqualTo(new[] { "working" })); + } + + /// Writes a configuration whose single appender throws on activation. + private static void WriteThrowing(FileInfo configFile) + { + using (StreamWriter writer = configFile.CreateText()) + { + writer.Write(""" + + + + + + + + + + + + """); + } + + configFile.Refresh(); + } + + /// Writes a configuration whose first appender throws and whose second one works. + private static void WriteThrowingThenWorking(FileInfo configFile, AutoTempFolder folder) + { + using (StreamWriter writer = configFile.CreateText()) + { + writer.Write($""" + + + + + + + + + + + + + + + + + + + + """); + } + + configFile.Refresh(); + } + + /// Writes a configuration whose failing forwarder holds the appender root holds. + private static void WriteThrowingForwarder(FileInfo configFile, AutoTempFolder folder) + { + using (StreamWriter writer = configFile.CreateText()) + { + writer.Write($""" + + + + + + + + + + + + + + + + + + """); + } + + configFile.Refresh(); + } + /// Writes a configuration naming its single appender after the pass. private static void Write(FileInfo configFile, AutoTempFolder folder, string appenderName) { diff --git a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs index 0d270b4e9..8e868b076 100644 --- a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs +++ b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs @@ -219,13 +219,64 @@ public void Configure(XmlElement? element) private void ActivatePendingAppenders() { _deferActivation = false; - foreach (IOptionHandler optionHandler in _pendingActivations) + foreach (IAppender appender in _pendingActivations) { - optionHandler.ActivateOptions(); + try + { + appender.EnsureIs().ActivateOptions(); + } + catch (Exception e) when (!e.IsFatal()) + { + LogLog.Error(_declaringType, $"Could not activate Appender [{appender.Name}]. Reported error follows.", e); + DiscardAppender(appender); + } } _pendingActivations.Clear(); } + /// + /// Detaches from everything this pass attached it to and closes it. + /// + private void DiscardAppender(IAppender appender) + { + try + { + _appenderBag.Remove(appender.Name); + + hierarchy.Root.RemoveAppender(appender); + foreach (Logger logger in hierarchy.GetCurrentLoggers().OfType()) + { + logger.RemoveAppender(appender); + } + foreach (IAppenderAttachable container in _appenderBag.Values.OfType()) + { + container.RemoveAppender(appender); + } + + // Closing a container closes its children, which a logger may still hold. + if (appender is IAppenderAttachable attachable) + { + foreach (IAppender child in attachable.Appenders.ToArray()) + { + attachable.RemoveAppender(child); + } + } + } + catch (Exception e) when (!e.IsFatal()) + { + LogLog.Error(_declaringType, "Could not detach an Appender that failed to activate.", e); + } + + try + { + appender.Close(); + } + catch (Exception e) when (!e.IsFatal()) + { + LogLog.Error(_declaringType, "Could not close an Appender that failed to activate.", e); + } + } + /// /// Parse appenders by IDREF. /// @@ -339,7 +390,7 @@ private void ActivatePendingAppenders() { if (_deferActivation) { - _pendingActivations.Add(optionHandler); + _pendingActivations.Add(appender); } else { @@ -1077,7 +1128,7 @@ private static Hashtable CreateCaseInsensitiveWrapper(IDictionary dict) /// /// Appenders parsed in this pass and not activated yet. /// - private readonly List _pendingActivations = []; + private readonly List _pendingActivations = []; /// /// Set by alone: defers activation in .