UseSerilogRequestLogging()

[nblumhardt]

This long-talked-about feature adds middleware for request logging, based on the popular sample in this blog post.

In comparison with the default request logging performed by the framework, this implementation condenses as much information as possible into a single event, resulting in easier correlation and lower log volumes.

An example completion event might look like:

[15:31:09 INF] HTTP GET / responded 200 in 13.8298 ms {"RequestId": "0HLNOCKKFBOL3:00000003",
    "CorrelationId": null, "ConnectionId": "0HLNOCKKFBOL3"}

(I'm using the {Properties:j} output formatting option to include properties not present in the log message itself. This makes the events a bit noisier, but it's easier to see what's going on.)

Additional properties can be added to the completion event using IDiagnosticContext; e.g. in the InlineInitializationSample project's HomeController.Index():

public class HomeController : Controller
{
    static int _callCount = 0;

    readonly ILogger<HomeController> _logger;
    readonly IDiagnosticContext _diagnosticContext;

    public HomeController(ILogger<HomeController> logger, IDiagnosticContext diagnosticContext)
    {
        _logger = logger ?? throw new ArgumentNullException(nameof(logger));
        _diagnosticContext = diagnosticContext ??
             throw new ArgumentNullException(nameof(diagnosticContext));
    }

    public IActionResult Index()
    {
        _logger.LogInformation("Hello, world!");

        _diagnosticContext.Add("IndexCallCount", Interlocked.Increment(ref _callCount));

        return View();
    }
}

The _diagnosticContext.Add() call will attach IndexCallCount to completion events, e.g.:

[15:31:09 INF] Hello, world! {"SourceContext": "InlineInitializationSample.Controllers.HomeController"
    "ActionId": "3845d8d0-9e30-4264-b47a-ff72d4421038", "ActionName":
    "InlineInitializationSample.Controllers.HomeController.Index (InlineInitializationSample)",
    "RequestId": "0HLNOCKKFBOL3:00000003", "RequestPath": "/", "CorrelationId": null,
    "ConnectionId": "0HLNOCKKFBOL3"}
[15:31:09 INF] HTTP GET / responded 200 in 13.8298 ms {"IndexCallCount": 2, "RequestId":
    "0HLNOCKKFBOL3:00000003", "CorrelationId": null, "ConnectionId": "0HLNOCKKFBOL3"}

By doing this, it's no longer necessary to speculatively include a lot of information in the request completion event: users who want more details (e.g. form fields from the request, headers, etc.), can write middleware that depends on IDiagnosticContext and simply add these themselves.

Open to all opinions, including on:

• Localization/template customization - should we allow the text of the request completion message to be customized in the first version?
• Conditional logging - should we provide a leveled or predicate-based method of choosing which requests to log?
• Formatting - it's usual in many style guides to omit a space between numbers and SI unit abbreviations, e.g. 123.456ms vs 123.456 ms; in a cluttered log event I find the former a bit harder to quickly scan so I've gone with the latter.

The PR also replicates some changes, and depends on others, in serilog/serilog-extensions-hosting#9. In particular, UseSerilog() will now register the IDiagnosticContext and DiagnosticContext types, as well as ILogger if available, and the middleware consumes DiagnosticContext. CC @andrewlock.

[nblumhardt]

Argh, annoyingly, I forgot to mark this as "Draft" - it needs some upstream changes before it will build.

[andrewlock]

Looks good to me 👍

Localization/template customization - should we allow the text of the request completion message to be customized in the first version?

Probably, but I'm inclined to wait for someone to ask for it

Conditional logging - should we provide a leveled or predicate-based method of choosing which requests to log?

Again, probably, but the current implementation works for me as-is

Formatting - it's usual in many style guides to omit a space between numbers and SI unit abbreviations, e.g. 123.456ms vs 123.456 ms; in a cluttered log event I find the former a bit harder to quickly scan so I've gone with the latter.

Yeah I'd be inclined to remove the space for consistency with other systems, but I don't think it really matters much.

[nblumhardt]

Thinking again about the localisation and typographic questions, being able to solve both of those by providing template customization would kill two birds with one stone - I might take a look at that option :-)

[nblumhardt]

Alrighty, made messageTemplate an option to UseSerilogRequestLogging() and fixed a missing Dispose() call on collector 😊

Going to push the button and circulate some details so we have a chance of gathering feedback before the rush of ASP.NET Core/.NET Core 3.0 is upon us!

Hat tip to @martinjt whose Honeycomb middleware example was the inspiration to get going on this 🎩

[Giorgi]

Is there an example showing how to use IDiagnosticContext outside of ASP.NET Core?

[nblumhardt]

@Giorgi no, not currently. Though this was a promising direction, I think the ubiquity of tracing and Activity.Current (which can carry arbitrary properties to emit at the completion of the activity) made a generalized IDiagnosticContext separate from UseSerilogRequestLogging() less appealing.

Check out https://nblumhardt.com/2024/04/serilog-net8-0-minimal/#recording-web-requests for a quick run through how this looks with Serilog. HTH!