Logging MVC properties with Serilog.AspNetCore

In my previous post I described how to configure Serilog's RequestLogging middleware to add additional properties (such as the request hostname or the selected endpoint name) to Serilog's request log summary. These properties are available from HttpContext so can be added directly by the middleware itself.

Other properties, such as MVC-specific features like the action method ID, RazorPages Handler name, or the ModelValidationState are only available in an MVC context, so can't be directly accessed by Serilog's middleware.

In this post I show how you can create action/page filters to record these properties for you, which the middleware can access later when creating the log.

Nicholas Blumhardt, creator of Serilog, has addressed this topic before. The solutions are very similar, though in his example he creates an attribute that you can use to decorate on actions/controllers. I skip that approach in this post, and require it be applied globally, which I expect will be the common use case. Be sure to check out his previous comprehensive post on Serilog in ASP.NET Core 3.0 as well!

Recording additional information from MVC

A common thread in ASP.NET Core as it stands is that there's a lot of behaviour "locked-up" inside the MVC "infrastructure". Endpoint routing was one of the first efforts to take an MVC-feature and move it down into the core framework. There's an ongoing effort in the ASP.NET Core team to push more MVC specific features (for example model binding or action results) out of MVC and "down" into the core framework. See Ryan Nowak's discussion of Project Houdini at NDC for more on this).

However, as it stands, there are still some things inside MVC that aren't easy to get to from other parts of the application. When we consider that in terms of Serilog's request logging middleware, that means there are some things that we can't easily log. For example:

• HandlerName (OnGet)
• ActionId (1fbc88fa-42db-424f-b32b-c2d0994463f1)
• ActionName (MyController.SomeApiMethod (MyTestApp))
• RouteData ({action = "SomeApiMethod", controller = "My", page = ""})
• ValidationState (True/False)

In the previous post I showed how you can use the IDiagnosticContext to write additional values to Serilog's request log using an extension of the RequestLogging middleware. This only works for values that are available in HttpContext. In this post I show how you can use the IDiagnosticContext in an action filter to add MVC-specific values to the log as well. I also show how you can add RazorPages-specific values (like HandlerName) by using a page filter.

Logging MVC properties with a custom action filter

Filters are the MVC equivalent of a mini middleware pipeline that runs for every request. There are multiple types of filter, each running at a different point in the MVC filter pipeline (see this post for more details). We're going to be using one of the most common filters in this post, an action filter.

Action filters run just before, and just after, an MVC action method is executed. They have access to lots of MVC-specific values like the Action being executed and the parameters that it will be called with.

The action filter below directly implements IActionFilter. The OnActionExecuting method is called just before the action method is invoked, and adds the extra MVC-specific properties to the IDiagnosticContext passed in to the constructor.

public class SerilogLoggingActionFilter : IActionFilter
{
    private readonly IDiagnosticContext _diagnosticContext;
    public SerilogLoggingActionFilter(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext;
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
        _diagnosticContext.Set("RouteData", context.ActionDescriptor.RouteValues);
        _diagnosticContext.Set("ActionName", context.ActionDescriptor.DisplayName);
        _diagnosticContext.Set("ActionId", context.ActionDescriptor.Id);
        _diagnosticContext.Set("ValidationState", context.ModelState.IsValid);
    }

    // Required by the interface
    public void OnActionExecuted(ActionExecutedContext context){}
}

You can register the filter globally when you add the MVC services to your application in Startup.ConfigureServices():

public void ConfigureServices(IServiceCollection services)
{
    services.AddControllers(opts =>
    {
        opts.Filters.Add<SerilogLoggingPageFilter>();
    });
    // ... other service registration
}

You can add the filter globally in the same way whether you're using AddControllers, AddControllersWithViews, AddMvc, or AddMvcCore.

With this configuration complete, if you call an MVC controller, you'll see the extra data (ActionName, ActionId, and RouteData, ValidationState) recorded on the Serilog request log message:

You can add any additional data you require to your logs here. Just be careful about logging parameter values - you don't want to accidentally log sensitive or personally identifiable information!

The action filter that Nicholas Blumhardt suggests in his post derives from ActionFilterAttribute, so it can be applied directly as an attribute to controllers and actions. Unfortunately that means you have to use service location to retrieve the singleton IDiagnosticContext from the HttpContext for every request. My approach can use constructor injection instead, but it can't be applied as an attribute, so it must be used globally as shown above. Also, MVC will use a scoped lifetime for my implementation rather than a singleton, so it creates a new instance each request.

If you want to log values from other points in the MVC filter pipeline, you can always implement other filters in similar ways, such as a resource filter, result filter, or authorization filter.

Logging RazorPages properties with a custom page filter

The IActionFilter above runs for both MVC and API controllers, but it won't run for RazorPages. If you want to log the HandlerName that was selected for a given Razor Page, you'll need to create a custom IPageFilter instead.

Page filters are directly analogous to action filters, but they only run for Razor Pages. The example below retrieves the handler name from the PageHandlerSelectedContext and logs it as the property RazorPageHandler. There's a bit more boiler-plate code required in this case but the meat of the filter is again very basic - call IDiagnosticContext.Set() to record a property.

public class SerilogLoggingPageFilter : IPageFilter
{
    private readonly IDiagnosticContext _diagnosticContext;
    public SerilogLoggingPageFilter(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext;
    }

    public void OnPageHandlerSelected(PageHandlerSelectedContext context)
    {
        var name = context.HandlerMethod?.Name ?? context.HandlerMethod?.MethodInfo.Name;
        if (name != null)
        {
            _diagnosticContext.Set("RazorPageHandler", name);
        }
    }

    // Required by the interface
    public void OnPageHandlerExecuted(PageHandlerExecutedContext context){}
    public void OnPageHandlerExecuting(PageHandlerExecutingContext context) {}
}

Note that the IActionFilter we wrote previously won't run for Razor Pages, so if you want to record additional details like RouteData or ValidationState for RazorPages too, then you'll need to add that here too. The context property contains most of the properties you could want, like the ModelState and ActionDescriptor.

Next you need to register the page filter in your Startup.ConfigureServices() method. The docs show an approach that requires creating the filter up-front, but that doesn't work when your filter uses constructor injection parameters (as in this case). Instead, you can register the page filter in the standard MVC filters list exposed in AddMvcCore():

public void ConfigureServices(IServiceCollection services)
{
    services.AddMvcCore(opts =>
    {
        opts.Filters.Add<SerilogLoggingPageFilter>();
    });
    services.AddRazorPages();
}

This feels a bit naff, but it works. 🤷‍♂️

With the filter added, requests to your Razor Pages can now add additional properties the the IDiagnosticContext which are added to the Serilog request log. See the RazorPageHandler property in the image below:

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 configuration for Development environments). In this post I show how you can customise Serilog's RequestLoggingOptions to add the MVC-specific additional properties back in.

To add MVC-related properties to the Serilog request log, create an IActionFilter and add the properties using IDiagnosticContext.Set(). To add Razor Page-related properties to the Serilog request log, create an IPageFilter and add properties using IDiagnosticContext in the same way.