dotnet / dotnet/aspnetcore

Can't read response body neither in a custom logging middleware nor in built-in http logger via IHttpLoggingInterceptor.

Open
#52,731 8 comments 0 reactions 0 assignees View on GitHub
area-networking feature-http-logging Needs: Attention :wave:
Dominant language
C#
Stars
38.4k
Forks
10.9k
Avg merge
2d 6h
Merged PRs (30d)
290

Description

### Is there an existing issue for this?

- [X] I have searched the existing issues

### Describe the bug

When I tried to read `HttpLoggingInterceptorContext.HttpContext.Response.Body` via `StreamReader` it simply returns empty string.

When I tried to move that code inside `HttpLoggingInterceptorContext.HttpContext.Response.OnStarting` it's still an empty string.

Inside `HttpLoggingInterceptorContext.HttpContext.Response.OnCompleted` `HttpContext` is already unavailable from `HttpLoggingInterceptorContext.HttpContext`

I was trying to use [this code](https://stackoverflow.com/a/43404745/7402089) for the body reading itself. Was experimenting with multiple small changes while trying to adopt that middleware code to this interceptor code but it still doesn't work. How do I do that?

Previously I was trying to simply implement custom middleware for logging purposes. And I was also stuck at the point where I was trying to read a response body. However in my custom code I was getting `System.InvalidOperationException: The response headers cannot be modified because the response has already started.` at that line where it was trying to read stream from body via reader. It was happening even though I was just reading response, I didn't try to modify it in any possible way. Also it wasn't reproducable every time. Only when multiple async requests are processed at the same time. One by one it worked perfectly. And I've found [this discussion](https://github.com/dotnet/aspnetcore/issues/35364).

They mentioned that this bug was introduced from .NET 7 in that discussion. So we tried to update to .NET 8 hoping that it would solve the problem, but it didn't.

So eventually I've found out that built-in logger also has a way to customize it via code, not only options choice what to log and what to ignore. So I tried that. Good news - it doesn't give exception on trying to read body. Bad news - it always returns empty string.

Seems like it's a bug that might have a common root cause both in custom middleware exception case and empty string inside interceptor implementation.

### Expected Behavior

Response body should be able to be read both in middleware and IHttpLoggingInterceptor without exceptions.

### Steps To Reproduce

Create a custom middleware and try to read response body. Here's a code example from stackoverflow link above:

```
public class ResponseRewindMiddleware
{
private readonly RequestDelegate next;

public ResponseRewindMiddleware(RequestDelegate next) {
this.next = next;
}

public async Task Invoke(HttpContext context) {

Stream originalBody = context.Response.Body;

try {
using (var memStream = new MemoryStream()) {
context.Response.Body = memStream;

await next(context);

memStream.Position = 0;
string responseBody = new StreamReader(memStream).ReadToEnd();

memStream.Position = 0;
await memStream.CopyToAsync(originalBody);
}

} finally {
context.Response.Body = originalBody;
}

}
}
```

This approach gives exception `System.InvalidOperationException: The response headers cannot be modified because the response has already started.`. But in order to get this exception you need to send multiple async requests to the backend. So try to use this middleware with any available website code where you can, for instance, open a page and send multiple requests at the same time.

Also you might reproduce a second approach using default code from [this documentation](https://learn.microsoft.com/en-us/aspnet/core/fundamentals/http-logging/?view=aspnetcore-8.0#ihttplogginginterceptor) and try to read response body using a code like this in a IHttpLoggingInterceptor implementation:

```
public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext)
{
Stream originalBody = logContext.HttpContext.Response.Body;

try
{
using var memStream = new MemoryStream();
logContext.HttpContext.Response.Body = memStream;

memStream.Position = 0;
var responseBody = new StreamReader(memStream).ReadToEnd();

memStream.Position = 0;
memStream.CopyTo(originalBody);

// responseBody is always empty here
}
finally
{
logContext.HttpContext.Response.Body = originalBody;
}

return default;
}
```
Second way to reproduce it doesn't require multiple requests sent. It always behaves the same.

### Exceptions (if any)

System.InvalidOperationException: The response headers cannot be modified because the response has already started.

### .NET Version

8.0.100

### Anything else?

IDE: Microsoft Visual Studio Community 2022 (64-bit) - Current Version 17.8.2
`dotnet --info`:
.NET SDK:
Version: 8.0.100
Commit: 57efcf1350
Workload version: 8.0.100-manifests.8d38d0cc

Runtime Environment:
OS Name: Windows
OS Version: 10.0.22000
OS Platform: Windows
RID: win-x64
Base Path: C:\Program Files\dotnet\sdk\8.0.100\

.NET workloads installed:
Workload version: 8.0.100-manifests.8d38d0cc
[android]
Installation Source: VS 17.8.34322.80
Manifest Version: 34.0.43/8.0.100
Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.android\34.0.43\WorkloadManifest.json
Install Type: Msi

[maui-windows]
Installation Source: VS 17.8.34322.80
Manifest Version: 8.0.3/8.0.100
Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json
Install Type: Msi

[maccatalyst]
Installation Source: VS 17.8.34322.80
Manifest Version: 17.0.8478/8.0.100
Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maccatalyst\17.0.8478\WorkloadManifest.json
Install Type: Msi

[ios]
Installation Source: VS 17.8.34322.80
Manifest Version: 17.0.8478/8.0.100
Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.ios\17.0.8478\WorkloadManifest.json
Install Type: Msi

Host:
Version: 8.0.0
Architecture: x64
Commit: 5535e31a71

.NET SDKs installed:
5.0.408 [C:\Program Files\dotnet\sdk]
8.0.100 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
Microsoft.AspNetCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 6.0.25 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 6.0.25 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.NETCore.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 6.0.25 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 7.0.14 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
Microsoft.WindowsDesktop.App 8.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
x86 [C:\Program Files (x86)\dotnet]
registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables:
Not set

global.json file:
Not found

Learn more:
https://aka.ms/dotnet/info

Download .NET:
https://aka.ms/dotnet/download

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.