How to log automatic 400 responses on model validation errors

[MNF]

“The ApiController attribute makes model validation errors automatically trigger an HTTP 400 response.”
It is not described, does details of 400 errors logged or not?
If not, is it possible to configure error details to be logged?
Or I have to SuppressModelStateInvalidFilter = true; and do logging by myself in the block
if (!ModelState.IsValid)
{
Log (ModelState);
return BadRequest(ModelState);
}

---

Document Details

⚠ Do not edit this section. It is required for docs.microsoft.com ➟ GitHub issue linking.

• ID: b391017f-25e1-d5e1-c4f7-020408ade7b5
• Version Independent ID: 263a7b64-2e42-bbfc-c1d3-61680438e1e4
• Content: Create web APIs with ASP.NET Core
• Content Source: aspnetcore/web-api/index.md
• Product: aspnet-core
• Technology: aspnetcore-webapi
• GitHub Login: @scottaddie
• Microsoft Alias: scaddie

[serpent5]

There's a section in the docs that explains how to customise the BadRequest response when using the built-in filter. You can set the InvalidModelStateResponseFactory to a custom function that first performs the logging and then returns an appropriate BadRequestObjectResult.

@Rick-Anderson I can provide an example of what that would look like here if it would be helpful. Otherwise, is this something that could be taken over to Stack Overflow with a link. What's the best approach for handling something like that?

[Rick-Anderson]

@serpent5 an example in this issue would be great. We can add a link to this issue in the doc and close the issue.

[serpent5]

There are a few ways to approach this, but I'll list a couple of ideas to get you started:

1. Perform the logging and return a BadRequestObjectResult:

services.AddMvc()
    .SetCompatibilityVersion(CompatibilityVersion.Version_2_2)
    .ConfigureApiBehaviorOptions(options =>
    {
        options.InvalidModelStateResponseFactory = context =>
        {
            // Get an instance of ILogger (see below) and log accordingly.

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

With this option, the response will not be wrapped in ProblemDetails, regardless of whether or not that is configured. If you do want a ProblemDetails wrapper, you can follow the example in the docs or...

2. Perform the logging and invoke the existing functionality that generates the response. This is a little more involved as you have to add a PostConfigure<> step rather than using the ConfigureApiBehaviorOptions call to make sure that the built-in setup adds the ProblemDetails wrapper first (if it's configured to do so):

services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_2);

services.PostConfigure<ApiBehaviorOptions>(options =>
{
    var builtInFactory = options.InvalidModelStateResponseFactory;

    options.InvalidModelStateResponseFactory = context =>
    {
        // Get an instance of ILogger (see below) and log accordingly.

        return builtInFactory(context);
    };
});

This option sets up a wrapper function that first performs your custom logging and then invokes the existing factory function. This ensures that the default functionality that comes out-of-the-box will work as it did before, but it might be overkill if you do want to take full control of the response or don't need ProblemDetails support.

---

Getting an instance of ILogger

You can use the context parameter that gets passed in to the InvalidModelStateResponseFactory delegate to get a logger from DI. There are a few options for this:

1. Resolve ILogger<Startup> from DI and use that:

var logger = context.HttpContext.RequestServices
    .GetRequiredService<ILogger<Startup>>();

This has the downside that the category for the log messages will be the full name of the Startup class, but the ActionName is included in the log context so that information will also be logged.

2. Resolve ILoggerFactory from DI and create a logger with a custom category:

var loggerFactory = context.HttpContext.RequestServices
    .GetRequiredService<ILoggerFactory>();
var logger = loggerFactory.CreateLogger("YourCategory");

3. Resolve ILoggerFactory from DI and create a logger with the full name of the action method as the category:

var loggerFactory = context.HttpContext.RequestServices
    .GetRequiredService<ILoggerFactory>();
var logger = loggerFactory.CreateLogger(context.ActionDescriptor.DisplayName);

[tdykstra]

@Rick-Anderson Added link to the doc in #12315 per your plan --

We can add a link to this issue in the doc and close the issue.

[GF-Huang]

There are a few ways to approach this, but I'll list a couple of ideas to get you started:
...

It seems too complex, I just wanna a log..

[MNF]

@RobinHSanner, did you mean “disable the automatic 400 error handling”? We want to enable logging. And we need to log before return, as I asked at the beginning of the thread

if (!ModelState.IsValid)
{
    LogErrors(ModelState);
    return BadRequest(ModelState);
}

[GF-Huang]

I want to keep "automatic 40x error handling" and log custom log.
For example, if 40x occur, log the user post form params.

[RobinHSanner]

Yes, that's what I meant. Thank you for the clarification. Sorry I obviously didn't read carefully enough. I feel pretty stupid for suggesting what you said you were having to do. I obviously have to stop skimming and read more carefully.

[mkvalluri]

I still feel this is complicated to log errors. Probably we need to have something as simple as enabling InvalidModelStateErrors that also logs the details of the request.

[kikaragyozov]

@serpent5 Could you please expand your original reply to also include how one can add the "traceId" property to their custom bad request response?

EDIT:

var problemDetails = new ValidationProblemDetails(context.ModelState)
                        {
                            Type = "https://contoso.com/probs/modelvalidation",
                            Title = "One or more model validation errors occurred.",
                            Status = StatusCodes.Status400BadRequest,
                            Detail = "See the errors property for details.",
                            Instance = context.HttpContext.Request.Path,
                            Extensions =
                            {
                                ["traceId"] = Activity.Current?.Id ?? context.HttpContext?.TraceIdentifier
                            }
                        };

[serpent5]

Thanks for the example @spiritbob. I think we can just leave your comment as-is to help others that want to do the same. What do you think?

[kikaragyozov]

@serpent5 I think it is more proper if someone can take all of the relevant information in here and find its place in the docs.

I find it odd requiring the end-user to scroll through issues to a given project, which should only be relevant to active developers/contributors of that project.

If you'd like, I can attempt to tackle on this in my free time and hopefully make an initial PR we can all iron out?

[serpent5]

If you'd like, I can attempt to tackle on this in my free time and hopefully make an initial PR we can all iron out?

Sure, that sounds like a good idea.

[harafat007]

There are a few ways to approach this, but I'll list a couple of ideas to get you started:

1. Perform the logging and return a BadRequestObjectResult:

services.AddMvc()
    .SetCompatibilityVersion(CompatibilityVersion.Version_2_2)
    .ConfigureApiBehaviorOptions(options =>
    {
        options.InvalidModelStateResponseFactory = context =>
        {
            // Get an instance of ILogger (see below) and log accordingly.

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

With this option, the response will not be wrapped in ProblemDetails, regardless of whether or not that is configured. If you do want a ProblemDetails wrapper, you can follow the example in the docs or...

2. Perform the logging and invoke the existing functionality that generates the response. This is a little more involved as you have to add a PostConfigure<> step rather than using the ConfigureApiBehaviorOptions call to make sure that the built-in setup adds the ProblemDetails wrapper first (if it's configured to do so):

services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_2);

services.PostConfigure<ApiBehaviorOptions>(options =>
{
    var builtInFactory = options.InvalidModelStateResponseFactory;

    options.InvalidModelStateResponseFactory = context =>
    {
        // Get an instance of ILogger (see below) and log accordingly.

        return builtInFactory(context);
    };
});

This option sets up a wrapper function that first performs your custom logging and then invokes the existing factory function. This ensures that the default functionality that comes out-of-the-box will work as it did before, but it might be overkill if you do want to take full control of the response or don't need ProblemDetails support.

Getting an instance of ILogger

You can use the context parameter that gets passed in to the InvalidModelStateResponseFactory delegate to get a logger from DI. There are a few options for this:

1. Resolve ILogger<Startup> from DI and use that:

var logger = context.HttpContext.RequestServices
    .GetRequiredService<ILogger<Startup>>();

This has the downside that the category for the log messages will be the full name of the Startup class, but the ActionName is included in the log context so that information will also be logged.

2. Resolve ILoggerFactory from DI and create a logger with a custom category:

var loggerFactory = context.HttpContext.RequestServices
    .GetRequiredService<ILoggerFactory>();
var logger = loggerFactory.CreateLogger("YourCategory");

3. Resolve ILoggerFactory from DI and create a logger with the full name of the action method as the category:

var loggerFactory = context.HttpContext.RequestServices
    .GetRequiredService<ILoggerFactory>();
var logger = loggerFactory.CreateLogger(context.ActionDescriptor.DisplayName);

[harafat007]

I have created a handler to log and return model binding exceptions. The handler gets invoked and logs the error before returning the error response
Code given below:
public static IMvcBuilder HandleModelBindingExceptions(this IMvcBuilder builder, ILogger logger)
{
var errorInfo = string.Empty;
string methodName = "HandleModelBindingExceptions";

        builder.ConfigureApiBehaviorOptions(option =>
          {
              //Lambda, Func delegate
              option.InvalidModelStateResponseFactory = 
              context =>
              {
                  try
                  {
                      if (context.ModelState.Count > 0 && context.ModelState.First().Value != null && context.ModelState.First().Value.Errors.Count > 0)
                      {
                          errorInfo = context.ModelState.First().Value.Errors.First().ErrorMessage;
                      }
                  }
                  catch(Exception ex)
                  {
                      errorInfo = "Issue reading errorInfo";
                      logger.Error("Method name: {methodName}, ModelState issue, details: {message}", methodName, ex);
                  }

                  var errorResponse = new ErrorResponse
                  {
                      StatusCode = LibConstants.StatusCodes.BadRequest,
                      StatusMsg = LibConstants.StatusMessages.Failure,
                      ErrorMsg = errorInfo,
                  };

                  if (errorInfo == null || errorInfo.Trim() == string.Empty)
                  {
                      errorInfo = "Something went wrong with model binding ..";
                  }
                  logger.Error("Method name: {methodName}, Details: {message}", methodName, errorInfo);

                  return new ObjectResult(errorResponse) { StatusCode = 400 };
              };
          });

        return builder;

    }

[michael-freidgeim-webjet]

@harafat007 , have you post ChatGPT answer?
If yes, you should include a link to the original source.

[harafat007]

@michael-freidgeim-webjet this is my own code. No chat gpt code

[sereneowl]

Thanks @harafat007 for your snippet. Starting from your snippet, I made following changes:

• the logger is generated on the fly, so one parameter less for injection
• works with nullable enabled
• it displays all error messages
• the error messages are gathered in a structured log, so it can be queried.
• it displays the original validation message provided by the factory.
• the validation message is logged as warning, because the app won't crash because of it. Just the exception is logged as error.

I removed the try catch block when iterating through the ModelStates, because the exception middleware is responsible for handling exceptions and because this code doesn't try to access nonexistent values.
If you're not comfortable with this, add the try catch block around the 2 foreach.

public static void ConfigureValidationApiBehavior(this IMvcBuilder builder)
   {
      builder.ConfigureApiBehaviorOptions(options =>
      {
         var builtInFactory = options.InvalidModelStateResponseFactory;

         options.InvalidModelStateResponseFactory = context =>
         {
            var logger = context.HttpContext.RequestServices.GetService<ILoggerFactory>()?
            .CreateLogger("ValidationLogger");
            var errorInfo = new Dictionary<string, Collection<string>>(StringComparer.Ordinal);

            if (logger == null || context.ModelState.Count == 0)
            {
               return builtInFactory(context);
            }

            foreach (var modelState in context.ModelState)
            {
               if (!errorInfo.TryGetValue(modelState.Key, out Collection<string>? errorMessages))
               {
                  errorMessages = [];
                  errorInfo.Add(modelState.Key, errorMessages);
               }

               foreach (var error in modelState.Value.Errors)
               {
                  errorMessages.Add(error.ErrorMessage);
               }
            }

            logger.LogWarning("Validation errors: {@message}", errorInfo);

            return builtInFactory(context);
         };
      });
   }

Usage:

builder.Services.AddControllers().ConfigureValidationApiBehavior();