HttpLoggingMiddleware does not log RequestBody when body is consumed by copying to another stream

[olegbaslak]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

When HttpLoggingMiddleware is enabled and HttpContext.Request.Body is consumed by copying to another stream (calling CopyToAsync) instead of reading, an empty RequestBody is logged after an endpoint is executed.

Expected Behavior

Not empty request body is logged when calling CopyToAsync, e.g. when sending json body

{
    "Response": "Test Response"
}

it should be logged as is.

Steps To Reproduce

1. Simple Program.cs of ASP.NET Core project that copies request into memory stream and writes it back to response:

using System.Text;
using Microsoft.AspNetCore.HttpLogging;

var builder = WebApplication.CreateBuilder(args);
builder.Services.AddHttpLogging(options => { options.LoggingFields = HttpLoggingFields.RequestBody; });

var app = builder.Build();

app.MapGet("/", async context =>
{
    // context.Request.EnableBuffering(); // Enabling buffering "fixes" the issue

    using var tempStream = new MemoryStream();
    await context.Request.Body.CopyToAsync(tempStream);

    var responseContent = Encoding.Default.GetString(tempStream.ToArray());
    await context.Response.WriteAsync(responseContent);
});

app.UseHttpLogging();
await app.RunAsync();

2. Send a request to / endpoint with some json body, e.g. { "Response": "Test Response" }
3. Observe logs.

Logs:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET https://localhost:7255/ application/json 37
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      Request:

info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[3]
      RequestBody:
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET https://localhost:7255/ application/json 37 - 200 - - 38.6330ms

Exceptions (if any)

Enabling buffering by uncommenting context.Request.EnableBuffering(); line.

Logs in this case:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET https://localhost:7255/ application/json 37
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      Request:

info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[3]
      RequestBody: {
          "Response": "Test Response"
      }
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET https://localhost:7255/ application/json 37 - 200 - - 25.6788ms

Probably it happens because FileBufferingReadStream calls ReadAsync methods on the inner stream (in this case inner is RequestBufferingStream) in its CopyToAsync implementation. And RequestBufferingStream, when not wrapped, does not write anything in its buffer when CopyToAsync is called.

.NET Version

7.0.203

Anything else?

ASP.NET Core: 7.0.5
IDE: Visual Studio 2022, Rider

Also reproducible for .NET 6

[BrennanConroy]

Try using 7.07 or later, we fixed a bug that sounds similar
#47811

[olegbaslak]

Try using 7.07 or later, we fixed a bug that sounds similar #47811

Hi @BrennanConroy, thank you for quick reply! Tried 7.0.10. No luck, unfortunately. I assume it is not connected to #47811 because calling CopyToAsync does not trigger Read or ReadAsync methods at all.

[BrennanConroy]

Ok, thanks for giving it a try 😃

[Tratcher]

Ah,

aspnetcore/src/Middleware/HttpLogging/src/RequestBufferingStream.cs

Line 10 in 31a26e0

internal sealed class RequestBufferingStream : BufferingStream

Doesn't override CopyTo/Async from the base stream:

aspnetcore/src/Middleware/HttpLogging/src/BufferingStream.cs

Lines 298 to 306 in 31a26e0

	public override void CopyTo(Stream destination, int bufferSize)
	{
	_innerStream.CopyTo(destination, bufferSize);
	}
	public override Task CopyToAsync(Stream destination, int bufferSize, CancellationToken cancellationToken)
	{
	return _innerStream.CopyToAsync(destination, bufferSize, cancellationToken);
	}

So CopyTo/Async skips the logging buffer.

FileBufferingReadStream that's used by EnableBuffering does override CopyTo/Async and calls ReadAsync on the inner logging stream so it's fine.

aspnetcore/src/Http/WebUtilities/src/FileBufferingReadStream.cs

Lines 427 to 438 in 31a26e0

	public override Task CopyToAsync(Stream destination, int bufferSize, CancellationToken cancellationToken)
	{
	// Set a minimum buffer size of 4K since the base Stream implementation has weird behavior when the stream is
	// seekable *and* the length is 0 (it passes in a buffer size of 1).
	// See https://github.com/dotnet/runtime/blob/222415c56c9ea73530444768c0e68413eb374f5d/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs#L164-L184
	bufferSize = Math.Max(4096, bufferSize);
	// If we're completed buffered then copy from the underlying source
	if (_completelyBuffered)
	{
	return _buffer.CopyToAsync(destination, bufferSize, cancellationToken);
	}

Fix: RequestBufferingStream must override CopyTo/Async like FileBufferingReadStream does. Actually, we could put that logic in the base BufferingStream class, having it delegate to Read/Async so the normal buffering could happen.

Side note: Why does your GET request have a body? That's odd.

[olegbaslak]

@Tratcher very detailed comment, thanks! So it is exactly how I thought.

Regarding GET... Sometimes, answer is very easy. It is postman default request type for new requests. I just didn't bother changing it 😁