Adding Logging Middleware in .net core 2 web api, cause http 307 and 400 error in response

Question

I want to use the logging middleware provided by aspnet core sample. Before I adding the Logging Middleware, everything worked fine. After adding the logging middleware I got error messages.

Before adding middleware:

info: Microsoft.AspNetCore.Server.Kestrel[32]
      Connection id "0HLJA6SH4AF9Q", Request id "0HLJA6SH4AF9Q:00000001": the application completed without reading the entire request body.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1] Request starting HTTP/1.1 POST https://localhost:5001/api/operations/deposit application/json 282
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Route matched with {action = "Post", controller = "Operations"}. Executing action API.Controllers.OperationsController.Post (API)
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method API.Controllers.OperationsController.Post (API) with arguments (API.Req.Deposit) - Validation state: Valid
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action method API.Controllers.OperationsController.Post (API), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 4782.8378ms.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'API.Res.Deposit'.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action API.Controllers.OperationsController.Post (API) in 4901.4518ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 4930.5295ms 200 application/json; charset=utf-8

After adding the middleware in the Startup.cs:

public void Configure(IApplicationBuilder app, IHostingEnvironment env)
{
    ...
    app.UseMiddleware<RequestResponseLoggingMiddleware>();
    app.UseHttpsRedirection();
    app.UseMvc();
}

The whole log will output

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST http://localhost:5000/api/operations/deposit application/json 282
info: API.RequestResponseLoggingMiddleware[0]
      http localhost:5000/api/operations/deposit  
      {
        "merchant": "981001",
        ....,
        "userName": "susan"
      }
info: API.RequestResponseLoggingMiddleware[0]
      Response
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 50.7335ms 307
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 POST https://localhost:5001/api/operations/deposit application/json 282
info: API.RequestResponseLoggingMiddleware[0]
      https localhost:5001/api/operations/deposit  
      {
           "merchant": "981001",
           ...,
           "userName": "susan"
      }
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Route matched with {action = "Post", controller = "Operations"}. Executing action API.Controllers.OperationsController.Post (API)
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'Microsoft.AspNetCore.Mvc.SerializableError'.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action API.Controllers.OperationsController.Post (API) in 179.1267ms
info: API.RequestResponseLoggingMiddleware[0]
      Response {"":["A non-empty request body is required."]}
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 213.3557ms 400 application/json; charset=utf-8

It spotted a serialize problem, then I try to set SuppressModelStateInvalidFilter as follows:

public void ConfigureServices(IServiceCollection services)
{

services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_1);
    services.Configure<ApiBehaviorOptions>(
        options => {options.SuppressModelStateInvalidFilter = true; });
}

The log shows more information as follows:

info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Route matched with {action = "Post", controller = "Operations"}. Executing action API.Controllers.OperationsController.Post (API)
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      Executing action method API.Controllers.OperationsController.Post (API) with arguments () - Validation state: Invalid
      Object reference not set to an instance of an object.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action method API.Controllers.OperationsController.Post (API), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 454.3309ms.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'API.Res.Deposit'.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      Executed action API.Controllers.OperationsController.Post (API) in 640.913ms
info: API.RequestResponseLoggingMiddleware[0]
      Response 
      {
         "branch": null,
         "holder": null,
         "number": null,
         "expire": "0001-01-01T00:00:00",
         "error": 0,
         "verifyText": null,
         "transactionId": null
      }
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      Request finished in 671.6427ms 200 application/json; charset=utf-8

Everything becomes null. Why is the request context body lost in the middleware?

Answer 1

Create middleware class to intercept all requests and responses without affecting the response flow. Enable middleware class association in startup.cs

app.UseMiddleware<HttpRequestResponseLogger>();

Implement a middleware class to intercept request and response . optionally you can store these logs in a database. I am ignoring secrets and unnecessary header values

 public class HttpRequestResponseLogger
{
    RequestDelegate next;

    public HttpRequestResponseLogger(RequestDelegate next)
    {
        this.next = next;
    }
    //can not inject as a constructor parameter in Middleware because only Singleton services can be resolved
    //by constructor injection in Middleware. Moved the dependency to the Invoke method
    public async Task InvokeAsync(HttpContext context, IHttpLogRepository repoLogs)
    {
        HttpLog logEntry = new HttpLog();
        await RequestLogger(context, logEntry);
        
        await next.Invoke(context);

        await ResponseLogger(context, logEntry);

        //store log to database repository
        repoLogs.SaveLog(logEntry);
    }

    // Handle web request values
    public async Task RequestLogger(HttpContext context, HttpLog log)
    {
        string requestHeaders = string.Empty;

        log.RequestedOn = DateTime.Now;
        log.Method = context.Request.Method;
        log.Path = context.Request.Path;
        log.QueryString = context.Request.QueryString.ToString();
        log.ContentType = context.Request.ContentType;

        foreach (var headerDictionary in context.Request.Headers)
        {
            //ignore secrets and unnecessary header values
            if (headerDictionary.Key != "Authorization" && headerDictionary.Key != "Connection" &&
                headerDictionary.Key != "User-Agent" && headerDictionary.Key != "Postman-Token" &&
                headerDictionary.Key != "Accept-Encoding")
            {
                requestHeaders += headerDictionary.Key + "=" + headerDictionary.Value + ", ";
            }
        }

        if (requestHeaders != string.Empty)
            log.Headers = requestHeaders;

        //Request handling. Check if the Request is a POST call 
        if (context.Request.Method == "POST")
        {
            context.Request.EnableBuffering();
            var body = await new StreamReader(context.Request.Body).ReadToEndAsync();
            context.Request.Body.Position = 0;
            log.Payload = body;
        }
    }

    //handle response values
    public async Task ResponseLogger(HttpContext context, HttpLog log)
    {
        using (Stream originalRequest = context.Response.Body)
        {
            try
            {
                using (var memStream = new MemoryStream())
                {
                    context.Response.Body = memStream;
                    // All the Request processing as described above 
                    // happens from here.
                    // Response handling starts from here
                    // set the pointer to the beginning of the 
                    // memory stream to read
                    memStream.Position = 0;
                    // read the memory stream till the end
                    var response = await new StreamReader(memStream)
                        .ReadToEndAsync();
                    // write the response to the log object
                    log.Response = response;
                    log.ResponseCode = context.Response.StatusCode.ToString();
                    log.IsSuccessStatusCode = (
                        context.Response.StatusCode == 200 ||
                        context.Response.StatusCode == 201);
                    log.RespondedOn = DateTime.Now;

                    // since we have read till the end of the stream, 
                    // reset it onto the first position
                    memStream.Position = 0;

                    // now copy the content of the temporary memory 
                    // stream we have passed to the actual response body 
                    // which will carry the response out.
                    await memStream.CopyToAsync(originalRequest);
                }
            }
            catch (Exception ex)
            {
                Console.WriteLine(ex);
            }
            finally
            {
                // assign the response body to the actual context
                context.Response.Body = originalRequest;
            }
        }

    }

Answer 2

The problem has resolved as @PeterBons pointed out.

We need to set request.EnableRewind(); and after read the content so set the body position to 0 request.Body.Position = 0;. The following is the code I used:

private async Task<string> FormatRequest(HttpRequest request)
{
    request.EnableRewind();
    var buffer = new byte[Convert.ToInt32(request.ContentLength)];
    await request.Body.ReadAsync(buffer, 0, buffer.Length).ConfigureAwait(false);
    var bodyAsText = Encoding.UTF8.GetString(buffer);
    request.Body.Position = 0;
    return $"{bodyAsText}";
}

Happy coding!