NLogLoggingConfiguration leak with auto reload json configuration

[Vasek-gh]

Type: Bug

NLog version: 5.3.3

NLog.Extensions.Logging version: 5.3.12

Platform: .NET 6.0

To reproduce:

csproj

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

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net6.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <None Remove="nlog.json" />
  </ItemGroup>

  <ItemGroup>
    <Content Include="nlog.json">
      <CopyToOutputDirectory>Always</CopyToOutputDirectory>
    </Content>
  </ItemGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Configuration" Version="8.0.0" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Abstractions" Version="8.0.0" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Json" Version="8.0.0" />
    <PackageReference Include="NLog" Version="5.3.3" />
    <PackageReference Include="NLog.Extensions.Logging" Version="5.3.12" />
  </ItemGroup>

</Project>

main.cs

using Microsoft.Extensions.Configuration;
using NLog.Extensions.Logging;

var config = new ConfigurationBuilder()
    .AddJsonFile("nlog.json", optional: true, reloadOnChange: true)
    .Build();

NLog.LogManager.Configuration = new NLogLoggingConfiguration(config.GetSection("NLog"));

var logger = NLog.LogManager.GetLogger("q");
logger.Info("Hello");

var task = ChangeNlogJson();

Console.Read();

async Task ChangeNlogJson()
{
    while (true)
    {
        await Task.Delay(500);

        try
        {
            using var writer = File.AppendText("nlog.json");
            await writer.WriteAsync(" ");
        }
        catch
        {
        }
    }
}

nlog.json

{
  "NLog": {
    "autoReload": true,
    "targets": {
      "async": true,
      "logconsole": {
        "type": "ColoredConsole"
      }
    },
    "rules": [
      {
        "logger": "*",
        "minLevel": "Info",
        "writeTo": "logconsole"
      }
    ]
  }
}

After some time take memory snapshot, and see it.

PS

I encountered this in Kubernetes. For reasons unknown to me, the configuration constantly received an event that the file was changing. But the timestamp and the contents of the file did not change.

If my memory serves me right, when I was analyzing the problem, I found that inside LogFactory_ConfigurationChanged the event is not unsubscribed from LogFactory.ConfigurationChanged. And this leads to the accumulation of handlers that hold a reference to the configuration instance.

[snakefoot]

Thank you for reporting this issue. The NLogLoggingConfiguration tries to unhook from the event-handler here:

https://github.com/NLog/NLog.Extensions.Logging/blob/0d6564fb2426372e49ae47e38f56c82b5320cd5c/src/NLog.Extensions.Logging/Config/NLogLoggingConfiguration.cs#L90-L100

But if you can write an unit-test that reproduces the issue, then it would be most hopeful.

[Vasek-gh]

tries to unhook from the event-handler here

Yes, I saw this, but now I've forgotten why it doesn't work. I ran it under debug about 3 weeks ago.

But if you can write an unit-test that reproduces the issue, then it would be most hopeful.

I'm not sure if it will work for this case, but I can try to write a test, but I won't have time for it until after September 9th.

[snakefoot]

Have no issue with waiting for an unit-test that reproduces the unwanted behavior.

[snakefoot]

Think I forgot to open my eyes, and actually recognize that you had provided perfect example code for how to reproduce the issue.

After debugging, then I have created #761

Thank you again for reporting this, together with providing example-code for reproducing the issue.

[snakefoot]

NLog.Extensions.Logging v5.3.13 has been released:

• https://www.nuget.org/packages/NLog.Extensions.Logging/5.3.13

Thank you again for the very detailed bug report.