There is a race condition in CreateLoggers that results in an IndexOutOfRangeException

[lucastheisen]

If you believe you have an issue that affects the security of the platform please do NOT create an issue and instead email your issue details to secure@microsoft.com. Your report may be eligible for our bug bounty but ONLY if it is reported through email.

Describe the bug

We are experiencing intermittent IndexOutOfRangeException's when using loggers in our xunit tests. I am not exactly sure what is required to reproduce, but the code clearly shows how it could be happening.

From the source:

        private LoggerInformation[] CreateLoggers(string categoryName)
        {
            var loggers = new LoggerInformation[_providerRegistrations.Count];
            for (var i = 0; i < _providerRegistrations.Count; i++)
            {
                loggers[i] = new LoggerInformation(_providerRegistrations[i].Provider, categoryName);
            }
            return loggers;
        }

You can see that if a new provider is added after loggers is created, and before the loop completes, you will get an IndexOutOfRangeException

To Reproduce

1. Intermittent, so not sure how to reproduce

Expected behavior

Either no-exception, or an exception when trying to add a provider after CreateLogger of any sort has been called (indicating that addition of providers is not allowed after creating loggers).

Screenshots

None

Additional context

[bamboo@6a7a6b3b927b ~]$ dotnet --info .NET Core SDK (reflecting any global.json): Version: 2.1.504 Commit: 91e160c7f0

Runtime Environment: OS Name: centos OS Version: 7 OS Platform: Linux RID: centos.7-x64 Base Path: /usr/share/dotnet/sdk/2.1.504/

Host (useful for support): Version: 2.1.8 Commit: 209f8aa25c

.NET Core SDKs installed: 2.1.504 [/usr/share/dotnet/sdk]

.NET Core runtimes installed: Microsoft.AspNetCore.All 2.1.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.All] Microsoft.AspNetCore.App 2.1.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App] Microsoft.NETCore.App 2.1.8 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs: https://aka.ms/dotnet-download

[davidfowl]

What are you unit tests doing? Can you show some sample code?

[lucastheisen]

Its complicated... But, I will try to boil it down here. First, our logging approach is outlined in this article. It basically boils down to a static AppLogging class to CreateLogger, rather than using DI to inject logger instances:

    public static class AppLogging
    {
        static AppLogging()
        {
            // Ensure loggers get flushed before _polite_ exit
            AppDomain.CurrentDomain.ProcessExit +=
                (sender, eventArgs) => LoggerFactory.Dispose();
        }

        public static ILoggerFactory LoggerFactory { get; } = new LoggerFactory()

        public static T AddProvider<T>() where T : ILoggerProvider, new()
        {
            var provider = new T();
            LoggerFactory.AddProvider(provider);
            return provider;
        }

        public static ILogger CreateLogger<T>() => LoggerFactory.CreateLogger<T>();
    }

In all of our regular classes we can then:

    public class ReplicatorService : IReplicatorService
    {
        private readonly ILogger logger = AppLogging.CreateLogger<ReplicatorService>();
        ...

Normally, we would add all our providers at application startup:

        public static async Task<int> Main(string[] args)
        {
            var loggerProvider = AppLogging
                .AddProvider<ConsoleFilterableLoggerProvider>();
            try
            {
                return await new HostBuilder()
                    .ConfigureAppConfiguration(
                        (context, config) =>
                        {
                            config.AddJsonFile(resources, "appsettings.json", false, false);
                        })
                    .ConfigureLogging(
                        (context, logging) =>
                        {
                            logging.AddProvider(loggerProvider);
                        })
                ....

But because xunit requires some gymasitcs to capture output, we add providers in our test cases like this:

    public sealed class ReplicatorServiceFacts
    {
        public class Replicate
        {
             public Replicate(ITestOutputHelper output)
            {
                AppLogging.AddProvider(new XunitFilterableLoggerProvider(output));
            }

            [Fact]
            public void ReplicatesMultipleWays()
            {
                using(var replicator = new ReplicatorService())
                {
                    ...

Does that help?

[analogrelay]

You can see that if a new provider is added after loggers is created, and before the loop completes, you will get an IndexOutOfRangeException

I'm not sure how this could happen though. _providerRegistrations is only modified in two places:

1. During the constructor
2. In AddProvider, which takes the _sync lock before running.

The CreateLoggers method also runs inside the _sync lock so it shouldn't be possible to modify _providerRegistrations during that loop.

Do you have a stack trace for the IndexOutOfRangeException confirming the exact code path that causes it?

[lucastheisen]

Sure do:

Starting test execution, please wait...
[xUnit.net 00:00:01.9309622]     Mitre.Tableau.Test.Replicator.ReplicatorFacts+Replicate.ReplicatesMultipleWays [FAIL]
Failed   Mitre.Tableau.Test.Replicator.ReplicatorFacts+Replicate.ReplicatesMultipleWays
Error Message:
 System.IndexOutOfRangeException : Index was outside the bounds of the array.
Stack Trace:
   at Microsoft.Extensions.Logging.LoggerFactory.CreateLoggers(String categoryName)
   at Microsoft.Extensions.Logging.LoggerFactory.CreateLogger(String categoryName)
   at Microsoft.Extensions.Logging.Logger`1..ctor(ILoggerFactory factory)
   at Microsoft.Extensions.Logging.LoggerFactoryExtensions.CreateLogger[T](ILoggerFactory factory)
   at Mitre.Tableau.Document.Replicator.ReplicatorService..ctor(ReplicatorConfiguration configuration) in C:\Users\ltheisen\git\asiasetl-tableau-automation\Mitre.Tableau.Document.Replicator\ReplicatorService.cs:line 19
   at Mitre.Tableau.Test.Replicator.ReplicatorFacts.Replicate.ReplicatesMultipleWays() in C:\Users\ltheisen\git\asiasetl-tableau-automation\Mitre.Tableau.Test\Replicator\ReplicatorFacts.cs:line 66

Total tests: 129. Passed: 128. Failed: 1. Skipped: 0.
Test Run Failed.

[analogrelay]

Ah I see you are on 2.1. If you look at the code for 2.1, the AddProviderRegistration is done outside the _sync lock:

https://github.com/aspnet/Extensions/blob/272957a803593830f39796976bcbd588f670c0f5/src/Logging/Logging/src/LoggerFactory.cs#L92-L95

In 2.2 (and 3.0) this was fixed:

https://github.com/aspnet/Extensions/blob/b6abd65ea27719ede2147a4a3ed6f4b226f11fd8/src/Logging/Logging/src/LoggerFactory.cs#L104-L106

[lucastheisen]

That code would certainly resolve this issue. Given the intermittent nature of this failure, i have no way to prove it, but i think this issue can be safely closed.

Thank you @anurse