Log Requests and Responses in ASP.NET Core 3

This post is going to be a refresh of the Log Requests and Responses in ASP.NET Core post which no longer works more modern versions of ASP.NET Core. For the most part, this post will exactly match the original but with the code bits updated.

As part of trying to do some debugging, I needed a way to log the requests and responses. Writing a piece of middleware seemed to be a good way to handle this problem. It also turned out to be more complicated than I had expected to deal with the request and response bodies.

Middleware

In ASP.NET Core middleware are the components that make up the HTTP pipeline that handles requests and responses for the application. Each piece of middleware called has the option to do some processing on the request before calling the next piece of middleware in line. After execution returns from the call to the next middleware, there is an opportunity to do processing on the response.

The HTTP pipeline for an application is set in the Configure function of the Startup class. Run, Map and Use are the three types of middleware available. Run should only be used to terminate the pipeline. Map is used for pipeline branching. Use seems to be the most common type of middleware that does some processing and call the next middleware in line. For more detail see the official docs.

Creating Middleware

Middleware can be implemented as a lambda directly in the Configure function, but more typically it is implemented as a class that is added to the pipeline using an extension method on IApplicationBuilder. This example will be using the class route.

This example is a piece of middleware that uses ASP.NET Core’s built-in logging to log requests and responses. Create a class called RequestResponseLoggingMiddleware.

The class will need a constructor that takes two arguments both will be provided by ASP.NET Core’s dependency injection system. The first is a RequestDelegate which will be the next piece of middleware in the pipeline. The second is an instance of an ILoggerFactory which will be used to create a logger. The RequestDelegate is stored to the class level _next variable and the loggerFactory is used to create a logger that is stored to the class level _logger variable.

public class RequestResponseLoggingMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;

    public RequestResponseLoggingMiddleware(RequestDelegate next,
                                            ILoggerFactory loggerFactory)
    {
        _next = next;
        _logger = loggerFactory
                  .CreateLogger<RequestResponseLoggingMiddleware>();
    }
}

Add an Invoke function which is the function that will be called when your middleware is run by the pipeline. The following is the function that does nothing other than call the next middleware in the pipeline.

public async Task Invoke(HttpContext context)
{
     //code dealing with the request

     await _next(context);

     //code dealing with the response
}

Next, add a static class to simplify adding the middleware to the application’s pipeline. This is the same pattern the built-in middleware uses.

public static class RequestResponseLoggingMiddlewareExtensions
{
    public static IApplicationBuilder UseRequestResponseLogging(this IApplicationBuilder builder)
    {
        return builder.UseMiddleware<RequestResponseLoggingMiddleware>();
    }
}

Adding to the pipeline

To add the new middleware to the pipeline open the Startup.cs file and add the following line to the Configure function.

app.UseRequestResponseLogging();

Keep in mind that the order in which middleware is added can make a difference in how the application behaves. Since the middleware this post is dealing with is logging I have placed it near the start of the pipeline.

Logging requests and responses

Now that the setup work for our new middleware is done we will come back to its Invoke function. As I stated above this ended up being more complicated than I expected, but thankfully I found this by Sul Aga which really helped me work through the issues I was having along with a lot of feedback on the original version of this post.

One of the bits of feedback on the original version of this post was about a potential memory leak and using recyclable memory streams. First, add a NuGet reference to the Microsoft.IO.RecyclableMemoryStream package. Next, we will add a class-level variable to hold an instance of a RecyclableMemoryStreamManager which we will create in the constructor. The following is an updated class view with these changes as well as changes to the Invoke function and stubs for the logging methods.

public class RequestResponseLoggingMiddleware
{
    private readonly RequestDelegate _next;
    private readonly ILogger _logger;
    private readonly RecyclableMemoryStreamManager _recyclableMemoryStreamManager;

    public RequestResponseLoggingMiddleware(RequestDelegate next,
                                            ILoggerFactory loggerFactory)
    {
        _next = next;
        _logger = loggerFactory
                  .CreateLogger<RequestResponseLoggingMiddleware>();
        _recyclableMemoryStreamManager = new RecyclableMemoryStreamManager();
    }

    public async Task Invoke(HttpContext context)
    {
        await LogRequest(context);
        await LogResponse(context);
    }
  
    private async Task LogRequest(HttpContext context) {}
    private async Task LogResponse(HttpContext context) {}
}

First, we are going to look at the LogRequest function, and a helper function it uses.

private async Task LogRequest(HttpContext context)
{
    context.Request.EnableBuffering();

    await using var requestStream = _recyclableMemoryStreamManager.GetStream();
    await context.Request.Body.CopyToAsync(requestStream);
    _logger.LogInformation($"Http Request Information:{Environment.NewLine}" +
                           $"Schema:{context.Request.Scheme} " +
                           $"Host: {context.Request.Host} " +
                           $"Path: {context.Request.Path} " +
                           $"QueryString: {context.Request.QueryString} " +
                           $"Request Body: {ReadStreamInChunks(requestStream)}");
    context.Request.Body.Position = 0;
}

private static string ReadStreamInChunks(Stream stream)
{
    const int readChunkBufferLength = 4096;

    stream.Seek(0, SeekOrigin.Begin);

    using var textWriter = new StringWriter();
    using var reader = new StreamReader(stream);

    var readChunk = new char[readChunkBufferLength];
    int readChunkLength;

    do
    {
        readChunkLength = reader.ReadBlock(readChunk, 
                                           0, 
                                           readChunkBufferLength);
        textWriter.Write(readChunk, 0, readChunkLength);
    } while (readChunkLength > 0);

    return textWriter.ToString();
}

The key to getting this function to work and allow reading of the request body was context.Request.EnableBuffering() which allows us to read from the beginning of the stream. The rest of the function is pretty straight forward.

The next function is LogResponse which is used to execute the next bit of middleware in the pipeline, using await _next(context) and then logging the response body after the rest of the pipeline has run.

private async Task LogResponse(HttpContext context)
{
    var originalBodyStream = context.Response.Body;

    await using var responseBody = _recyclableMemoryStreamManager.GetStream();
    context.Response.Body = responseBody;

    await _next(context);

    context.Response.Body.Seek(0, SeekOrigin.Begin);
    var text = await new StreamReader(context.Response.Body).ReadToEndAsync();
    context.Response.Body.Seek(0, SeekOrigin.Begin);

    _logger.LogInformation($"Http Response Information:{Environment.NewLine}" +
                           $"Schema:{context.Request.Scheme} " +
                           $"Host: {context.Request.Host} " +
                           $"Path: {context.Request.Path} " +
                           $"QueryString: {context.Request.QueryString} " +
                           $"Response Body: {text}");

    await responseBody.CopyToAsync(originalBodyStream);
}

As you can see the trick to reading the response body is replacing the stream being used with a new MemoryStream and then copying the data back to the original body steam. I don’t know how much this affects performance and would make sure to study how it scales before using it in a production environment.

Wrapping up

I hope this updated post turns out to be as helpful as the original seemed to be. This round I do have the code in a GitHub repo and the commit with the related changes can be found here.


Also published on Medium.

25 thoughts on “Log Requests and Responses in ASP.NET Core 3”

  1. Good article.
    I think you forgot await _next(context); between
    await LogRequest(context);
    await LogResponse(context);

  2. Why do we need to read request in chunks ?

    Why do not just :

    string requestBody;
    requestStream.Position = 0;
    using (StreamReader streamReader = new StreamReader(requestStream))
    {
    requestBody = streamReader.ReadToEnd();
    }

    ?

  3. I think you need to reset the context.Request.Body location after you’ve copied it, maybe add line below to the end of LogRequest
    context.Request.Body.Seek(0, SeekOrigin.Begin);
    Couldn’t the RecyclableMemoryStreamManager copy/read/copy back pattern be used for the request as well, and if so would this perform better than EnableBuffering() ?

    1. You could write the logs to a database if you wanted, but really this is just a quick thing thrown together for debugging and not really meant to be used in production.

  4. Great Article, super helpful!

    One question though, is there any particular reason why “await _next(context);” is within the LogResponse and not in the Invoke method like:

    public async Task Invoke(HttpContext context)
    {
    await LogRequest(context);
    await _next(context);
    await LogResponse(context);
    }

    Cheers!

    1. That is because the Response stream needs to be replaced by another stream before the “await _next(context);” to be able to read the response. After reading it for logging it will copy the data to the original stream.

  5. When the action throw a exception ,
    in function : LogResponse , it execut to line : await _next(context);
    and it would not back to next line .
    and , at client side , there only a 500 status code ,but body is empty .
    why ?

    thanks.

    1. ok,i found why it happens .
      if ‘ app.UseRequestResponseLogging();’ before ‘ app.UseDeveloperExceptionPage();’ ,it fixed.

  6. Is it possible a memory leak is created here when writing this:

    var text = await new StreamReader(context.Response.Body).ReadToEndAsync();

    shouldn’t the Streamreader be using the “using” pattern?

  7. Is there a way to do this out of process, so that the original application does not suffer a performance hit ?

  8. This does not work if you use compression.

    app.UseResponseCompression();

    You just get the compressed response body after awaiting _next()

    1. As a matter of fact, I have no clue on where this data is logged either. I guess you would have to add a ILogger implementation tah manges it easily like Elmah ou Serilog? Did you finaly foung where those logs are generated by default?

  9. Request-response pipeline breaks if somehow an exception occurs in LogResponse method. This should not happen as it should not affect original pipeline functionality. How to deal with this situation? Valuable comments are appreciated

  10. I’m using dotnet core 2.2 and it doesn’t support the “using” statement.

    is there any other option to write this ?
    using var textWriter = new StringWriter();
    using var reader = new StreamReader(stream);

  11. I used this code a while back… a few small tweaks but the base code is based on above…. I’ve just ran into an issue where an Angular front-end page is making 5 rxjs calls to the API within the constuctor and it’s failing with the message…

    “Cannot write to the response body, the response has completed.\r\nObject name: ‘HttpResponseStream’.”

    on line… await responseBody.CopyToAsync(originalBodyStream); …… any ideas for consurrent calls?

Leave a Reply to Paul Nel Cancel Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.