Unexpected behavior with ConsoleLoggerProvider & LoggerExternalScopeProvider

[Ninds]

There are 2 scenarios :

Scenario 1

1. Setup logging with Dependency Injection using ConsoleLoggerProvider
2. Set a scopeprovider on the ConsoleLoggerProvider
3. Create a Logger
4. Log something

The output is not what is expected in that the scope information is missing from the output:

info: DemonstrateWeirdScopedLoggerBehaviour.ScopedLoggerDemo[0]
      Hello world at 09/07/2020 22:19:09

Scenario 2

1. Setup logging with Dependency Injection using ConsoleLoggerProvider
2. Create a (unnecessary) logger
3. Set a scopeprovider on the ConsoleLoggerProvider
4. Create a Logger
5. Log something

The output is what is expected in that the scope information is present in the output:

info: DemonstrateWeirdScopedLoggerBehaviour.ScopedLoggerDemo[0]
      => MyScope
      Hello world at 09/07/2020 22:22:11

A reproducer can be found here : ScopedLoggerDemo.cs

I see the same behaviour in 3.1.5 and 5.0.0-preview6

Perhaps the behaviour is by design but it does seem odd.

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[maryamariyan]

I checked your sample, it is because for ConsoleLoggerProvider you have IncludeScopes option enabled:

opt => opt.IncludeScopes=true

[Ninds]

HI
Thankyou for looking at it.
Can you elaborate why the difference in behaviour ?
Specifically why should it make any difference whether an unnecessary logger is instantiated before setting a scopeprovider on the ConsoleLoggerProvider ?

[maryamariyan]

@Ninds so basically

var logger = sp.GetRequiredService<ILogger<Program>>();

would need to be called before the scope provider setup. That's why ILogger defined in your "if (itWorks)" code block works and not the one define underneath.

[davidfowl]

You shouldn't be setting the scope provider yourself, that's the job of the LoggerFactory. What exactly are you trying to do?

[maryamariyan]

And to further elaborate, I believe when you use LoggerFactory your code sample should look something like below:

    using var loggerFactory = LoggerFactory.Create(builder =>
    {
         builder.AddConsole(opt => opt.IncludeScopes = true);
    });
    var logger = loggerFactory.CreateLogger<Program>();

But (a heads up), when you update to using .NET5 preview8 or later you'll notice due to some API deprecations you'll end up using the below sample instead:

    using var loggerFactory = LoggerFactory.Create(builder =>
    {
         builder.AddSimpleConsole(opt => opt.IncludeScopes = true);
    });
    var logger = loggerFactory.CreateLogger<Program>();

Refer to: #34742 which introduced the changes.

[Ninds]

But (a heads up),....

Thank you. That's good to know.

What exactly are you trying to do?

Nothing specific, I was on an exploration exercise.

The original context was to have a way of adding attributes to the logging output at the Microsoft.Extensions.Logging level without having to resort to the underlying implementation library , for example :

ILogEventEnricher in Serilog

or

LoggingEvent.Properties in Log4Net

Example of attributes I'd like to add are :

• Name of the AssemblyLoadContext
• Request Id (designated by the server when a new request arrives)

However, I was mistaken about how scopes work in the Logging API and thought that this couldn't be achieved with simple a BeginScope construct because I mistakenly thought it attached a local scope to a local ILogger.

I subsequently did this test and realised that scopes indeed achieve exactly what I was after. On the other hand it also raised a further question; "How does this (magic) work ?"

Moreover, I still find the initial observation counter-intuitive.

[Ninds]

@Drawaes just explained the magic with reference to AsyncLocal<T>