How to get the request body inside InvalidModelStateResponseFactory?

Question

I have an API that is called by an external application, and I believe we're having a lot of 400 errors.

I've looked up how to catch and log automatic HTTP 400 errors, and found this solution:

services.AddMvc()
        .ConfigureApiBehaviorOptions(options =>
        {
            options.InvalidModelStateResponseFactory = context =>
            {
                ILogger logger = context.HttpContext.RequestServices
                                            .GetRequiredService<ILogger>();
                string keys = JsonConvert.SerializeObject(context.ModelState.Keys);
                string values = JsonConvert.SerializeObject(context.ModelState.Values);

                logger.Debug($"Keys: {keys}, Values: {values}");

                return new BadRequestObjectResult(context.ModelState);
            };
        });

This works well, but I assumed that I would get all keys and all values, when in fact, it only shows the keys that has an error, and not even their sent value.

Is there a way to log the whole request body in InvalidModelStateResponseFactory or am I looking at it in the wrong way?

Note that I don't want to use the SuppressModelStateInvalidFilter option.

Answer 1

Reading the request body more than once requires buffering and storing it somewhere rather than just streaming it as it arrives (remember the model binder has already read it once). Be aware that doing this can negatively affect performance as the requests will need to be stored in memory (larger ones on disk). I chose to enable this in non-production instances only. Here's how I got it to work:

First you need to tell the request you'll need it more than once. Here's a middleware I adapted from this answer

using System;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Http; 

public sealed class RequestBodyRewindMiddleware
{
    readonly RequestDelegate _next;

    public RequestBodyRewindMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task Invoke(HttpContext context)
    {
        try { context.Request.EnableBuffering(); } catch { }
        await _next(context);
    }
}

public static class BodyRewindExtensions
{
    public static IApplicationBuilder EnableRequestBodyRewind(this IApplicationBuilder app)
    {
        if (app is null)
            throw new ArgumentNullException(nameof(app));

        return app.UseMiddleware<RequestBodyRewindMiddleware>();
    }
}

I registered it like so:

   public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        if (!env.IsProduction())
            app.EnableRequestBodyRewind();
    }

Finally the code you're looking for:

public void ConfigureServices(IServiceCollection services)
{   
    services.PostConfigure<ApiBehaviorOptions>(opt =>
    {
        var defaultFactory = opt.InvalidModelStateResponseFactory;
        opt.InvalidModelStateResponseFactory = context =>
        {
            AllowSynchronousIO(context.HttpContext);

            var result = defaultFactory(context);

            var bad = result as BadRequestObjectResult;                    
            if (bad?.Value is ValidationProblemDetails problem)
                LogInvalidModelState(context, problem);

            return result;

            static void AllowSynchronousIO(HttpContext httpContext)
            { 
                IHttpBodyControlFeature? maybeSyncIoFeature = httpContext.Features.Get<IHttpBodyControlFeature>();
                if (maybeSyncIoFeature is IHttpBodyControlFeature syncIoFeature)
                    syncIoFeature.AllowSynchronousIO = true;
            }

            static void LogInvalidModelState(ActionContext actionContext, ValidationProblemDetails error)
            {
                var errorJson = System.Text.Json.JsonSerializer.Serialize(error);

                var reqBody = actionContext.HttpContext.Request.Body;
                if (reqBody.CanSeek) reqBody.Position = 0;
                var sr = new System.IO.StreamReader(reqBody);
                string body = sr.ReadToEnd();

                actionContext.HttpContext
                    .RequestServices.GetRequiredService<ILoggerFactory>()
                    .CreateLogger(nameof(ApiBehaviorOptions.InvalidModelStateResponseFactory))
                    .LogWarning("Invalid model state. Responded: '{ValidationProblemDetails}'. Received: '{Request}'", errorJson, body);
            }
        };
    });
}

Since we have no option to provide an async factory function and synchronous reads are disabled by default, we have to explicitly enable it for this request. Code is from the announcement issue here.

Make sure to rewind the body stream before you read it and don't dispose it in case something else in the pipeline needs it.

In my case where the middleware isn't registered in production, CanSeek will be false and the StreamReader.ReadToEnd just returns an empty string.