Maintaining separate scope context with serilog in asp.net core

Question

I am having an issue where the scope context is being shared between ILogger<T> instances.

Below is how I am configuring Serilog in my asp.net core 3.1 service and injecting ILogger<T>. I have a WithClassContext extension that I call within each class's constructor in order to push the class name as a context property. What I am finding is that the wrong ClassName value appears in my logs.

When I inspect the injected ILogger object in the debugger I find the following:

ILogger<T> -> Logger<T>
{
  _logger -> Serilog.Extensions.Logger.SerilogLogger
   {
      _logger -> Serilog.Core.Logger
      _provider -> Serilog.Extensions.Logger.SerilogLoggerProvider
      {
         CurrentScope -> Serilog.Extensions.Logger.SerilogLoggerScope
         {
           Parent -> Serilog.Extensions.Logger.SerilogLoggerScope
           _state -> Dictionary<string, object>
         }
      }
   }
}

So what I am observing is that each injected ILogger<T> has the same _provider object shared by all loggers. _provider.CurrentScope appears to be a linked list of SerilogLoggerScope objects, with _provider.CurrentScope pointing to the last node in the list and _provider.CurrentScope.Parent being the previous one. There is also a CurrentScope._state Dictionary<string, object> containing the property names and values. When the scope context is written out, if there are any conflicting property names, the last SerilogLoggerScope in the list is used.

So using the example I have below:

FooService is created and pushes ClassName
- CurrentScope._state -> {"ClassName", "FooService"}
FooController is created and pushes ClassName
- CurrentScope._state -> {"ClassName", "FooController"}
- CurrentScope.Parent._state -> {"ClassName", "FooService"}
FooService: CurrentScope is the same as FooController now.
Logging from all classes now push "ClassName": "FooController".

I would have thought that by injecting ILogger<T>, the scope context would not be shared by other instances. I also researched how others are pushing the class name into the logging context, and I believe I am doing the same.

Program.cs:

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .UseSerilog(ConfigureLogger)
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
            webBuilder.UseUrls("http://*:6050");
        });


private static void ConfigureLogger(HostBuilderContext ctx, IServiceProvider sp, LoggerConfiguration config)
{
    var shouldFormatElastic = !ctx.HostingEnvironment.EnvironmentName.Equals("local", StringComparison.OrdinalIgnoreCase);
    config.ReadFrom.Configuration(ctx.Configuration)
          .Enrich.FromLogContext()
          .Enrich.WithExceptionDetails();

    if (shouldFormatElastic)
    {
        var logFormatter = new ExceptionAsObjectJsonFormatter(renderMessage: true);
        config.WriteTo.Async(a =>
                                 a.Console(logFormatter, standardErrorFromLevel: LogEventLevel.Error));
    }
    else
    {
        config.WriteTo.Async(a =>
                                 a.Console(
                                     outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Properties:j}{Exception}{NewLine}",
                                     theme: SystemConsoleTheme.Literate));
    }
}

Controller:

[ApiController]
[Route("api/[controller]")]
public class FooController : ControllerBase
{
    private ILogger _logger;
    private readonly IFooService _fooService;

    /// <inheritdoc />
    public FooController(ILogger<FooController> logger, IFooService fooService)
    {
        _logger = logger.WithClassContext();
        _fooService = fooService;
    }
}

Service:

public class FooService : IFooService
{
    private readonly ILogger _logger;

    public FooService(ILogger<IFooService> logger)
    {
        _logger = logger.WithClassContext();
    }

LoggingExtensions.cs

public static class FooLoggingExtensions
{
    public static ILogger Here(this ILogger logger, [CallerMemberName] string memberName = null)
    {
        var state = new Dictionary<string, object>
        {
            {"MemberName", memberName }
        };

        // Don't need to dispose since this scope will last through the call stack.
        logger.BeginScope(state);
        return logger;
    }

    public static ILogger WithClassContext<T>(this ILogger<T> logger)
    {
        var state = new Dictionary<string, object>
        {
            {"ClassName", typeof(T).Name }
        };

        // Don't need to dispose since this scope will last through the call stack.
        logger.BeginScope(state);
        return logger;
    }
}

score 2 · Accepted Answer · answered Mar 05 '21 at 21:47

Based on what you're attempting to do, BeginScope does not appear to be the correct tool to solve the problem. The problem you're trying to solve is every log needs to have the ClassName as part of the log message. To do this you can modify the outputTemplate you're using to include {SourceContext} and then inside of your constructor instead of calling logger.WithClassContext() you call logger.ForContext<ClassName>().

Please note that I have only modified the local environment logging in the following example.

private static void ConfigureLogger(HostBuilderContext ctx, IServiceProvider sp, LoggerConfiguration config)
{
    var shouldFormatElastic = !ctx.HostingEnvironment.EnvironmentName.Equals("local", StringComparison.OrdinalIgnoreCase);
    config.ReadFrom.Configuration(ctx.Configuration)
          .Enrich.FromLogContext()
          .Enrich.WithExceptionDetails();

    if (shouldFormatElastic)
    {
        var logFormatter = new ExceptionAsObjectJsonFormatter(renderMessage: true);
        config.WriteTo.Async(a =>
                                 a.Console(logFormatter, standardErrorFromLevel: LogEventLevel.Error));
    }
    else
    {
        config.WriteTo.Async(a =>
                                 a.Console(
                                     outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {SourceContext} {Message:lj}{NewLine}{Properties:j}{Exception}{NewLine}",
                                     theme: SystemConsoleTheme.Literate));
    }
}

[ApiController]
[Route("api/[controller]")]
public class FooController : ControllerBase
{
    private ILogger _logger;
    private readonly IFooService _fooService;

    /// <inheritdoc />
    public FooController(ILogger<FooController> logger, IFooService fooService)
    {
        _logger = logger.ForContext<FooController>();
        _fooService = fooService;
    }
}

I used the following sites/blogs as references to formulate this answer.
https://benfoster.io/blog/serilog-best-practices/#source-context
C# ASP.NET Core Serilog add class name and method to log
https://github.com/serilog/serilog/issues/968

Maintaining separate scope context with serilog in asp.net core

1 Answers1