This is an automated email from the ASF dual-hosted git repository.
gdziadkiewicz pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
The following commit(s) were added to refs/heads/master by this push:
new 44e9c13d Fix race in Hierarchy.TryCreateLogger (#294)
44e9c13d is described below
commit 44e9c13d5ffb9afacadc754e11afd89ee294ab5e
Author: Grzegorz Dziadkiewicz <[email protected]>
AuthorDate: Sat May 9 16:54:09 2026 +0200
Fix race in Hierarchy.TryCreateLogger (#294)
* Add the repro project from #292
* Add the repro for #292 as test
* Add dotted logers tests and GetCurrentLoggers tests
Co-authored-by: Copilot <[email protected]>
* Use one lock approach and add marker interface
* Implement TODOs
* Fix mistaken in if -> switch refactor and adjust test for scenario with
locking
* PR upgrades
* Potential fix for pull request finding
Co-authored-by: Copilot Autofix powered by AI
<[email protected]>
* PR upgrades 2
---------
Co-authored-by: Copilot <[email protected]>
Co-authored-by: Copilot Autofix powered by AI
<[email protected]>
---
src/log4net.Tests/Hierarchy/HierarchyTest.cs | 40 +++
.../Hierarchy/LoggingConcurrencyTest.cs | 277 +++++++++++++++++++++
src/log4net/Repository/Hierarchy/Hierarchy.cs | 142 +++++++----
src/log4net/Repository/Hierarchy/Logger.cs | 2 +-
src/log4net/Repository/Hierarchy/ProvisionNode.cs | 9 +-
5 files changed, 426 insertions(+), 44 deletions(-)
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
new file mode 100644
index 00000000..f45e8dcc
--- /dev/null
+++ b/src/log4net.Tests/Hierarchy/LoggingConcurrencyTest.cs
@@ -0,0 +1,277 @@
+#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;
+using System.Threading.Tasks;
+using log4net.Appender;
+using log4net.Core;
+using log4net.Repository;
+using log4net.Repository.Hierarchy;
+using NUnit.Framework;
+
+namespace log4net.Tests.Hierarchy;
+
+/// <summary>
+/// Concurrency tests for <see cref="LogManager.GetLogger(string, string)"/>.
+/// Regression test for LOG4NET-292.
+/// </summary>
+[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();
+ }
+
+ /// <summary>
+ /// Verifies that no messages are lost when multiple threads call
+ /// <see cref="LogManager.GetLogger(string, string)"/> with the same logger
+ /// name concurrently (LOG4NET-292).
+ /// </summary>
+ [Test]
+ public void GetLogger_UnderHighConcurrency_ShouldNotLoseMessages()
+ {
+ const int messageCount = 400;
+ const int loggerCount = 20;
+ const int repetitions = 20;
+
+ for (int run = 0; run < repetitions; run++)
+ {
+ _memoryAppender.Clear();
+
+ Parallel.For(0, messageCount, i =>
+ {
+ var logger = LogManager.GetLogger(_repository.Name, "ConcurrencyTest-"
+ run + "-" + (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<LoggingEvent>(e =>
e.RenderedMessage == expectedMessage),
+ $"Run {run}: Missing message: {expectedMessage}");
+ }
+ }
+ }
+
+ [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<LoggingEvent>(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<InvalidOperationException>(() =>
hierarchy.GetLogger(loggerName));
+ Assert.That(actualException, Is.SameAs(expectedException));
+ }
+ finally
+ {
+ hierarchy.LoggerCreatedEvent -= ThrowingHandler;
+ }
+
+ Task<Logger> 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<LoggingEvent>(
+ 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<Logger> 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(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();
+
+ Assert.That(memoryAppender.GetEvents(), Has.Some.Matches<LoggingEvent>(
+ 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;
+ }
+ }
+ }
+}
diff --git a/src/log4net/Repository/Hierarchy/Hierarchy.cs
b/src/log4net/Repository/Hierarchy/Hierarchy.cs
index 452b5d7f..4d11ee15 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<LoggerKey, object> _loggers =
new(LoggerKey.ComparerInstance);
+ private readonly ConcurrentDictionary<LoggerKey, IHierarchyNode> _loggers =
new(LoggerKey.ComparerInstance);
private ILoggerFactory _defaultFactory = loggerFactory.EnsureNotNull();
private Logger? _rootLogger;
@@ -108,7 +108,7 @@ public class Hierarchy(PropertiesDictionary properties,
ILoggerFactory loggerFac
/// <summary>
/// Default constructor
/// </summary>
- public Hierarchy()
+ public Hierarchy()
: this(new DefaultLoggerFactory())
{ }
@@ -116,7 +116,7 @@ public Hierarchy()
/// Construct with properties
/// </summary>
/// <param name="properties">The properties to pass to this
repository.</param>
- public Hierarchy(PropertiesDictionary properties)
+ public Hierarchy(PropertiesDictionary properties)
: this(properties, new DefaultLoggerFactory())
{ }
@@ -179,7 +179,7 @@ public ILoggerFactory LoggerFactory
/// </remarks>
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,37 +526,79 @@ public Logger GetLogger(string name, ILoggerFactory
factory)
$"GetLogger failed, because possibly too many threads are messing with
creating the logger {name}!");
}
+ /// <summary>
+ /// Attempts to create or retrieve a logger with the specified key.
+ /// </summary>
+ /// <param name="key">The logger key.</param>
+ /// <param name="factory">The factory to create the logger instance.</param>
+ /// <returns>The logger if successful; otherwise null to indicate retry is
needed.</returns>
private Logger? TryCreateLogger(LoggerKey key, ILoggerFactory factory)
{
- if (!_loggers.TryGetValue(key, out object? node))
+ Logger? result = null;
+ bool fireLoggerCreationEvent = false;
+
+ 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 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 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,
+ // because it is possible that another thread created the logger
and replaced the provision node with a logger
+ if (!_loggers.TryGetValue(key, out IHierarchyNode nodeRechecked))
+ {
+ // This should never happen, but if it does, we can just create
the logger and register it
+ 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 (nodeRechecked is ProvisionNode)
+ {
+ CreateAndReplaceProvisionNode(provisionNode);
+ }
+ }
+ break;
}
}
-
- if (node is Logger logger)
+ else
{
- return logger;
+ // Slow path - need to create the logger and register it, no provision
node a moment ago, locking to stop the changes
+ lock (_loggers)
+ {
+ // We won the race to create the logger
+ if (!_loggers.TryGetValue(key, out node))
+ {
+ CreateAndRegisterLogger();
+ }
+ // 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)
+ {
+ CreateAndReplaceProvisionNode(provisionNode);
+ }
+ }
}
- if (node is ProvisionNode provisionNode)
+ if (fireLoggerCreationEvent)
{
- Logger newLogger = CreateLogger(key.Name);
- if (_loggers.TryUpdate(key, newLogger, node))
- {
- UpdateChildren(provisionNode, newLogger);
- RegisterLogger(newLogger);
- return newLogger;
- }
- return null;
+ OnLoggerCreationEvent(result.EnsureNotNull());
}
- // 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!");
+ return result ?? throw new LogException("TryCreateLogger failed, because a
node is neither a Logger nor a ProvisionNode!");
Logger CreateLogger(string name)
{
@@ -568,7 +610,24 @@ Logger CreateLogger(string name)
void RegisterLogger(Logger logger)
{
UpdateParents(logger);
- 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;
}
}
@@ -591,6 +650,10 @@ protected virtual void OnLoggerCreationEvent(Logger logger)
/// This method loops through all the <i>potential</i> parents of
/// <paramref name="log"/>. There 3 possible cases:
/// </para>
+ /// <para>
+ /// <b>Threading:</b> This method must always be called while holding a lock
on <c>_loggers</c>
+ /// to ensure consistent hierarchy state across concurrent logger creation.
+ /// </para>
/// <list type="number">
/// <item>
/// <term>No entry for the potential parent of <paramref name="log"/>
exists</term>
@@ -628,31 +691,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)
- {
- _loggers[key] = new ProvisionNode(log);
- }
- else
+ switch (node)
{
- 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)
- {
+ return; // no need to update the ancestors of the closest ancestor
+ 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;
/// <author>Gert Driesen</author>
/// <author>Aspi Havewala</author>
/// <author>Douglas de la Torre</author>
-public abstract class Logger(string name) : IAppenderAttachable, ILogger
+public abstract class Logger(string name) : IHierarchyNode,
IAppenderAttachable, ILogger
{
/// <summary>
/// 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..474ba451 100644
--- a/src/log4net/Repository/Hierarchy/ProvisionNode.cs
+++ b/src/log4net/Repository/Hierarchy/ProvisionNode.cs
@@ -23,6 +23,13 @@
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
+
/// <summary>
/// Provision nodes are used where no logger instance has been specified
/// </summary>
@@ -38,7 +45,7 @@ namespace log4net.Repository.Hierarchy;
/// </remarks>
/// <author>Nicko Cadell</author>
/// <author>Gert Driesen</author>
-internal sealed class ProvisionNode
+internal sealed class ProvisionNode : IHierarchyNode
{
private readonly List<Logger> _loggers;
