Attach a specific scope to a specific ILogger instance

[bitbonk]

I would like to have a scope attached to a specific instance of an ILogger so whenever anyone logs using that specific ILogger instance, that scoped property (SomeProperty in the below example) is always present.
If someone logs using any different ILogger instance, that property should not be present.

What is the best way to implement this?

The below example demonstrates it. It is not pretty because:

1. The logging class (Example) needs to implement IDisposable
2. It sometime does not work, the scope is missing for some reason sometimes.

pulic class Example : IDisposable
{
    private readonly ILogger logger;
    private readonly IDisposable? scope;
    private readonly InnerHelpler innerHelper = new();

    public Example(ILogger<Example> logger)
    {
        this.logger = logger;
        
        // this forces class Example to implement IDisposable
        this.scope = this.logger.BeginScope(new Dictionary<string, object> { { "SomeProperty", "some value" } });
    }

    // might be called on a custom synchronization context
    public async Task OnSomethingHappenedAsync()
    {
        // Depending on who calls OnSomethingHappened externally, the SomeProperty sometimes
        // is missing for some reason
        this.logger.LogInformation("The scope property {SomeProperty} is available");
        
        // pass the logger AND THE SOMEPROPERTY context to inner types
        await this.innerHelper.DoSomethingAsync(this.logger);
        
    }

    public void Dispose()
    {
        this.scope?.Dispose();
    }
}

[KalleOlaviNiemitalo]

For logger providers that implement ISupportExternalScope, this could be done by implementing an IExternalScopeProvider that retrieves an overriding list of scopes from thread-local storage, and telling each provider to use that. An ILogger wrapper would then set the scope list, call the per-provider loggers, and restore the list. Likely you'd need a custom ILoggerFactory too.

Not all providers support ISupportExternalScope though. The Microsoft.Extensions.Logging.TraceSource package doesn't, because the underlying TraceSource reads the scopes from Trace.CorrelationManager. If you need to support those too, then I think your ILogger has to save an ExecutionContext that has the correct scopes and call the provider-specific loggers on clones of that. Which even seems easier to implement than the IExternalScopeProvider hack.

Replacing the ExecutionContext seems likely to break log enrichment as implemented in this repository, though.

[KalleOlaviNiemitalo]

It would be easiest to begin the logger scopes first, then create the logger wrapper within those scopes and make its constructor capture the ExecutionContext. Something like this:

    private readonly ExecutionContext executionContext = ExecutionContext.Capture() ?? throw new InvalidOperationException();

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        // Because of the type parameter, it isn't easy to avoid allocating a closure.
        this.executionContext.CreateCopy().Run(
            _ => this.logger.Log(logLevel, eventId, state, exception, formatter),
            null);
    }

ILogger wrapper;
using (logger.BeginScope("hi there"))
{
    wrapper = new FrozenScopesLogger(logger);
}

Or, if you want the wrapper to also include the logger scopes from the execution context from which its Log method is called, then it would be simplest to make Log call BeginScope:

    // Scopes specific to this logger instance.
    private readonly LoggerExternalScopeProvider extraScopesProvider = new LoggerExternalScopeProvider();

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        // Could check IsEnabled here.

        // Could use stackalloc or a pool.
        var disposables = new Stack<IDisposable>();

        try
        {
            // Add all of our extra scopes to the underlying logger.
            this.extraScopesProvider.ForEachScope(
                (object? scope, Stack<IDisposable> state) => state.Push(this.logger.BeginScope(scope)),
                state: disposables);

            this.logger.Log(logLevel, eventId, state, exception, formatter);
        }
        finally
        {
            // Remove the extra scopes from the underlying logger.
            while (disposables.Count != 0)
            {
                disposables.Pop()?.Dispose();
            }
        }
    }

[KalleOlaviNiemitalo]

If you don't need the extra information specifically as logger scopes and can instead take them within the state passed to ILogger.Log, then a custom ILogEnricher may be a better choice. It would have to be registered in DependencyInjection and the application would have to call LoggingEnrichmentExtensions.EnableEnrichment.

[bitbonk]

@KalleOlaviNiemitalo

It would be easiest to begin the logger scopes first, then create the logger wrapper within those scopes and make its constructor capture the ExecutionContext.

So to apply this to my Example class, I would to it like this?

pulic class Example : IDisposable
{
    private readonly ILogger logger;
    private readonly InnerHelpler innerHelper = new();

    public Example(ILogger<Example> logger)
    {
        using (logger.BeginScope(new Dictionary<string, object> { { "SomeProperty", "some value" } })
        {
            this.logger = new FrozenScopesLogger(logger);
        }
    }

    // might be called on a custom synchronization context
    public async Task OnSomethingHappenedAsync()
    {
        // Depending on who calls OnSomethingHappened externally, the SomeProperty sometimes
        // is missing for some reason
        this.logger.LogInformation("The scope property {SomeProperty} is available");
        
        // pass the logger AND THE SOMEPROPERTY context to inner types
        await this.innerHelper.DoSomethingAsync(this.logger);        
    }
}

Will subsequent BeginScope calls on FrozenScopesLogger inside InnerHelpler.DoSomethingAsync(ILogger) still be able to add additional scopes to that logger?

[KalleOlaviNiemitalo]

Will subsequent BeginScope calls on FrozenScopesLogger inside InnerHelpler.DoSomethingAsync(ILogger) still be able to add additional scopes to that logger?

Unlikely. If FrozenScopesLogger has a readonly ExecutionContext executionContext field, and its ILogger.Log method simply calls the inner ILogger.Log on that, then the logger scopes seen by the inner logger always match what was stored in the ExecutionContext. Which makes ILogger.BeginScope difficult to implement in FrozenScopesLogger.

It isn't clear to me how you want this to work. Suppose there is a SpecificScopeLogger class that does what you want. Then:

1. If two parallel async functions call ILogger.BeginScope on the same SpecificScopeLogger instance, should each of them have an independent stack of logger-specific scopes, or should both scopes be stacked together? If they should be independent, then SpecificScopeLogger needs to save the scopes in AsyncLocal<T> somehow, like LoggerExternalScopeProvider does in the code I posted above.
2. If code first calls ILogger.BeginScope on a different logger and then calls ILogger.Log on the SpecificScopeLogger, should the scope apply to that log entry? If it should, then saving an ExecutionContext doesn't seem a good idea.

To illustrate question 1:

void M(ILogger innerLogger)
{
    var logger = new SpecificScopeLogger(innerLogger);
    Task task1 = DoAsync(logger, 1);
    Task task2 = DoAsync(logger, 2);
    await task1;
    await task2;
}

async Task DoAsync(ILogger logger, int scope)
{
    using (logger.BeginScope(scope))
    {
        await Task.Delay(TimeSpan.FromSeconds(1)); // in lieu of proper synchronization
        logger.LogInformation("hello " + scope);
    }
}

This would call first BeginScope(1) and then BeginScope(2). Both of those calls would probably finish before the LogInformation("hello 1") and LogInformation("hello 2") calls start.

[bitbonk]

@KalleOlaviNiemitalo

It isn't clear to me how you want this to work. Suppose there is a SpecificScopeLogger class that does what you want.

The behavior we are after is that whenever someone logs using the instance of SpecificScopeLogger a specific log property should be present and it should always have the value that was initially passed to that instance of SpecificScopeLogger. This should always be true even if the users adds new properties by calling BeginScope on that instance of SpecificScopeLogger or even if that instance of SpecificScopeLogger is called in concurrently (disclaimer: we have a system wide synchronization context that is based on a single thread that works similar to the DispatcherSynchronizationContext of WPF).

Some more background:

Our overall system works somewhat similar to the actor model where user code is embedded into an actor (node). Usually, a node is represented by a single class that gets its ID via the constructor. For simplicity users can implement such a node by inheriting from a base class. This base class should provide a logging mechanism based on ILogger that always knows about ID and always logs the ID as a well known log property. As a result, all log entries contain the node context information.

class MyNode : NodeBase
{
    public MyNode(NodeIdentifier id, ILoggerFactory loggerFactory) : base(id, loggerFactory)
    {
    }

     // will always be called on the single threaded synchronization context, but could be called concurrently
    public Task OnSomethingHappendAsync()
    {
        // this.Logger is a protected `ILogger` member provided by `NodeBase`
        this.Loggger.LogInformation("The scope property {NodeId} is available and its value will be what was injected via the ctor");

        using (this.Loggger.BeginScope(new Dictionary<string, object> { { "SomeUserProperty", "some value" } })
        {
            this.Loggger.LogInformation("The scope property {NodeId} is available but also {SomeUserProperty}");
        }
    } 
}