Question

How to set up Serilog to log request and response bodies together?

In an ASP.NET Core Web API, it is very easy to add Microsoft.AspNetCore.HttpLogging to include both request and response.

In my startup, before building the app with builder.Build(), I add this code:

builder.Services.AddHttpLogging(logging =>
        {
            logging.LoggingFields =
                HttpLoggingFields.RequestPath |
                HttpLoggingFields.RequestBody |
                HttpLoggingFields.ResponseStatusCode |
                HttpLoggingFields.ResponseBody |
                HttpLoggingFields.Duration;
            logging.MediaTypeOptions.AddText("application/json");
            logging.MediaTypeOptions.AddText("text/plain");
            logging.RequestBodyLogLimit = 4096;
            logging.ResponseBodyLogLimit = 4096;
            logging.CombineLogs = true;
        });

After building, I call

app.UseHttpLogging();

In my appsettings.json, I added:

"Logging": {
    "LogLevel": {
        "Default": "Information",
        "Microsoft.AspNetCore": "Warning",
        "Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware": "Information"
    }
}

I then wind up with exactly the information I want in my log:

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[9]
      Request and Response:
      PathBase:
      Path: /api/v1/products
      StatusCode: 200
      ResponseBody: {"products":[{"family":"ProductFamily","products":["C91C","C90C","C89C","C89B","C23A","C09C","C09B","A43A","A31B"]}]}
      Duration: 533.5687

(In this case there was no request body)

This could all be set up in about 20 minutes. The problem is that Microsoft.AspNetCore.HttpLogging only writes to the console, there is no support for logging to a file or any other target.

To accomplish the logging with Serilog, one apparently needs to code a custom middleware to capture the information. I've been unable to find a clear answer anywhere about exactly how to set this up.

Here we find a good explanation how to set up a middleware to capture the request and response bodies:

https://exceptionnotfound.net/using-middleware-to-log-requests-and-responses-in-asp-net-core/

but it doesn't include how to actually log them with Serilog.

This question

How to add 'request body' in serilog's output .net core?

has several answers about how to log the request body, but they are not applicable to the response body since its stream cannot be repositioned the same as the one for the request.

This posting

https://github.com/serilog/serilog-aspnetcore/issues/168

and this question

Serilog logging web-api methods, adding context properties inside middleware

would seem to be exactly what I need, but using them didn't work for me because the properties added via

LogContext.PushProperty("RequestBody", requestBodyPayload);

don't show up in my log, even when I specify

"Enrich": [ "FromLogContext" ]

in appsettings.json for Serilog. There is no way to retrieve the properties yourself from the LogContext, so I couldn't make a workaround.

What I first attempted was this: I activate Serilog in the builder and instruct it to retrieve its configuration from the settings:

builder.Host.UseSerilog((context, configuration) =>
        {
            configuration.ReadFrom.Configuration(context.Configuration);
        });

In my appsettings.json, I have settings to log to console and a file:

"Serilog": {
    "Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.File" ],
    "MinimumLevel": {
        "Default": "Information",
        "Override": {
            "Microsoft": "Warning",
            "System": "Warning"
        }
    },
    "WriteTo": [
        { "Name": "Console" },
        {
            "Name": "File",
            "Args": {
                "path": "Log_.log",
                "rollingInterval": "Day",
                "rollOnFileSizeLimit": true,
                "filesizeLimitBytes": 67108864
            }
        }
    ],
    "Enrich": [ "FromLogContext" ]
},

After the app is built, I call

app.UseSerilogRequestLogging();

This gives me nice request/response logging, but without the bodies.

Example log entry:

[16:02:21 INF] HTTP GET /api/v1/products responded 200 in 504.9038 ms

I then implemented a middleware to capture the bodies and push them to the LogContext.

public class MyRequestResponseLoggingMiddlewareForSerilog
{
    private readonly RequestDelegate _next;

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

    public async Task Invoke(HttpContext context)
    {
        // Allow multiple reading of request body
        context.Request.EnableBuffering();

        // Add the request body to the LogContext
        string requestBodyText = await new StreamReader(context.Request.Body).ReadToEndAsync();
        LogContext.PushProperty("RequestBody", requestBodyText);

        // Rewind the Body stream so the next middleware can use it.
        context.Request.Body.Position = 0;

        //Save the reference to the original response body stream
        var originalBodyStream = context.Response.Body;

        // Create a new rewindable memory stream...
        using (var responseBody = new MemoryStream())
        {
            //...and use that for the temporary response body
            context.Response.Body = responseBody;

            // Continue down the Middleware pipeline, eventually returning to this class
            await _next(context);

            // Get the response from the server and save it in the LogContext
            context.Response.Body.Position = 0;
            string responseBodyText = await new StreamReader(context.Response.Body).ReadToEndAsync();
            context.Response.Body.Position = 0;
            LogContext.PushProperty("ResponseBody", responseBodyText);

            // Copy the contents of the new memory stream (which contains the response) to the original stream,
            // which is then returned to the client.
            await responseBody.CopyToAsync(originalBodyStream);
        }
    }
}

I activate it after activating Serilog so that its context would be available when the control goes back up to the Serilog request logging.

            app.UseSerilogRequestLogging(options =>
                {
                    options.MessageTemplate =
                        "HTTP {RequestMethod} {RequestPath} {RequestBody} responded {StatusCode} with {ResponseBody} in {Elapsed:0.0000}";
                }
            );
            app.UseMiddleware<MyRequestResponseLoggingMiddlewareForSerilog>();

Unfortunately, the logs don't show the bodies. Instead, I see the text from the template {RequestBody} and {ResponseBody} without it being replaced.

[16:08:55 INF] HTTP GET /api/v1/products {RequestBody} responded 200 with {ResponseBody} in 520.2372

To finally get it to work, I replaced my middleware with this:

   public class MyRequestResponseLoggingMiddlewareForSerilog
   {
       private readonly RequestDelegate _next;

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

       public async Task Invoke(HttpContext context)
       {
           // Allow multiple reading of request body
           context.Request.EnableBuffering();

           // Create a new rewindable memory stream for the response which downstream middleware will use
           context.Response.Body = new MemoryStream();

           // Continue down the Middleware pipeline, eventually returning to this class
           await _next(context);
       }

       public static async void EnrichDiagnosticContext(IDiagnosticContext diagnosticContext, HttpContext httpContext)
       {
           Stream requestBodyStream = httpContext.Request.Body;
           requestBodyStream.Position = 0;
           string requestBodyAsText = await new StreamReader(requestBodyStream).ReadToEndAsync();
           requestBodyStream.Position = 0;
           diagnosticContext.Set("RequestBody", requestBodyAsText);

           Stream responseBodyStream = httpContext.Response.Body;
           responseBodyStream.Position = 0;
           string responseBodyAsText = await new StreamReader(responseBodyStream).ReadToEndAsync();
           responseBodyStream.Position = 0;
           diagnosticContext.Set("ResponseBody", responseBodyAsText);
       }
   }

and activate the "enricher" for Serilog when I activate the request logging.

            app.UseSerilogRequestLogging(options =>
                {
                    options.MessageTemplate =
                        "HTTP {RequestMethod} {RequestPath} {RequestBody} responded {StatusCode} with {ResponseBody} in {Elapsed:0.0000}";
                    options.EnrichDiagnosticContext = MyRequestResponseLoggingMiddlewareForSerilog.EnrichDiagnosticContext;
                }
            );

This gives me the log entry I want:

[16:21:40 INF] HTTP GET /api/v1/products {} responded 200 with {"products":[{"family":"ProductFamily","products":["C91C","C90C","C89C","C89B","C23A","C09C","C09B","A43A","A31B"]}]} in 574.4265

BUT it leaves me with the following questions:

Is this really the way you have to do it with Serilog, or am I missing something basic? It seems overly complex for an operation that I would think a lot of people would need.
I need to create a MemoryStream to make the stream for the response body rewindable, but I can't dispose it anywhere in my code, since the subsequent middleware needs it. Also, the original response body stream is also still around but not used anymore and probably also not disposed. How and where can I dispose these streams to clean up?
Could I have gotten the information from the LogContext into the log by doing something differently? Then I could clean up the stream I created in my own code.

3 187 3

1 Jan 1970