From d9cb524067ac5c18402246e92f6ea7f6b5f21bc0 Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Wed, 22 Apr 2026 21:01:24 +0200 Subject: [PATCH 1/9] Add the repro project from #292 --- .../Log4NetConcurrencyRepro.csproj | 18 +++ .../LoggingConcurrencyTests.cs | 112 ++++++++++++++++++ src/Log4NetConcurrencyRepro/script.ps1 | 32 +++++ 3 files changed, 162 insertions(+) create mode 100644 src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj create mode 100644 src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs create mode 100644 src/Log4NetConcurrencyRepro/script.ps1 diff --git a/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj b/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj new file mode 100644 index 00000000..20c6c268 --- /dev/null +++ b/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj @@ -0,0 +1,18 @@ + + + net472;net10.0-windows + false + true + 3.3.0 + + + + + + + + all + runtime; build; native; contentfiles; analyzers; buildtransitive + + + \ No newline at end of file diff --git a/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs b/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs new file mode 100644 index 00000000..92abd26c --- /dev/null +++ b/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs @@ -0,0 +1,112 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using log4net; +using log4net.Appender; +using log4net.Core; +using log4net.Layout; +using log4net.Repository; +using log4net.Repository.Hierarchy; +using Xunit; + +namespace Log4NetConcurrencyRepro +{ + public class LoggingConcurrencyTests : IDisposable + { + private readonly TestMemoryAppender _memoryAppender; + private readonly ILoggerRepository _repository; + + public LoggingConcurrencyTests() + { + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + _memoryAppender = new TestMemoryAppender(); + _memoryAppender.Layout = new PatternLayout("%message"); + _memoryAppender.ActivateOptions(); + + var hierarchy = (Hierarchy)_repository; + hierarchy.Root.AddAppender(_memoryAppender); + hierarchy.Root.Level = Level.All; + hierarchy.Configured = true; + } + + [Fact] + public void Logging_DuringHighConcurrency_ShouldNotLoseMessages() + { + const int messageCount = 400; + const int loggerCount = 20; + + // alt b: var loggers = Enumerable.Range(0, loggerCount).Select(i => LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + i)).ToArray(); + + Parallel.For(0, messageCount, i => + { + // alt b: var logger = loggers[i % loggerCount]; + var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + (i % loggerCount)); + logger.Info("High concurrency message " + i); + }); + + Assert.Equal(messageCount, _memoryAppender.GetAppendCount()); + + var events = _memoryAppender.GetEvents(); + Assert.Equal(messageCount, events.Length); + + for (var i = 0; i < messageCount; i++) + { + var expectedMessage = "High concurrency message " + i; + Assert.Contains(events, e => e.RenderedMessage == expectedMessage); + } + } + + public void Dispose() + { + _memoryAppender.Clear(); + _repository.Shutdown(); + } + + private sealed class TestMemoryAppender : AppenderSkeleton + { + private readonly List _events = new List(); + private readonly object _lock = new object(); + private int _appendCount; + + protected override void Append(LoggingEvent loggingEvent) + { + Interlocked.Increment(ref _appendCount); + + if (loggingEvent == null) + return; + + loggingEvent.Fix = FixFlags.All; + + lock (_lock) + { + _events.Add(loggingEvent); + } + } + + public int GetAppendCount() + { + return Volatile.Read(ref _appendCount); + } + + public LoggingEvent[] GetEvents() + { + lock (_lock) + { + return _events.ToArray(); + } + } + + public void Clear() + { + lock (_lock) + { + _events.Clear(); + _appendCount = 0; + } + } + } + } +} \ No newline at end of file diff --git a/src/Log4NetConcurrencyRepro/script.ps1 b/src/Log4NetConcurrencyRepro/script.ps1 new file mode 100644 index 00000000..f6bae2c3 --- /dev/null +++ b/src/Log4NetConcurrencyRepro/script.ps1 @@ -0,0 +1,32 @@ +function BuildAndTest([string]$tfm, [string]$l4n) { + "" + "************************************************************" + "*** Running $l4n on $tfm" + "*** " + remove-item .\bin,.\obj -rec -ea 0 + dotnet build .\Log4NetConcurrencyRepro.csproj -c Release -f $tfm -p Log4NetVersion=$l4n + 1..20 | + %{ $testok = 0; $testnok = 0 } ` + { dotnet vstest .\bin\Release\$tfm\Log4NetConcurrencyRepro.dll; if (!$lastexitcode) { $testok++ } else { $testnok++ } } ` + { "***`n***`n*** Completed $l4n on $tfm. Outcome: OK=$testok, NOK=$testnok`n***" + $script:result += "$l4n on $tfm : `tOK=$testok, NOK=$testnok" + } + "" +} + +$result = @() + +BuildAndTest 'net472' '3.3.0' +BuildAndTest 'net472' '2.0.14' +BuildAndTest 'net10.0-windows' '3.3.0' +BuildAndTest 'net10.0-windows' '2.0.14' +BuildAndTest 'net472' '3.0.4' +BuildAndTest 'net472' '2.0.17' +BuildAndTest 'net10.0-windows' '3.0.4' +BuildAndTest 'net10.0-windows' '2.0.17' + +"" +"************************************************************" +"*** Overall results:" +$result +"" \ No newline at end of file From d032f463271d89897dd2b72f811c1ec70d9d2594 Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 25 Apr 2026 12:54:38 +0200 Subject: [PATCH 2/9] Add the repro for #292 as test --- .../Log4NetConcurrencyRepro.csproj | 18 --- .../LoggingConcurrencyTests.cs | 112 ------------------ src/Log4NetConcurrencyRepro/script.ps1 | 32 ----- .../Hierarchy/LoggingConcurrencyTest.cs | 94 +++++++++++++++ 4 files changed, 94 insertions(+), 162 deletions(-) delete mode 100644 src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj delete mode 100644 src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs delete mode 100644 src/Log4NetConcurrencyRepro/script.ps1 create mode 100644 src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs diff --git a/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj b/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj deleted file mode 100644 index 20c6c268..00000000 --- a/src/Log4NetConcurrencyRepro/Log4NetConcurrencyRepro.csproj +++ /dev/null @@ -1,18 +0,0 @@ - - - net472;net10.0-windows - false - true - 3.3.0 - - - - - - - - all - runtime; build; native; contentfiles; analyzers; buildtransitive - - - \ No newline at end of file diff --git a/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs b/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs deleted file mode 100644 index 92abd26c..00000000 --- a/src/Log4NetConcurrencyRepro/LoggingConcurrencyTests.cs +++ /dev/null @@ -1,112 +0,0 @@ -using System; -using System.Collections.Generic; -using System.Linq; -using System.Threading; -using System.Threading.Tasks; -using log4net; -using log4net.Appender; -using log4net.Core; -using log4net.Layout; -using log4net.Repository; -using log4net.Repository.Hierarchy; -using Xunit; - -namespace Log4NetConcurrencyRepro -{ - public class LoggingConcurrencyTests : IDisposable - { - private readonly TestMemoryAppender _memoryAppender; - private readonly ILoggerRepository _repository; - - public LoggingConcurrencyTests() - { - _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); - - _memoryAppender = new TestMemoryAppender(); - _memoryAppender.Layout = new PatternLayout("%message"); - _memoryAppender.ActivateOptions(); - - var hierarchy = (Hierarchy)_repository; - hierarchy.Root.AddAppender(_memoryAppender); - hierarchy.Root.Level = Level.All; - hierarchy.Configured = true; - } - - [Fact] - public void Logging_DuringHighConcurrency_ShouldNotLoseMessages() - { - const int messageCount = 400; - const int loggerCount = 20; - - // alt b: var loggers = Enumerable.Range(0, loggerCount).Select(i => LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + i)).ToArray(); - - Parallel.For(0, messageCount, i => - { - // alt b: var logger = loggers[i % loggerCount]; - var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + (i % loggerCount)); - logger.Info("High concurrency message " + i); - }); - - Assert.Equal(messageCount, _memoryAppender.GetAppendCount()); - - var events = _memoryAppender.GetEvents(); - Assert.Equal(messageCount, events.Length); - - for (var i = 0; i < messageCount; i++) - { - var expectedMessage = "High concurrency message " + i; - Assert.Contains(events, e => e.RenderedMessage == expectedMessage); - } - } - - public void Dispose() - { - _memoryAppender.Clear(); - _repository.Shutdown(); - } - - private sealed class TestMemoryAppender : AppenderSkeleton - { - private readonly List _events = new List(); - private readonly object _lock = new object(); - private int _appendCount; - - protected override void Append(LoggingEvent loggingEvent) - { - Interlocked.Increment(ref _appendCount); - - if (loggingEvent == null) - return; - - loggingEvent.Fix = FixFlags.All; - - lock (_lock) - { - _events.Add(loggingEvent); - } - } - - public int GetAppendCount() - { - return Volatile.Read(ref _appendCount); - } - - public LoggingEvent[] GetEvents() - { - lock (_lock) - { - return _events.ToArray(); - } - } - - public void Clear() - { - lock (_lock) - { - _events.Clear(); - _appendCount = 0; - } - } - } - } -} \ No newline at end of file diff --git a/src/Log4NetConcurrencyRepro/script.ps1 b/src/Log4NetConcurrencyRepro/script.ps1 deleted file mode 100644 index f6bae2c3..00000000 --- a/src/Log4NetConcurrencyRepro/script.ps1 +++ /dev/null @@ -1,32 +0,0 @@ -function BuildAndTest([string]$tfm, [string]$l4n) { - "" - "************************************************************" - "*** Running $l4n on $tfm" - "*** " - remove-item .\bin,.\obj -rec -ea 0 - dotnet build .\Log4NetConcurrencyRepro.csproj -c Release -f $tfm -p Log4NetVersion=$l4n - 1..20 | - %{ $testok = 0; $testnok = 0 } ` - { dotnet vstest .\bin\Release\$tfm\Log4NetConcurrencyRepro.dll; if (!$lastexitcode) { $testok++ } else { $testnok++ } } ` - { "***`n***`n*** Completed $l4n on $tfm. Outcome: OK=$testok, NOK=$testnok`n***" - $script:result += "$l4n on $tfm : `tOK=$testok, NOK=$testnok" - } - "" -} - -$result = @() - -BuildAndTest 'net472' '3.3.0' -BuildAndTest 'net472' '2.0.14' -BuildAndTest 'net10.0-windows' '3.3.0' -BuildAndTest 'net10.0-windows' '2.0.14' -BuildAndTest 'net472' '3.0.4' -BuildAndTest 'net472' '2.0.17' -BuildAndTest 'net10.0-windows' '3.0.4' -BuildAndTest 'net10.0-windows' '2.0.17' - -"" -"************************************************************" -"*** Overall results:" -$result -"" \ No newline at end of file diff --git a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs new file mode 100644 index 00000000..ed2ca811 --- /dev/null +++ b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs @@ -0,0 +1,94 @@ +#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.Threading.Tasks; +using log4net.Appender; +using log4net.Core; +using log4net.Repository; +using log4net.Repository.Hierarchy; +using NUnit.Framework; + +namespace log4net.Tests.Hierarchy; + +/// +/// Concurrency tests for . +/// Regression test for LOG4NET-292. +/// +[TestFixture] +public class LoggingConcurrencyTest +{ + private MemoryAppender _memoryAppender = null!; + private ILoggerRepository _repository = null!; + + [SetUp] + public void SetUp() + { + _repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + _memoryAppender = new MemoryAppender(); + _memoryAppender.ActivateOptions(); + + var hierarchy = (log4net.Repository.Hierarchy.Hierarchy)_repository; + hierarchy.Root.AddAppender(_memoryAppender); + hierarchy.Root.Level = Level.All; + hierarchy.Configured = true; + } + + [TearDown] + public void TearDown() + { + _memoryAppender.Clear(); + _repository.Shutdown(); + } + + /// + /// Verifies that no messages are lost when multiple threads call + /// with the same logger + /// name concurrently (LOG4NET-292). + /// + [Test] + public void GetLogger_UnderHighConcurrency_ShouldNotLoseMessages() + { + const int messageCount = 400; + const int loggerCount = 20; + const int repetitions = 20; + + for (var run = 0; run < repetitions; run++) + { + _memoryAppender.Clear(); + + Parallel.For(0, messageCount, i => + { + var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + (i % loggerCount)); + logger.Info("High concurrency message " + i); + }); + + var events = _memoryAppender.GetEvents(); + Assert.That(events, Has.Length.EqualTo(messageCount), $"Run {run}: expected {messageCount} messages"); + + for (var i = 0; i < messageCount; i++) + { + var expectedMessage = "High concurrency message " + i; + Assert.That(events, Has.Some.Matches(e => e.RenderedMessage == expectedMessage), + $"Run {run}: Missing message: {expectedMessage}"); + } + } + } +} From 3a4eee591deaf9c93a9bfff5be60a0e9c67f5bcb Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Wed, 29 Apr 2026 08:52:55 +0200 Subject: [PATCH 3/9] Add dotted logers tests and GetCurrentLoggers tests Co-authored-by: Copilot --- src/log4net.Tests/Hierarchy/HierarchyTest.cs | 40 ++++ .../Hierarchy/LoggingConcurrencyTest.cs | 185 +++++++++++++++++- 2 files changed, 224 insertions(+), 1 deletion(-) diff --git a/src/log4net.Tests/Hierarchy/HierarchyTest.cs b/src/log4net.Tests/Hierarchy/HierarchyTest.cs index 16bbb9ae..065f7a58 100644 --- a/src/log4net.Tests/Hierarchy/HierarchyTest.cs +++ b/src/log4net.Tests/Hierarchy/HierarchyTest.cs @@ -23,6 +23,7 @@ using System.Threading.Tasks; using System.Xml; using log4net.Config; +using log4net.Core; using log4net.Repository; using log4net.Tests.Appender; using NUnit.Framework; @@ -221,4 +222,43 @@ public void CreateChildLoggersMultiThreaded() Parallel.For(0, 100, i => Assert.That(rep.GetLogger($"A.{i}").Name, Is.EqualTo($"A.{i}"))); } + + [Test] + public void GetCurrentLoggers_EmptyHierarchy_ReturnsEmptyArray() + { + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + + Assert.That(rep.GetCurrentLoggers(), Is.Empty); + } + + [Test] + public void GetCurrentLoggers_ReturnsCreatedLoggers() + { + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + rep.GetLogger("Foo"); + rep.GetLogger("Bar"); + + string[] names = Array.ConvertAll(rep.GetCurrentLoggers(), l => l.Name); + Assert.That(names, Is.EquivalentTo(new[] { "Foo", "Bar" })); + } + + [Test] + public void GetCurrentLoggers_DoesNotIncludeRoot() + { + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + rep.GetLogger("Foo"); + + Assert.That(rep.GetCurrentLoggers(), Has.None.Property(nameof(ILogger.Name)).EqualTo("root")); + } + + [Test] + public void GetCurrentLoggers_DoesNotIncludeProvisionNodes() + { + // Creating "A.B.C" before "A" and "A.B" causes provision nodes to be inserted for the ancestors. + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + rep.GetLogger("A.B.C"); + + string[] names = Array.ConvertAll(rep.GetCurrentLoggers(), l => l.Name); + Assert.That(names, Is.EquivalentTo(new[] { "A.B.C" })); + } } \ No newline at end of file diff --git a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs index ed2ca811..4a007935 100644 --- a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs +++ b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs @@ -18,6 +18,7 @@ #endregion using System; +using System.Threading; using System.Threading.Tasks; using log4net.Appender; using log4net.Core; @@ -76,7 +77,7 @@ public void GetLogger_UnderHighConcurrency_ShouldNotLoseMessages() Parallel.For(0, messageCount, i => { - var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + (i % loggerCount)); + var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-" + run + "-" + (i % loggerCount)); logger.Info("High concurrency message " + i); }); @@ -91,4 +92,186 @@ public void GetLogger_UnderHighConcurrency_ShouldNotLoseMessages() } } } + + [Test] + public void GetLogger_WithDottedNamesUnderHighConcurrency_ShouldNotLoseMessages() + { + const int messageCount = 400; + const int loggerCount = 40; + const int repetitions = 20; + + for (var run = 0; run < repetitions; run++) + { + _memoryAppender.Clear(); + string loggerPrefix = "DottedConcurrencyTest-" + run; + + Parallel.For(0, messageCount, i => + { + var logger = LogManager.GetLogger(_repository.Name, GetDottedLoggerName(loggerPrefix, i % loggerCount)); + logger.Info("Dotted concurrency message " + i); + }); + + var events = _memoryAppender.GetEvents(); + Assert.That(events, Has.Length.EqualTo(messageCount), $"Run {run}: expected {messageCount} messages"); + + for (var i = 0; i < messageCount; i++) + { + var expectedMessage = "Dotted concurrency message " + i; + Assert.That(events, Has.Some.Matches(e => e.RenderedMessage == expectedMessage), + $"Run {run}: Missing message: {expectedMessage}"); + } + } + } + + [Test] + public void GetLogger_WhenCreationEventThrows_ShouldNotBlockSubsequentCalls() + { + var hierarchy = (log4net.Repository.Hierarchy.Hierarchy)_repository; + var expectedException = new InvalidOperationException("Logger creation event failed"); + string loggerName = "ThrowingEventLogger-" + Guid.NewGuid(); + + void ThrowingHandler(object sender, LoggerCreationEventArgs args) => throw expectedException; + + hierarchy.LoggerCreatedEvent += ThrowingHandler; + try + { + var actualException = Assert.Throws(() => hierarchy.GetLogger(loggerName)); + Assert.That(actualException, Is.SameAs(expectedException)); + } + finally + { + hierarchy.LoggerCreatedEvent -= ThrowingHandler; + } + + Task getLoggerTask = Task.Run(() => (Logger)hierarchy.GetLogger(loggerName)); + Assert.That(getLoggerTask.Wait(TimeSpan.FromSeconds(5)), Is.True, + "A failed logger creation event left the logger permanently not ready."); + + Logger logger = getLoggerTask.GetAwaiter().GetResult(); + logger.Log(Level.Info, "Message after failed creation event", null); + + Assert.That(_memoryAppender.GetEvents(), Has.Some.Matches( + e => e.RenderedMessage == "Message after failed creation event")); + } + + [Test] + public void GetLogger_WhenParentLoggerIsStillRegistering_ShouldWaitBeforeReturningChild() + { + string testId = Guid.NewGuid().ToString("N"); + string parentName = "ConcurrentParent-" + testId; + string firstChildName = parentName + ".FirstChild"; + string secondChildName = parentName + ".SecondChild"; + + using ManualResetEventSlim parentAssignmentStarted = new(); + using ManualResetEventSlim allowParentAssignment = new(); + + using BlockingLoggerFactory factory = new(parentName, firstChildName, secondChildName, + parentAssignmentStarted, allowParentAssignment); + log4net.Repository.Hierarchy.Hierarchy hierarchy = new(factory) { Name = "Hierarchy-" + testId }; + MemoryAppender memoryAppender = new(); + memoryAppender.ActivateOptions(); + hierarchy.Root.AddAppender(memoryAppender); + hierarchy.Root.Level = Level.All; + hierarchy.Configured = true; + + try + { + hierarchy.GetLogger(firstChildName); + + Task parentTask = Task.Run(() => (Logger)hierarchy.GetLogger(parentName)); + Assert.That(parentAssignmentStarted.Wait(TimeSpan.FromSeconds(5)), Is.True, + "The parent logger did not reach child relinking."); + + Task childLogTask = Task.Run(() => + { + Logger childLogger = (Logger)hierarchy.GetLogger(secondChildName); + childLogger.Log(Level.Info, "Message from child while parent registers", null); + }); + + Assert.That(factory.SecondChildCreated.Wait(TimeSpan.FromSeconds(5)), Is.True, + "The second child logger was not created."); + Assert.That(childLogTask.Wait(TimeSpan.FromMilliseconds(100)), Is.False, + "The child logger was returned before its parent logger was ready."); + + allowParentAssignment.Set(); + + Assert.That(parentTask.Wait(TimeSpan.FromSeconds(5)), Is.True); + Assert.That(childLogTask.Wait(TimeSpan.FromSeconds(5)), Is.True); + parentTask.GetAwaiter().GetResult(); + childLogTask.GetAwaiter().GetResult(); + + Assert.That(memoryAppender.GetEvents(), Has.Some.Matches( + e => e.RenderedMessage == "Message from child while parent registers")); + } + finally + { + allowParentAssignment.Set(); + memoryAppender.Clear(); + hierarchy.Shutdown(); + } + } + + private static string GetDottedLoggerName(string prefix, int index) + { + int group = index / 4; + string groupName = prefix + ".Group" + group; + + return (index % 4) switch + { + 0 => groupName, + 1 => groupName + ".Child", + 2 => groupName + ".Child.Grandchild", + _ => groupName + ".Sibling" + }; + } + + private sealed class BlockingLoggerFactory( + string parentName, + string firstChildName, + string secondChildName, + ManualResetEventSlim parentAssignmentStarted, + ManualResetEventSlim allowParentAssignment) : ILoggerFactory, IDisposable + { + public ManualResetEventSlim SecondChildCreated { get; } = new(); + + public Logger CreateLogger(ILoggerRepository repository, string? name) + { + if (name is null) + { + return new RootLogger(repository.LevelMap.LookupWithDefault(Level.Debug)); + } + + if (name == secondChildName) + { + SecondChildCreated.Set(); + } + + return new BlockingLogger(name, parentName, firstChildName, parentAssignmentStarted, allowParentAssignment); + } + + public void Dispose() => SecondChildCreated.Dispose(); + } + + private sealed class BlockingLogger( + string name, + string parentName, + string blockedChildName, + ManualResetEventSlim parentAssignmentStarted, + ManualResetEventSlim allowParentAssignment) : Logger(name) + { + public override Logger? Parent + { + get => base.Parent; + set + { + if (Name == blockedChildName && value?.Name == parentName) + { + parentAssignmentStarted.Set(); + allowParentAssignment.Wait(TimeSpan.FromSeconds(5)); + } + + base.Parent = value; + } + } + } } From 3fd4b31cbbfac8591333c8318b40ac3dd2b277ae Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 2 May 2026 13:07:23 +0200 Subject: [PATCH 4/9] Use one lock approach and add marker interface --- src/log4net/Repository/Hierarchy/Hierarchy.cs | 115 ++++++++++++------ src/log4net/Repository/Hierarchy/Logger.cs | 2 +- .../Repository/Hierarchy/ProvisionNode.cs | 6 +- 3 files changed, 82 insertions(+), 41 deletions(-) diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index 452b5d7f..17937552 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -88,7 +88,7 @@ public class LoggerCreationEventArgs(Logger log) : EventArgs public class Hierarchy(PropertiesDictionary properties, ILoggerFactory loggerFactory) : LoggerRepositorySkeleton(properties), IBasicRepositoryConfigurator, IXmlRepositoryConfigurator { - private readonly ConcurrentDictionary _loggers = new(LoggerKey.ComparerInstance); + private readonly ConcurrentDictionary _loggers = new(LoggerKey.ComparerInstance); private ILoggerFactory _defaultFactory = loggerFactory.EnsureNotNull(); private Logger? _rootLogger; @@ -108,7 +108,7 @@ public class Hierarchy(PropertiesDictionary properties, ILoggerFactory loggerFac /// /// Default constructor /// - public Hierarchy() + public Hierarchy() : this(new DefaultLoggerFactory()) { } @@ -116,7 +116,7 @@ public Hierarchy() /// Construct with properties /// /// The properties to pass to this repository. - public Hierarchy(PropertiesDictionary properties) + public Hierarchy(PropertiesDictionary properties) : this(properties, new DefaultLoggerFactory()) { } @@ -179,7 +179,7 @@ public ILoggerFactory LoggerFactory /// public override ILogger? Exists(string name) { - _loggers.TryGetValue(new(name.EnsureNotNull()), out object? o); + _loggers.TryGetValue(new(name.EnsureNotNull()), out IHierarchyNode? o); return o as Logger; } @@ -526,33 +526,74 @@ public Logger GetLogger(string name, ILoggerFactory factory) $"GetLogger failed, because possibly too many threads are messing with creating the logger {name}!"); } + //TODO 2 Introduce additional local functions to reduce duplication + //TODO 3 Add xml comment here private Logger? TryCreateLogger(LoggerKey key, ILoggerFactory factory) { - if (!_loggers.TryGetValue(key, out object? node)) + if (_loggers.TryGetValue(key, out IHierarchyNode? node)) { - Logger newLogger = CreateLogger(key.Name); - node = _loggers.GetOrAdd(key, newLogger); - if (node == newLogger) + switch (node) { - RegisterLogger(newLogger); + // Fast path - logger already exists and is fully registered + case Logger logger: + return logger; + // Need to create a new logger and register it, but there is already a provision node for it + case ProvisionNode provisionNode: + // Locking to stop the changes while we try to replace the provisions node with a logger + lock (_loggers) + { + // We need to check again if the logger has been created while we were waiting for the lock, + // because it is possible that another thread created the logger and replaced the provision node with a logger + if (!_loggers.TryGetValue(key, out IHierarchyNode node2)) + { + // This should never happen, but if it does, we can just create the logger and register it + Logger newLogger = CreateLogger(key.Name); + RegisterLogger(newLogger); + _loggers[key] = newLogger; + return newLogger; + } + // It is still a provision node, so we can create the logger and replace it + else if (node2 is ProvisionNode) + { + Logger newLogger = CreateLogger(key.Name); + UpdateChildren(provisionNode, newLogger); + RegisterLogger(newLogger); + _loggers[key] = newLogger; + return newLogger; + } + // Someone else created it while we were waiting for the lock, so we can just return it + return node2 as Logger; + } } } - - if (node is Logger logger) - { - return logger; - } - - if (node is ProvisionNode provisionNode) + else { - Logger newLogger = CreateLogger(key.Name); - if (_loggers.TryUpdate(key, newLogger, node)) + // Slow path - need to create the logger and register it, no provision node a moment ago, locking to stop the changes + lock (_loggers) { - UpdateChildren(provisionNode, newLogger); - RegisterLogger(newLogger); - return newLogger; + // We won the race to create the logger + if (!_loggers.TryGetValue(key, out node)) + { + Logger newLogger = CreateLogger(key.Name); + RegisterLogger(newLogger); // wire up parents FIRST + _loggers[key] = newLogger; // THEN publish + return newLogger; + } + // Someone else created it while we were waiting for the lock, so we can just return it + else if (node is Logger existingLogger) + { + return existingLogger; + } + // Someone else created a provision node while we were waiting for the lock, so we can just create the logger and register it + else if (node is ProvisionNode provisionNode) + { + Logger newLogger = CreateLogger(key.Name); + UpdateChildren(provisionNode, newLogger); + RegisterLogger(newLogger); + _loggers[key] = newLogger; + return newLogger; + } } - return null; } // It should be impossible to arrive here but let's keep the compiler happy. @@ -568,6 +609,7 @@ Logger CreateLogger(string name) void RegisterLogger(Logger logger) { UpdateParents(logger); + // TODO 1 Move outside the _loggers locks OnLoggerCreationEvent(logger); } } @@ -628,31 +670,26 @@ private void UpdateParents(Logger log) string substr = name.Substring(0, i); LoggerKey key = new(substr); - _loggers.TryGetValue(key, out object? node); + _loggers.TryGetValue(key, out IHierarchyNode? node); - // Create a provision node for a future parent. - if (node is null) + switch (node) { - _loggers[key] = new ProvisionNode(log); - } - else - { - if (node is Logger nodeLogger) - { + // Create a provision node for a future parent. + case null: + _loggers[key] = new ProvisionNode(log); + break; + case Logger nodeLogger: parentFound = true; log.Parent = nodeLogger; break; // no need to update the ancestors of the closest ancestor - } - - if (node is ProvisionNode nodeProvisionNode) - { + case ProvisionNode nodeProvisionNode: nodeProvisionNode.Add(log); - } - else - { + break; + default: LogLog.Error(_declaringType, $"Unexpected object type [{node.GetType()}] in loggers.", new LogException()); - } + break; } + if (i == 0) { // logger name starts with a dot and we've hit the start diff --git a/src/log4net/Repository/Hierarchy/Logger.cs b/src/log4net/Repository/Hierarchy/Logger.cs index db52b68a..016dc2c8 100644 --- a/src/log4net/Repository/Hierarchy/Logger.cs +++ b/src/log4net/Repository/Hierarchy/Logger.cs @@ -52,7 +52,7 @@ namespace log4net.Repository.Hierarchy; /// Gert Driesen /// Aspi Havewala /// Douglas de la Torre -public abstract class Logger(string name) : IAppenderAttachable, ILogger +public abstract class Logger(string name) : IHierarchyNode, IAppenderAttachable, ILogger { /// /// The fully qualified type of the Logger class. diff --git a/src/log4net/Repository/Hierarchy/ProvisionNode.cs b/src/log4net/Repository/Hierarchy/ProvisionNode.cs index 3411775f..56fcafe9 100644 --- a/src/log4net/Repository/Hierarchy/ProvisionNode.cs +++ b/src/log4net/Repository/Hierarchy/ProvisionNode.cs @@ -23,6 +23,10 @@ namespace log4net.Repository.Hierarchy; +internal interface IHierarchyNode +{ +} + /// /// Provision nodes are used where no logger instance has been specified /// @@ -38,7 +42,7 @@ namespace log4net.Repository.Hierarchy; /// /// Nicko Cadell /// Gert Driesen -internal sealed class ProvisionNode +internal sealed class ProvisionNode : IHierarchyNode { private readonly List _loggers; From 912474a1ff4985d76db8f33155137484b9134b71 Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 2 May 2026 14:44:21 +0200 Subject: [PATCH 5/9] Implement TODOs --- src/log4net/Repository/Hierarchy/Hierarchy.cs | 77 +++++++++++-------- 1 file changed, 47 insertions(+), 30 deletions(-) diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index 17937552..178399d1 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -526,17 +526,24 @@ public Logger GetLogger(string name, ILoggerFactory factory) $"GetLogger failed, because possibly too many threads are messing with creating the logger {name}!"); } - //TODO 2 Introduce additional local functions to reduce duplication - //TODO 3 Add xml comment here + /// + /// Attempts to create or retrieve a logger with the specified key. + /// + /// The logger key. + /// The factory to create the logger instance. + /// The logger if successful; otherwise null to indicate retry is needed. private Logger? TryCreateLogger(LoggerKey key, ILoggerFactory factory) { + Logger? result = null; + bool fireLoggerCreationEvent = false; + if (_loggers.TryGetValue(key, out IHierarchyNode? node)) { switch (node) { // Fast path - logger already exists and is fully registered - case Logger logger: - return logger; + case Logger existingLogger: + return existingLogger; // Need to create a new logger and register it, but there is already a provision node for it case ProvisionNode provisionNode: // Locking to stop the changes while we try to replace the provisions node with a logger @@ -544,26 +551,23 @@ public Logger GetLogger(string name, ILoggerFactory factory) { // We need to check again if the logger has been created while we were waiting for the lock, // because it is possible that another thread created the logger and replaced the provision node with a logger - if (!_loggers.TryGetValue(key, out IHierarchyNode node2)) + if (!_loggers.TryGetValue(key, out IHierarchyNode nodeRechecked)) { // This should never happen, but if it does, we can just create the logger and register it - Logger newLogger = CreateLogger(key.Name); - RegisterLogger(newLogger); - _loggers[key] = newLogger; - return newLogger; + CreateAndRegisterLogger(); + } + // Someone else created it while we were waiting for the lock, so we can just return it + else if (nodeRechecked is Logger existingLogger) + { + return existingLogger; } // It is still a provision node, so we can create the logger and replace it - else if (node2 is ProvisionNode) + else if (nodeRechecked is ProvisionNode) { - Logger newLogger = CreateLogger(key.Name); - UpdateChildren(provisionNode, newLogger); - RegisterLogger(newLogger); - _loggers[key] = newLogger; - return newLogger; + CreateAndReplaceProvisionNode(provisionNode); } - // Someone else created it while we were waiting for the lock, so we can just return it - return node2 as Logger; } + break; } } else @@ -574,10 +578,7 @@ public Logger GetLogger(string name, ILoggerFactory factory) // We won the race to create the logger if (!_loggers.TryGetValue(key, out node)) { - Logger newLogger = CreateLogger(key.Name); - RegisterLogger(newLogger); // wire up parents FIRST - _loggers[key] = newLogger; // THEN publish - return newLogger; + CreateAndRegisterLogger(); } // Someone else created it while we were waiting for the lock, so we can just return it else if (node is Logger existingLogger) @@ -587,17 +588,17 @@ public Logger GetLogger(string name, ILoggerFactory factory) // Someone else created a provision node while we were waiting for the lock, so we can just create the logger and register it else if (node is ProvisionNode provisionNode) { - Logger newLogger = CreateLogger(key.Name); - UpdateChildren(provisionNode, newLogger); - RegisterLogger(newLogger); - _loggers[key] = newLogger; - return newLogger; + CreateAndReplaceProvisionNode(provisionNode); } } } - // It should be impossible to arrive here but let's keep the compiler happy. - throw new LogException("TryCreateLogger failed, because a node is neither a Logger nor a ProvisionNode!"); + if (fireLoggerCreationEvent) + { + OnLoggerCreationEvent((Logger)_loggers[key]!); + } + + return result ?? throw new LogException("TryCreateLogger failed, because a node is neither a Logger nor a ProvisionNode!"); Logger CreateLogger(string name) { @@ -609,8 +610,24 @@ Logger CreateLogger(string name) void RegisterLogger(Logger logger) { UpdateParents(logger); - // TODO 1 Move outside the _loggers locks - OnLoggerCreationEvent(logger); + fireLoggerCreationEvent = true; + } + + void CreateAndRegisterLogger() + { + Logger newLogger = CreateLogger(key.Name); + RegisterLogger(newLogger); + _loggers[key] = newLogger; + result = newLogger; + } + + void CreateAndReplaceProvisionNode(ProvisionNode provisionNode) + { + Logger newLogger = CreateLogger(key.Name); + UpdateChildren(provisionNode, newLogger); + RegisterLogger(newLogger); + _loggers[key] = newLogger; + result = newLogger; } } From 82ee29e49cff1c3dfbcd6e80b6272a4ffb7b412a Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 2 May 2026 17:09:47 +0200 Subject: [PATCH 6/9] Fix mistaken in if -> switch refactor and adjust test for scenario with locking --- src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs | 4 ++-- src/log4net/Repository/Hierarchy/Hierarchy.cs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs index 4a007935..b662ad0a 100644 --- a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs +++ b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs @@ -188,14 +188,14 @@ public void GetLogger_WhenParentLoggerIsStillRegistering_ShouldWaitBeforeReturni childLogger.Log(Level.Info, "Message from child while parent registers", null); }); - Assert.That(factory.SecondChildCreated.Wait(TimeSpan.FromSeconds(5)), Is.True, - "The second child logger was not created."); Assert.That(childLogTask.Wait(TimeSpan.FromMilliseconds(100)), Is.False, "The child logger was returned before its parent logger was ready."); allowParentAssignment.Set(); Assert.That(parentTask.Wait(TimeSpan.FromSeconds(5)), Is.True); + Assert.That(factory.SecondChildCreated.Wait(TimeSpan.FromSeconds(5)), Is.True, + "The second child logger was not created."); Assert.That(childLogTask.Wait(TimeSpan.FromSeconds(5)), Is.True); parentTask.GetAwaiter().GetResult(); childLogTask.GetAwaiter().GetResult(); diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index 178399d1..dd429f6a 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -698,7 +698,7 @@ private void UpdateParents(Logger log) case Logger nodeLogger: parentFound = true; log.Parent = nodeLogger; - break; // no need to update the ancestors of the closest ancestor + return; // no need to update the ancestors of the closest ancestor case ProvisionNode nodeProvisionNode: nodeProvisionNode.Add(log); break; From e279102e389f697e02d1e8417a2d76755b38049e Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Fri, 8 May 2026 09:30:57 +0200 Subject: [PATCH 7/9] PR upgrades --- src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs | 2 +- src/log4net/Repository/Hierarchy/Hierarchy.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs index b662ad0a..f45e8dcc 100644 --- a/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs +++ b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs @@ -71,7 +71,7 @@ public void GetLogger_UnderHighConcurrency_ShouldNotLoseMessages() const int loggerCount = 20; const int repetitions = 20; - for (var run = 0; run < repetitions; run++) + for (int run = 0; run < repetitions; run++) { _memoryAppender.Clear(); diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index dd429f6a..5001984a 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -595,7 +595,7 @@ public Logger GetLogger(string name, ILoggerFactory factory) if (fireLoggerCreationEvent) { - OnLoggerCreationEvent((Logger)_loggers[key]!); + OnLoggerCreationEvent(result.EnsureNotNull()); } return result ?? throw new LogException("TryCreateLogger failed, because a node is neither a Logger nor a ProvisionNode!"); From 07a5fe356b1314dfb6fa5fcbecf0d8b06f55a74e Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 9 May 2026 14:59:31 +0200 Subject: [PATCH 8/9] Potential fix for pull request finding Co-authored-by: Copilot Autofix powered by AI <175728472+Copilot@users.noreply.github.com> --- src/log4net/Repository/Hierarchy/Hierarchy.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index 5001984a..22748540 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -546,7 +546,7 @@ public Logger GetLogger(string name, ILoggerFactory factory) return existingLogger; // Need to create a new logger and register it, but there is already a provision node for it case ProvisionNode provisionNode: - // Locking to stop the changes while we try to replace the provisions node with a logger + // Locking to stop the changes while we try to replace the provision node with a logger lock (_loggers) { // We need to check again if the logger has been created while we were waiting for the lock, From 18405c485dbca51cfcb655d276b7091fb8e5a2d2 Mon Sep 17 00:00:00 2001 From: Grzegorz Dziadkiewicz Date: Sat, 9 May 2026 15:16:14 +0200 Subject: [PATCH 9/9] PR upgrades 2 --- src/log4net/Repository/Hierarchy/Hierarchy.cs | 4 ++++ src/log4net/Repository/Hierarchy/ProvisionNode.cs | 3 +++ 2 files changed, 7 insertions(+) diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs b/src/log4net/Repository/Hierarchy/Hierarchy.cs index 22748540..4d11ee15 100644 --- a/src/log4net/Repository/Hierarchy/Hierarchy.cs +++ b/src/log4net/Repository/Hierarchy/Hierarchy.cs @@ -650,6 +650,10 @@ protected virtual void OnLoggerCreationEvent(Logger logger) /// This method loops through all the potential parents of /// . There 3 possible cases: /// + /// + /// Threading: This method must always be called while holding a lock on _loggers + /// to ensure consistent hierarchy state across concurrent logger creation. + /// /// /// /// No entry for the potential parent of exists diff --git a/src/log4net/Repository/Hierarchy/ProvisionNode.cs b/src/log4net/Repository/Hierarchy/ProvisionNode.cs index 56fcafe9..474ba451 100644 --- a/src/log4net/Repository/Hierarchy/ProvisionNode.cs +++ b/src/log4net/Repository/Hierarchy/ProvisionNode.cs @@ -23,9 +23,12 @@ namespace log4net.Repository.Hierarchy; +#pragma warning disable CA1040 //Avoid empty interfaces +//Used intentionally as a marker interface for pattern matching. internal interface IHierarchyNode { } +#pragma warning restore CA1040 /// /// Provision nodes are used where no logger instance has been specified