9

This is related to this question. Context: .Net Core 3.1, using Microsoft.Extensions.Logging

Loggers are singletons in the application's IHost. If I inject (DI) an ILogger<T> into my class or method, the injected object is the same instance other classes or methods receive if they ask for ILogger<T>. This poses the question of what happens when I use logger.BeginScope($"Processing {transactionId}") in one thread. What happens with the other threads? Do they change the logging scope as well? Do logging scopes get mixed up? If they don't: how does that work, being their loggers the same object? If they do mix scopes, how can I make two threads use different logging scopes for a given ILogger<T> type?

Guillermo Prandi
  • 1,537
  • 1
  • 16
  • 31

1 Answers1

13

This depends on the logger implementation, but typically they're implemented using a type of stack held within an AsyncLocal.

A call to BeginScope will put a new item onto that stack, and the adjoining Dispose will pop it off of that stack.

When the logger is invoked via LogInformation or otherwise, the data of the current stack object will be copied to write it to the console or whatever output that logger instance is configured to do.

The AsyncLocal is what gives the framework the ability to store information across threads and tasks.

For reference, check out the Microsoft.Extensions.Logging.Console source code:

Matthew
  • 24,703
  • 9
  • 76
  • 110
  • Thanks! I wasn't aware of the `AsyncLocal` type. The only problem with this design is that tasks can't get a clean logging context if they want one. Or can they? – Guillermo Prandi Sep 11 '20 at 22:10
  • I think that's the purpose of the design, you want to have contextual information of the code calling your method. If you do not want a "clean" context, then I think that goes against the intended design. – Matthew Sep 12 '20 at 14:36
  • I'm writing a class that launches tasks for different purposes; the launched tasks are unrelated to the launching class, but the logging context/scope from the launching class is transferred to the launched tasks, which pollutes their logs. – Guillermo Prandi Sep 12 '20 at 17:18
  • 3
    @GuillermoPrandi If you want to start background tasks, then I would generally recommend you not to simply start them but to consider queueing them so that you have control over the amount of parallel executions (to keep the thread pool in check). You can for example use the [`BackgroundTaskQueue` recipe](https://learn.microsoft.com/en-us/aspnet/core/fundamentals/host/hosted-services?view=aspnetcore-3.1&tabs=visual-studio#queued-background-tasks). Since the execution then runs from a hosted service, you can also start with a clean logging scope there. – poke Sep 13 '20 at 10:35
  • I wasn't aware of that option. Thank you! – Guillermo Prandi Sep 13 '20 at 16:03
  • 2
    Is this behaviour officially documented anywhere? Because it has some pretty nasty gotchas. For example, if you start a logging scope in a constructor and dispose it in `Dispose()`, it's natural to assume that the scope would be attached to the lifetime of the class. However, this isn't the case, I am observing logging scopes "stacking" when multiple classes are instantiated, which now makes sense given the implementation. I wonder why this design was chosen instead of `BeginScope()` returning a sub-logger, similar to the way `IServiceProvider` works. – Ryan Jun 02 '22 at 05:19
  • Also, the Logger Scope will flow across a `Task.Run()` boundary, which is a bit unexpected. `ExecutionContext.SuppressFlow()` is needed to prevent this. – Ryan Jun 02 '22 at 06:27
  • @Ryan With your proposal of sub-logger, wouldn't each class then need to be passed a reference to this sub-logger? – Matthew Jun 02 '22 at 14:42