Logging the selected Endpoint Name with Serilog

In my previous post I described how to configure Serilog's RequestLogging middleware to create "summary" logs for each request, to replace the 10 or more logs you get from ASP.NET Core by default.

In this post I show how you can add additional metadata to Serilog's summary request log, such as the Request's hostname, the Response's content-type, or the selected Endpoint Name from the endpoint routing middleware used in ASP.NET Core 3.0.

ASP.NET Core infrastructure logs are verbose, but have more details by default

As I showed in my previous post, in the Development environment the ASP.NET Core infrastructure generates 10 log messages for a request to a RazorPage handler:

By switching to Serilog's RequestLoggingMiddleware that comes with the Serilog.AspNetCore NuGet package you can reduce this to a single log message:

All the images of logs used in this post are taken using Seq, which is an excellent tool for viewing structured logs

Clearly the original set of logs are more verbose, and a large part of that is not especially useful information. However, if you take the original 10 logs as a whole, they do record some additional fields in the structure log template when compared to the Serilog summary log.

Additional fields logged by the ASP.NET Core infrastructure which are not logged by Serilog include:

• Host (localhost:5001)
• Scheme (https)
• Protocol (HTTP/2)
• QueryString (test=true)
• EndpointName (/Index)
• HandlerName (OnGet/SerilogRequestLogging.Pages.IndexModel.OnGet)
• ActionId (1fbc88fa-42db-424f-b32b-c2d0994463f1)
• ActionName (/Index)
• RouteData ({page = "/Index"})
• ValidationState (True/False)
• ActionResult (PageResult)
• ContentType (text/html; charset=utf-8)

I'd argue that some of these points would definitely be useful to include in the summary log message. For example, if your app is bound to multiple host names then Host is definitely important to log. QueryString is potentially another useful field. EndpointName/HandlerName, ActionId, and ActionName seem slightly less critical, given that you should be able to deduce those given the request path, but logging them explicitly will help you catch bugs, as well as make it easier to filter all requests to a specific action.

Broadly speaking, you can separate these properties into two categories:

• Request/Response properties e.g. Host, Scheme, ContentType, QueryString, EndpointName
• MVC/RazorPages-related properties e.g. HandlerName, ActionId, ActionResult etc

In this post i'll show how you can add the first of these categories, properties related to the Request/Response, and in the next post I'll show how you can add MVC/RazorPages-based properties.

Adding additional data to the Serilog request log

I showed how to add Serilog request logging to your application in my previous post, so I'm not going to cover that again here. For now, I'll assume you've already set that up, and you have a Startup.Configure method that looks something like this:

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    // ... Error handling/HTTPS middleware
    app.UseStaticFiles();

    app.UseSerilogRequestLogging(); // <-- Add this line

    app.UseRouting();
    app.UseAuthorization();
    app.UseEndpoints(endpoints =>
    {
        endpoints.MapRazorPages();
    });
}

The UseSerilogRequestLogging() extension method adds the Serilog RequestLoggingMiddleware to the pipeline. You can also call an overload to configure an instance of RequestLoggingOptions. This class has several properties that let you customise how the request logger generates the log statements:

public class RequestLoggingOptions
{
    public string MessageTemplate { get; set; }
    public Func<HttpContext, double, Exception, LogEventLevel> GetLevel { get; set; }
    public Action<IDiagnosticContext, HttpContext> EnrichDiagnosticContext { get; set; }
}

The MessageTemplate property controls how the log is rendered to a string and GetLevel lets you control whether a given log should be level Debug/Info/Warning etc. The property we're interested in here is the EnrichDiagnosticContext property.

When set, this Action<> is executed by Serilog's middleware when it generates a log message. It's run just before the log is written, which means it runs after the middleware pipeline has executed. For example, in the image below (taken from my book ASP.NET Core in Action) the log is written at step 5, when the response "passes back through" the middleware pipeline:

The fact that the log is written after the pipeline has processed means a couple of things:

• We can access properties of the Response, such as the status code, elapsed time, or the content type
• We can access Features that are set by middleware later in the pipeline, for example the IEndpointFeature set by the EndpointRoutingMiddleware (added via UseRouting()).

In the next section, I provide a helper function that adds all the "missing" properties to the Serilog request log message.

Setting values in IDiagnosticContext

Serilog.AspNetCore adds the interface IDiagnosticContext to the DI container as a singleton, so you can access it from any of your classes. You can then use it to attach additional properties to the request log message by calling Set().

For example, as shown in the documentation, you can add arbitrary values from an action method:

public class HomeController : Controller
{
    readonly IDiagnosticContext _diagnosticContext;
    public HomeController(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext;
    }

    public IActionResult Index()
    {
        // The request completion event will carry this property
        _diagnosticContext.Set("CatalogLoadTime", 1423);
        return View();
    }
}

The resulting summary log will then include the property CatalogLoadTime.

We essentially use exactly the same approach to customise the RequestLoggingOptions used by the middleware, by setting values on the provided IDiagnosticContext instance. The static helper class below retrieves values from the current HttpContext and sets them if they're available.

public static class LogHelper 
{
    public static void EnrichFromRequest(IDiagnosticContext diagnosticContext, HttpContext httpContext)
    {
        var request = httpContext.Request;

        // Set all the common properties available for every request
        diagnosticContext.Set("Host", request.Host);
        diagnosticContext.Set("Protocol", request.Protocol);
        diagnosticContext.Set("Scheme", request.Scheme);

        // Only set it if available. You're not sending sensitive data in a querystring right?!
        if(request.QueryString.HasValue)
        {
            diagnosticContext.Set("QueryString", request.QueryString.Value);
        }

        // Set the content-type of the Response at this point
        diagnosticContext.Set("ContentType", httpContext.Response.ContentType);

        // Retrieve the IEndpointFeature selected for the request
        var endpoint = httpContext.GetEndpoint();
        if (endpoint is object) // endpoint != null
        {
            diagnosticContext.Set("EndpointName", endpoint.DisplayName);
        }
    }
}

The helper function above retrieves values from the Request, from the Response, and from features set by other middleware (Endpoint Name). You could extend this to add other values from the request as appropriate.

You can register the helper by setting the EnrichDiagnosticContext property when you call UseSerilogRequestLogging in your Startup.Configure() method:

public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    // ... Other middleware

    app.UseSerilogRequestLogging(opts
        => opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest);

    // ... Other middleware
}

Now when you make requests, you will see all the extra properties added to your Serilog structured logs:

You can use this approach whenever you have values that are generally available to the middleware pipeline via the current HttpContext. The exception to that is MVC-specific features which are "internal" to the MVC middleware, like action names, or RazorPage handler names. In the next post I'll show how you can also add those to your Serilog request log.

Summary

By default, when you replace the ASP.NET Core infrastructure logging with Serilog's request logging middleware, you lose some information compared to the default logging configuration for Development environments. In this post I show how you can customise Serilog's RequestLoggingOptions to add these additional properties back in.

The method for doing so is very simple - you have access to the HttpContext so you can retrieve any values it has available and can set them as properties on the provided IDiagnosticContext. These are added as extra properties to the structured log generated by Serilog. In the next post I'll show how you can add MVC-specific values to the request log.