How do I include scope with Serilog's console sink when using Microsoft's ILogger?

Question

Based on the details in this blog post from Nicholas Blumhardt (I know, it's a few years old, but I can't seem to find anything more current), I'd expect to be able to use the following (minimal) configuration and have scope automatically added to my log event, however, I'm not getting anything from the default console provider. Ideally, this would just be a key=value on the log line, but a json blob {"key":"value"} could work too.

ASP.NET Core version: 3.1
Serilog version: 2.10.0
Serilog.AspNetCore version: 3.4.0

Program.cs

public class Program
{
    public static int Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .WriteTo.Console()
            .CreateLogger();

        try
        {
            Log.Information("Starting web host");
            CreateHostBuilder(args).Build().Run();
            return 0;
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Host terminated unexpectedly");
            return 1;
        }
        finally
        {
            Log.CloseAndFlush();
        }
    }

    public static IHostBuilder CreateHostBuilder(string[] args) =>
        Host.CreateDefaultBuilder(args)
            .UseSerilog()
            .ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.UseStartup<Startup>();
            });
}

Startup.cs

public class Startup
{
    public Startup(IConfiguration configuration)
    {
        Configuration = configuration;
    }

    public IConfiguration Configuration { get; }

    // This method gets called by the runtime. Use this method to add services to the container.
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddControllers();
    }

    // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        if (env.IsDevelopment())
        {
            app.UseDeveloperExceptionPage();
        }

        app.UseHttpsRedirection();

        app.UseRouting();

        app.UseAuthorization();

        app.UseEndpoints(endpoints =>
        {
            endpoints.MapControllers();
        });
    }
}

WeatherForecastController.cs

[ApiController]
[Route("[controller]")]
public class WeatherForecastController : ControllerBase
{
    private static readonly string[] _summaries = { "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching" };

    private readonly ILogger<WeatherForecastController> _logger;

    public WeatherForecastController(ILogger<WeatherForecastController> logger)
    {
        _logger = logger;
    }

    [HttpGet]
    public IEnumerable<WeatherForecast> Get()
    {
        var scopeProps = new Dictionary<string, string> { ["dude"] = "123" };
        using (_logger.BeginScope(scopeProps))
        {
            _logger.LogInformation("Hello world!");
        }

        var rng = new Random();
        return Enumerable.Range(1, 5).Select(index => new WeatherForecast
        {
            Date = DateTime.Now.AddDays(index),
            TemperatureC = rng.Next(-20, 55),
            Summary = _summaries[rng.Next(_summaries.Length)]
        })
        .ToArray();
    }
}

Logs (note the "Hello World" line that doesn't have "dude" or "123" anywhere in it)

[15:47:09 INF] Starting web host
[15:47:11 INF] Now listening on: https://localhost:5001
[15:47:11 INF] Now listening on: http://localhost:5000
[15:47:11 INF] Application started. Press Ctrl+C to shut down.
[15:47:11 INF] Hosting environment: Development
[15:47:11 INF] Content root path: C:\Users\a806228\source\repos\WebApplication10\WebApplication10
[15:47:13 INF] Request starting HTTP/2 GET https://localhost:5001/weatherforecast
[15:47:13 INF] Executing endpoint 'WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)'
[15:47:13 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[WebApplication10.WeatherForecast] Get() on controller WebApplication10.Controllers.WeatherForecastController (WebApplication10).
[15:47:13 INF] Hello world!
[15:47:13 INF] Executing ObjectResult, writing value of type 'WebApplication10.WeatherForecast[]'.
[15:47:13 INF] Executed action WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10) in 197.2872ms
[15:47:13 INF] Executed endpoint 'WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)'
[15:47:13 INF] Request finished in 533.989ms 200 application/json; charset=utf-8

I've also tried adding the RenderedCompactJsonFormatter, but that doesn't produce what I'm expecting either (based on the aforementioned blog post).

RenderedCompactJsonFormatter logs (note that scope properties are nested within the "Scope" property, not at the top level of the json object).

{"@t":"2021-02-24T23:56:08.5102552Z","@m":"Content root path: \"C:\\Users\\a806228\\source\\repos\\WebApplication10\\WebApplication10\"","@i":"b5d60022","contentRoot":"C:\\Users\\a806228\\source\\repos\\WebApplication10\\WebApplication10","SourceContext":"Microsoft.Hosting.Lifetime"}
{"@t":"2021-02-24T23:56:10.2879619Z","@m":"Request starting HTTP/2 GET https://localhost:5001/weatherforecast  ","@i":"ca22a1cb","Protocol":"HTTP/2","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"https","Host":"localhost:5001","PathBase":"","Path":"/weatherforecast","QueryString":"","HostingRequestStartingLog":"Request starting HTTP/2 GET https://localhost:5001/weatherforecast  ","EventId":{"Id":1},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.3924937Z","@m":"Executing endpoint '\"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)\"'","@i":"500cc934","EndpointName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","EventId":{"Name":"ExecutingEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.5410912Z","@m":"Route matched with \"{action = \\\"Get\\\", controller = \\\"WeatherForecast\\\"}\". Executing controller action with signature \"System.Collections.Generic.IEnumerable`1[WebApplication10.WeatherForecast] Get()\" on controller \"WebApplication10.Controllers.WeatherForecastController\" (\"WebApplication10\").","@i":"122b2fdf","RouteData":"{action = \"Get\", controller = \"WeatherForecast\"}","MethodInfo":"System.Collections.Generic.IEnumerable`1[WebApplication10.WeatherForecast] Get()","Controller":"WebApplication10.Controllers.WeatherForecastController","AssemblyName":"WebApplication10","EventId":{"Id":3,"Name":"ControllerActionExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"e2ddfe67-f10f-4720-b5f3-d7219eac02de","ActionName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.5548872Z","@m":"Hello world!","@i":"cc6ac8ad","SourceContext":"WebApplication10.Controllers.WeatherForecastController","ActionId":"e2ddfe67-f10f-4720-b5f3-d7219eac02de","ActionName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":"","Scope":[{"dude":"123"}]}
{"@t":"2021-02-24T23:56:10.6437907Z","@m":"Executing ObjectResult, writing value of type '\"WebApplication10.WeatherForecast[]\"'.","@i":"8a1b66c8","Type":"WebApplication10.WeatherForecast[]","EventId":{"Id":1,"Name":"ObjectResultExecuting"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","ActionId":"e2ddfe67-f10f-4720-b5f3-d7219eac02de","ActionName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.7730179Z","@m":"Executed action \"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)\" in 181.1047ms","@i":"afa2e885","ActionName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","ElapsedMilliseconds":181.1047,"EventId":{"Id":2,"Name":"ActionExecuted"},"SourceContext":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","ActionId":"e2ddfe67-f10f-4720-b5f3-d7219eac02de","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.8005134Z","@m":"Executed endpoint '\"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)\"'","@i":"99874f2b","EndpointName":"WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)","EventId":{"Id":1,"Name":"ExecutedEndpoint"},"SourceContext":"Microsoft.AspNetCore.Routing.EndpointMiddleware","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}
{"@t":"2021-02-24T23:56:10.8202960Z","@m":"Request finished in 538.2013ms 200 application/json; charset=utf-8","@i":"791a596a","ElapsedMilliseconds":538.2013,"StatusCode":200,"ContentType":"application/json; charset=utf-8","HostingRequestFinishedLog":"Request finished in 538.2013ms 200 application/json; charset=utf-8","EventId":{"Id":2},"SourceContext":"Microsoft.AspNetCore.Hosting.Diagnostics","RequestId":"0HM6P3V0MULJ3:00000001","RequestPath":"/weatherforecast","SpanId":"|705afff2-40607f543d36f77d.","TraceId":"705afff2-40607f543d36f77d","ParentId":""}

Also, I know I can specifically use the LogContext.PushProperty methods from within Serilog, but as a library maintainer, I'd really like to avoid that and have my callers to use Microsoft's ILogger interface (and scope) to interface with logging in ASP.NET Core because it gives me more flexibility in the long run.

Edit: I'm specifically concerned with Microsoft's ILogger interface, NOT ANYTHING RELATED to Serilog specifically. I don't actually care about "context" because I want to standardize around "scope" -- the .NET concept (not the Serilog concept). I don't care about all the other "properties" here because that's a "Serilog" concept, not a "Microsoft" concept.

Adding "Properties" to the "outputTemplate" is not what I'm asking for. Doing so via the following code:

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .UseSerilog(
            (context, configuration) =>
            {
                configuration.WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} Properties={Properties:j}{NewLine}{Exception}");
            })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        });

Creates a log line like this (note that scope is still nested within properties as a specific property).

[17:39:39 INF] Hello world! Properties={"SourceContext": "WebApplication10.Controllers.WeatherForecastController", "ActionId": "09a79aaf-7b21-46d2-b142-70d17fa41213", "ActionName": "WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)", "RequestId": "0HM6P5OR3IC2K:00000001", "RequestPath": "/weatherforecast", "SpanId": "|1c7f1f94-446bb6d3ebf05f96.", "TraceId": "1c7f1f94-446bb6d3ebf05f96", "ParentId": "", "Scope": [{"dude": "123"}]}

What I want is for the logging scope to be rendered in a way that matches how context is rendered.

Here's the Serilog way to do it.

// Program.cs
public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .UseSerilog(
            (context, configuration) =>
            {
                // add properties
                configuration
                    .Enrich.FromLogContext()
                    .WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}");
            })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        });

// WeatherForecastController.cs
[HttpGet]
public IEnumerable<WeatherForecast> Get()
{
    // use Serilog's LogContext instead of _logger.BeginScope()
    using (LogContext.PushProperty("dude", 123))
    {
        _logger.LogInformation("Hello world!");
    }

    var rng = new Random();
    return Enumerable.Range(1, 5).Select(index => new WeatherForecast
    {
        Date = DateTime.Now.AddDays(index),
        TemperatureC = rng.Next(-20, 55),
        Summary = _summaries[rng.Next(_summaries.Length)]
    })
    .ToArray();
}

It should produce the exact same log line as when I add to scope directly (however, scope is nested within properties instead of being a top level properties element like the context property I'm adding)

[17:51:35 INF] Hello world! {"SourceContext": "WebApplication10.Controllers.WeatherForecastController", "ActionId": "e0997db9-b301-495d-9cfc-7f2d2113f6f2", "ActionName": "WebApplication10.Controllers.WeatherForecastController.Get (WebApplication10)", "RequestId": "0HM6P5VGQ0U9J:00000001", "RequestPath": "/weatherforecast", "SpanId": "|1134d47e-49ed237c257f2857.", "TraceId": "1134d47e-49ed237c257f2857", "ParentId": "", "dude": 123}

Feuar

If you want to see the content in your BeginScope, you must to structured logging first.You can see more details in this article. – Cookhouse

Answer 1

I think you might be confusing adding properties to the context/scope vs rendering them.

When you use BeginScope you are adding the properties to the log context/scope and they will be sent to all sinks - and the sink decides how to render the properties.

Changing from BeginScope to LogContext.PushProperty wouldn't make any difference in how properties are rendered by a sink. Both methods equally add properties to the log context/scope i.e. A sink doesn't know (or care) about how the properties were added to a log event.

This means that the Console sink is correctly receiving the properties you're writing, but it's choosing not to render them, and that's because the default outputTemplate is:

"[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj}{NewLine}{Exception}"

Which doesn't include any context information. You need to add {Properties:j} somewhere in the template, to get the sink to render the properties.

e.g.

const string outputTemplate =
    "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties:j}{NewLine}{Exception}";

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .WriteTo.Console(outputTemplate: outputTemplate)
    .CreateLogger();

---

Documentation on output templates: https://github.com/serilog/serilog/wiki/Configuration-Basics#output-templates

Balliol

Maybe, but what you're suggesting is actually not what I'm asking for. What I want is a way to add properties to the scope and have them render in exactly the same way as properties added to the context. From what I can tell, properties added to the context are rendered differently from properties added to scope. That blog post EXPLICITLY indicates that if I add IEnumerable<KeyValuePair<string,object> then it will EXPLICITLY be added to the log event directly. Doing what you're describing gives me a bunch of other garbage that I don't care about. See the edits I just made in my post. – Feuar

@birdamongmen, have you solved this problem? – Motte

@Motte no, I didn’t. We parked the effort because of bigger fish to fry. We just have our own contextual logging implementation that doesn’t rely on the specifics of Serilog to maintain our flexibility to swap logging providers. – Feuar

Answer 2

I just had the same problem and solved it by having the exact type: Dictionary<string, object>

Try if this works for you:

var scopeProps = new Dictionary<string, object> { ["dude"] = "123" };

It is a bit stupid that it only works with that exact type. I think the place they check this is here.

Mcglothlin

Thanks for this; I created an extension method on object that converts to a Dictionary<string, object> so things can appear correctly without having to hand-craft a dictionary every time :-) – Formality

Spend a few hours today banging my head with this issue. Thank you. I think Serilog has addressed this but this extension I was trying to use does not work when you use typed scopes: github.com/Tolyandre/serilog-throw-context-enricher – Litman

Wow. This saved me. And no, they haven't addressed this. I could only get properties to appear via BeginScope() if I used this precise type of Dictionary. Thank you! – Phyllisphylloclade

Answer 3

To begin a scope while logging, use

using var logscope = logger.BeginScope("SomeScope");

This will then get added to the "Scope" property, which is an array of the current scope.

You can then output that using an output template, and it will be printed as a JSON array in line with the log:

"WriteTo": [
  {
    "Name": "Console",
    "Args": {
      "outputTemplate": "[{Timestamp:HH:mm:ss} {Scope} {Level:u3}] {Message:lj}{NewLine}{Exception}"
    }
  }
]

To actually output the scope as a period separated path, I created the following enricher:

internal class EnrichWithScopePath : ILogEventEnricher
{
    /// <summary>
    /// Replaces the "Scope" array property with a period separated scope path string
    /// </summary>
    /// <param name="logEvent"></param>
    /// <param name="propertyFactory"></param>
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        static IEnumerable<ScalarValue> ExpandOut(LogEventPropertyValue input) => input switch
        {
            SequenceValue sequenceValue => sequenceValue.Elements.SelectMany(e => ExpandOut(e)),
            ScalarValue scalarValue => Enumerable.Repeat(scalarValue, 1),
            _ => Enumerable.Empty<ScalarValue>() // TODO: Handle other types like StructureValue
        };

        if (logEvent.Properties.TryGetValue("Scope", out LogEventPropertyValue? sourceContextValue))
        {
            string joinedValue = string.Join('.', ExpandOut(sourceContextValue).Select(e => e.ToString("l", null)));
            LogEventProperty enrichProperty = propertyFactory.CreateProperty("ScopePath", joinedValue);
            logEvent.AddOrUpdateProperty(enrichProperty);
        }
    }
}

You can add it during Serilog setup using

loggerConfiguration.Enrich.With<EnrichWithScopePath>();

Then you can use the "ScopePath" property in output templating, for example in configuration file style:

"WriteTo": [
  {
    "Name": "Console",
    "Args": {
      // ScopePath is a custom enrichment to print out the scope as a period separated path
      "outputTemplate": "[{Timestamp:HH:mm:ss} {ScopePath} {Level:u3}] {Message:lj}{NewLine}{Exception}"
    }
  }
]

Charily