Log messages not getting to appender during concurrent GetLogger

[omtslug]

Hi
I'm looking into going to log4net 3.3 but we have some logging concurrency test that bails out and I'm uncertain about the real cause.

What happens is that we don't get expected log count in the appender when doing concurrent logging.

Rather hard to reproduce, see attached repro which sets up an ILoggerRepository and Hierarchy and then runs the concurrent logging.
(put them on disk and run script.ps1), (all of this on windows 11 and windows server)

The result I get:

3.3.0  on net472:           OK=17, NOK=3
3.3.0  on net10.0-windows:  OK=19, NOK=1
3.0.4  on net472:           OK=13, NOK=7
3.0.4  on net10.0-windows:  OK=20, NOK=0
2.0.14 on net472:           OK=20, NOK=0
2.0.14 on net10.0-windows:  OK=20, NOK=0
2.0.17 on net472:           OK=20, NOK=0
2.0.17 on net10.0-windows:  OK=20, NOK=0
(not ok should be 0)

Please have a look at the LoggingConcurrencyTests ctor if that code is correct for log4net 2 and 3 versions.
Please try to reproduce it with attached code.

The actual test just does massive parallel logging, including a GetLogger call.

If the GetLogger call is done outside the loop all is good ('alt b') so it's related to the GetLogger.

It's possible to argue that the test is somewhat theoretic and maybe aggressive but I think that this problem seen on v3, not v2, is a bit worrying.

(hmm, working on getting the repro code into this..)

[omtslug]

'' Failed to upload ''

Here's Log4NetConcurrencyRepro.csproj

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFrameworks>net472;net10.0-windows</TargetFrameworks>
    <IsPackable>false</IsPackable>
    <IsTestProject>true</IsTestProject>
    <Log4NetVersion Condition="'$(Log4NetVersion)' == ''">3.3.0</Log4NetVersion>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="log4net" Version="$(Log4NetVersion)" />
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.10.0" />
    <PackageReference Include="xunit" Version="2.9.0" />
    <PackageReference Include="xunit.runner.visualstudio" Version="2.8.1">
      <PrivateAssets>all</PrivateAssets>
      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
    </PackageReference>
  </ItemGroup>
</Project>

Here's LoggingConcurrencyTests.cs

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<LoggingEvent> _events = new List<LoggingEvent>();
            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;
                }
            }
        }
    }
}

Here's script.ps1

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
""

[omtslug]

I'm looking into this code in v3 Hierarchy.cs, (don't know if it's the stuff used but i think so)

  private Logger? TryCreateLogger(LoggerKey key, ILoggerFactory factory)
  {
    if (!_loggers.TryGetValue(key, out object? node))
    {
      Logger newLogger = CreateLogger(key.Name);
      node = _loggers.GetOrAdd(key, newLogger);
      if (node == newLogger)
      {
        RegisterLogger(newLogger);
      }
    }

    if (node is Logger logger)
    {
      return logger;
    }
    [snip]

Imagine that we have parallel GetLogger calls being made for the same logger.
Isn't there a risk that a 'not ready' logger is returned?
Two threads wants the same logger:
  a, neither of them gets it from _loggers.
  b, both does CreateLogger
  c, one of these gets into _loggers and the second GetOrAdd will return the one already in _loggers.
  d, the issue is now that this 'second' thread returns the Logger from _loggers but the RegisterLogger hasn't been done yet,
    it's the work for the first thread which in some cases is delayed.

Thoughts/discussion welcome.

[FreeAndNil]

Hi @omtslug,

thanks for the detailed report and the reproduction test - both are very helpful.

I will take a closer look tomorrow.