.NET Core: access request data on bad request when ApiController shortcuts the pipeline

Question

For all those stumbling accross logging issues I created a small public playground on Github. Feel free to join.

---

I am still experimenting with the one hits all logging filter for my requests.

The goal is simple. Instead of writing the logs in each controller method implement them once in a filter (or middleware) and apply them globally to all. This is used when something wents wrong I can see which data was used causing the problem.

so for example a controller action (with the globally applied filter)

[HttpPut("{id:int}")
public IActionResult UpdateModel(int id, [FromBody] MyRequestModel request) {}

would create logs like

[Timestamp] INFO: MyNamespace.Controllers.MyModelController.UpdateModel
{ 
  "Parameters": {
     "Id": 1,
     "Request": {
       "Name": "abc",
       "SomeInt": 3
     }
  }
}

Pretty, no more logging manually in each method.

But wait: it's an API and I used the [ApiController] attribute and the request model has invalid data (let's say Name = "a" but it needs to be at least of length of 3).

This gives me 3 problems

1. ActionFilter.OnActionExecuting is shortcutted and does not get called (due to the ApiController)
2. the binding of the arguments seems to be skipped and the bound (invalid) data is not applied to the ActionArguments
3. only the ResultFilter.OnResultExecuted is called but there seems to be no way for accessing/logging the invalid data

This somehow means logging works only when everything goes well but aren't the most interesting logs those were things go wrong?

public void OnActionExecuting(ActionExecutingContext context)
  {
    _loggerFactory
    .CreateLogger(context.ActionDescriptor.DisplayName.Split(" ")[0])
    .LogInformation
    (
      JsonConvert.SerializeObject
      (
        new { Parameters = context.ActionArguments },
        Formatting.Indented
      )
    );
  }

Point 1: I of course could remove the ApiController from each controller and go back to return BadRequest results manually. But I like the centralized approach and would like to stick with it.

I liked the model binding approach giving me classes to serialize for the logs (instead of reading the request body manually as one string). With a custom Json contract resolver I am able to mark model properties as sensitive and they are hidden in the logs (for those how care about security).

So my actual question:

Is there a way to get the model binding values in a ResultFilter or are they thrown away totally? Or is there a way to hook into the model binding/model validation and write the logs there before they get thrown away? Both especially for the case where the ApiController attribute starts shortcutting the filter pipeline.

---

public class LogFilter : IActionFilter, IResultFilter, IExceptionFilter
{

    private readonly ILoggerFactory _loggerFactory;

    public LogFilter(ILoggerFactory loggerFactory)
    {
      _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory));
    }

    public void OnActionExecuting(ActionExecutingContext context)
    {
      _loggerFactory
         .CreateLogger(context.ActionDescriptor.DisplayName.Split(" ")[0])
         .LogInformation
         (
           JsonConvert.SerializeObject
           (
             new
             {
               RequestBody = ReadBodyAsString(context.HttpContext.Request),
               Parameter = context.ActionArguments
             },
             Formatting.Indented
           )
         );
    }

    public void OnActionExecuted(ActionExecutedContext context) {}      

    public void OnResultExecuting(ResultExecutingContext context)
    {
        if (!context.ModelState.IsValid)
        {
          _loggerFactory
            .CreateLogger(context.ActionDescriptor.DisplayName.Split(" ")[0])
            .LogWarning
            (
               JsonConvert.SerializeObject
               (
                 new
                 {
                   RequestBody = ReadBodyAsString(context.HttpContext.Request),
                   ModelErrors = context.ModelState
                    .Where(kvp => kvp.Value.Errors.Count > 0)
                    .ToDictionary
                    (
                      kvp => kvp.Key,
                      kvp => kvp.Value.Errors.Select(e => e.ErrorMessage).ToArray()
                    )
                 },
                 Formatting.Indented
               )
            );
        }
    }

    public void OnResultExecuted(ResultExecutedContext context) {}

    public void OnException(ExceptionContext context)
    {

        _loggerFactory
        .CreateLogger(context.ActionDescriptor.DisplayName.Split(" ")[0])
        .LogError
        (
          context.Exception,
          JsonConvert.SerializeObject
          (
            new
            {
              //RequestBody = ReadBodyAsString(context.HttpContext.Request) // body is disposed here
            },
            Formatting.Indented
          )
        );

    }
}

Answer 1

You can create a class which implements OnActionExecuting method of IActionFilter. And register it in global filter so that it applies to all controllers and actions. When exception happens for model binding(coz of length), your OnActionExecuting method still gets called even when [ApiController] is used and you can log it there.

Eg.

public class MyActionFilterAttribute: IActionFilter
{
    public void OnActionExecuting(ActionExecutingContext context)
    {
        //Your logic to log the request, you can get the details from
        //context parameter

        //You can check if model state is valid also by using the property
        //context.ModelState.IsValid
    }
}

In Startup.cs, you need to set SuppressModelStateInvalidFilter to true. This will not return the 400 status automatically. Your controller method still gets called and since you have action filter, the OnActionExecuting gets called.

public void ConfigureServices(IServiceCollection services)
    {
        services.AddMvc(
            config =>
            {
                config.Filters.Add(new MyActionFilterAttribute());
            })
            .ConfigureApiBehaviorOptions(options =>
            {
                options.SuppressModelStateInvalidFilter = true;
            });
    }