OptionsMonitorExtensions.OnChange vs. non-default options name

[KalleOlaviNiemitalo]

Several Microsoft.Extensions.* libraries use the OptionsMonitorExtensions.OnChange<TOptions> method to register an Action<TOptions> delegate that applies the new options. This delegate does not get the name of the options as a parameter, unlike the Action<TOptions, string?> that can be registered via IOptionsMonitor<TOptions>.OnChange.

This then causes a potential bug: if an IOptionsChangeTokenSource<TOptions> implementation has been registered for a name other than Options.DefaultName, and it reports a change via its IChangeToken, then IOptionsMonitor<TOptions> gets the TOptions instance that corresponds to the non-default name and passes it to the delegates that apply these non-default options rather than IOptionsMonitor<TOptions>.CurrentValue.

I am posting this as a discussion rather than an issue, because I have not found a scenario in which an application developer would want to use non-default option names with a TOptions type that Microsoft.Extensions.* libraries monitor in this risky manner. Regardless, it seems to me that OptionsMonitorExtensions.OnChange<TOptions> is best avoided.

Here is sample code that demonstrates the bug.

Source code

CustomOptionsNameDemo.csproj

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net8.0</TargetFramework>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="8.0.0" />
  </ItemGroup>

</Project>

Program.cs

using System;
using System.Diagnostics;
using System.Threading;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Configuration.Memory;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;

namespace CustomOptionsNameDemo
{
    internal static class Program
    {
        private static void Main()
        {
            var memoryConfigurationProvider = new MemoryConfigurationProvider(new MemoryConfigurationSource())
            {
                { "Logging:CaptureScopes", "True" },
                { "Logging:Console:IncludeScopes", "True" }, // deprecated ConsoleLoggerOptions.IncludeScopes
                { "Logging:Console:FormatterOptions:IncludeScopes", "True" }, // ConsoleFormatterOptions.IncludeScopes
                { "SecondaryLogging:CaptureScopes", "False" },
            };
            using (var configurationRoot = new ConfigurationRoot(new[] { memoryConfigurationProvider }))
            {
                ServiceCollection serviceCollection = new ServiceCollection();

                // The order of registration matters.
                serviceCollection.Configure<LoggerFilterOptions>(
                    name: "Secondary",
                    configurationRoot.GetRequiredSection("SecondaryLogging"));
                serviceCollection.AddLogging(
                    (ILoggingBuilder loggingBuilder) =>
                    {
                        loggingBuilder.AddConsole();
                        loggingBuilder.AddConfiguration(configurationRoot.GetRequiredSection("Logging"));
                    });

                using (ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider())
                {
                    IOptionsMonitor<LoggerFilterOptions> loggerFilterOptionsMonitor
                        = serviceProvider.GetRequiredService<IOptionsMonitor<LoggerFilterOptions>>();

                    // These assertions pass.
                    Debug.Assert(loggerFilterOptionsMonitor.CurrentValue.CaptureScopes == true);
                    Debug.Assert(loggerFilterOptionsMonitor.Get("Secondary").CaptureScopes == false);

                    ILoggerFactory loggerFactory = serviceProvider.GetRequiredService<ILoggerFactory>();
                    ILogger logger = loggerFactory.CreateLogger(typeof(Program).FullName!);

                    using (logger.BeginScope("Scope1"))
                    {
                        logger.LogInformation("This log entry should be in a logger scope.");
                        Thread.Sleep(TimeSpan.FromSeconds(1));
                    }

                    // This causes LoggerFactory.RefreshFilters(LoggerFilterOptions) to be called twice:
                    // first with the new default options, and then with the new "Secondary" options.
                    // The second call makes LoggerFactory start using the wrong options.
                    configurationRoot.Reload();
                    Thread.Sleep(TimeSpan.FromSeconds(1));

                    using (logger.BeginScope("Scope2"))
                    {
                        logger.LogInformation("This log entry should likewise be in a logger scope.");
                        Thread.Sleep(TimeSpan.FromSeconds(1));
                    }

                    // These assertions still pass.
                    Debug.Assert(loggerFilterOptionsMonitor.CurrentValue.CaptureScopes == true);
                    Debug.Assert(loggerFilterOptionsMonitor.Get("Secondary").CaptureScopes == false);
                }
            }
        }
    }
}

Actual output

info: CustomOptionsNameDemo.Program[0]
      => Scope1
      This log entry should be in a logger scope.
info: CustomOptionsNameDemo.Program[0]
      This log entry should likewise be in a logger scope.

Expected output

info: CustomOptionsNameDemo.Program[0]
      => Scope1
      This log entry should be in a logger scope.
info: CustomOptionsNameDemo.Program[0]
      => Scope2
      This log entry should likewise be in a logger scope.