Possible EnricherStack memory leak

[andrii-babanin-sym]

Context: I'm trying to take advantage of MEL logging filters. To do this, I implement multiple output-specific ILoggerProvider instances, each of which creates its own Serilog logger with a particular sink.

Unfortunately, the ILogger.BeginScope method leads to memory leak.

Steps to reproduce:

Run the following code snippet and collect heap dump or use some another tool to analyze heap:

using Microsoft.Extensions.Logging;
using Serilog;
using Serilog.Extensions.Logging;
using ILogger = Microsoft.Extensions.Logging.ILogger;
using SerilogLogger = Serilog.ILogger;


var melFactory = LoggerFactory.Create(builder =>
{
    builder.AddProvider(new OneProvider());
    builder.AddProvider(new AnotherProvider());
});

var logger = melFactory.CreateLogger("Test");

while (true)
{
    using var scope = logger.BeginScope("Some property");

    logger.LogInformation("Hello world!");

    await Task.Delay(100);
}

public class OneProvider : LoggerProviderBase
{
    public OneProvider()
    :base(CreateLogger())
    {
        
    }

    private static SerilogLogger CreateLogger() =>
        new LoggerConfiguration().WriteTo.Console().CreateLogger();
}

public class AnotherProvider : LoggerProviderBase
{
    public AnotherProvider()
        : base(CreateLogger())
    {

    }

    private static SerilogLogger CreateLogger() =>
        new LoggerConfiguration().WriteTo.Console().CreateLogger();
}

public class LoggerProviderBase : ILoggerProvider
{
    private readonly SerilogLoggerProvider innerProvider;

    public LoggerProviderBase(SerilogLogger logger)
    {
        this.innerProvider = new SerilogLoggerProvider(logger, dispose: true);
    }

    /// <inheritdoc />
    public void Dispose() => this.innerProvider.Dispose();

    /// <inheritdoc />
    public ILogger CreateLogger(string categoryName) => this.innerProvider.CreateLogger(categoryName);
}

VS Memory analyze:

Root cause:

1. The Microsoft.Extensions.Logging.Logger object aggregates multiple ILogger instances retrieved from all registered ILoggerProvider instances (see the CreateLoggers method).

2. Logger.BeginScope calls BeginScope on the inner loggers in order.

3. Each inner logger's BeginScope execution triggers SerilogLoggerProvider.BeginScope, a new property is pushed into the LogContext, and the bookmark is retrieved.

4. Upon disposal, scopes are disposed of in order, and any incorrect bookmarks are reset.

Bookmark after first logger's BeginScope:

After second:

As it stands, the second bookmark will be restored after the first (MEL preserves order), which will result in the incorrect bookmark being restored.

Proposed solution: Implement logging scopes for each SerilogLoggerProvider that do not rely on the LogContext API. For backward compatibility, continue traversing the LogContext linked list.

I would like to contribute a fix if the proposed solution is approved.

CC @nblumhardt

[AndreReise]

I've managed to work around this issue by implementing the ISupportExternalScope in LoggerProviderBase, which simply proxies the call to SerilogLoggerProvider:

public void SetScopeProvider(IExternalScopeProvider scopeProvider)
{
    this.innerProvider.SetScopeProvider(scopeProvider);
}

Why is scope management handled using the LogContext API, instead of just using IExternalScopeProvider for simplicity sake, as Microsoft does - for example, in the ConsoleLogger?

[nblumhardt]

Hi @AndreReise, thanks for the report and analysis.

I think scope management is more convoluted than necessary in this library because it pre-dates IExternalScopeProvider, and when that interface was introduced, this library still needed to support usage without it (IIRC ...).

If you have a chance to dig in and simplify things, or can send a fix for this issue, targeted, backwards-compatible/non-breaking PRs are welcome. Let me know if you decide to give it a shot, happy to run through rough/early versions of possible changes.

Cheers,
Nick