HttpLoggingMiddleware does not log all response headers when log response body

WeihanLi commented 3 years ago

Describe the bug

When I use the HttpLoggingMiddleware to log the response body, the response header would not be logged as expected, not know if this is by design, guessing that it may caused by https://github.com/dotnet/aspnetcore/blob/v6.0.0-rc.1.21452.15/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs#L172

To Reproduce

Just create a api project with dotnet new webapi -n HttpLoggingMiddlewareSample --no-openapi --no-https, then add UseHttpLogging() to the request pipeline, and customize the logging option, modified the sample likes follows:

var builder = WebApplication.CreateBuilder(args);

builder.Services.AddControllers();
builder.Services.AddHttpLogging(options =>
{
    options.LoggingFields = Microsoft.AspNetCore.HttpLogging.HttpLoggingFields.All;
    options.RequestHeaders.Add("Cache-Control");
    options.ResponseHeaders.Add("Server");
});
var app = builder.Build();

// Configure the HTTP request pipeline.
app.UseHttpLogging();
app.MapControllers();

app.Run();

sample project: https://github.com/WeihanLi/SamplesInPractice/blob/master/net6sample/HttpLoggingMiddlewareSample/Program.cs

When I specific the logging fields with All, the response headers are not been logged, I got logs like below:

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      Request:
      Protocol: HTTP/1.1
      Method: GET
      Scheme: http
      PathBase:
      Path: /weatherforecast
      Host: localhost:5084
      User-Agent: dotnet-HTTPie/0.1.1
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      Response:
      StatusCode: 200
      Content-Type: application/json; charset=utf-8
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[4]
      ResponseBody: [{"date":"2021-09-25T22:37:45.0463903+08:00","temperatureC":-2,"temperatureF":29,"summary":"Mild"},{"date":"2021-09-26T22:37:45.0498642+08:00","temperatureC":-20,"temperatureF":-3,"summary":"Cool"},{"date":"2021-09-27T22:37:45.0498738+08:00","temperatureC":-20,"temperatureF":-3,"summary":"Freezing"},{"date":"2021-09-28T22:37:45.0498741+08:00","temperatureC":-15,"temperatureF":6,"summary":"Cool"},{"date":"2021-09-29T22:37:45.0498743+08:00","temperatureC":23,"temperatureF":73,"summary":"Balmy"}]

while when I commented the LoggingFields config, the response headers would be logged, I get logs as follows:

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
      Request:
      Protocol: HTTP/1.1
      Method: GET
      Scheme: http
      PathBase:
      Path: /weatherforecast
      Host: localhost:5084
      User-Agent: dotnet-HTTPie/0.1.1
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      Response:
      StatusCode: 200
      Content-Type: application/json; charset=utf-8
      Date: [Redacted]
      Server: Kestrel
      Transfer-Encoding: chunked

Exceptions (if any)

The response headers should be logged

Further technical details

ASP.NET Core version：.NET 6 RC 1
The IDE: VS 2022 Preview 4/ dotnet cli(.NET 6 RC1)
Include the output of dotnet --info

.NET SDK (reflecting any global.json):
 Version:   6.0.100-rc.1.21458.32
 Commit:    d7c22323c4

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.22463
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\6.0.100-rc.1.21458.32\

Host (useful for support):
  Version: 6.0.0-rc.1.21451.13
  Commit:  d7619cd4b1

.NET SDKs installed:
  2.1.802 [C:\Program Files\dotnet\sdk]
  2.2.300 [C:\Program Files\dotnet\sdk]
  3.1.300 [C:\Program Files\dotnet\sdk]
  3.1.301 [C:\Program Files\dotnet\sdk]
  3.1.412 [C:\Program Files\dotnet\sdk]
  5.0.400 [C:\Program Files\dotnet\sdk]
  6.0.100-rc.1.21458.32 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.All 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.18 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.0-rc.1.21452.15 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.18 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.0-rc.1.21451.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.1.18 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.0-rc.1.21451.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

adityamandaleeka commented 3 years ago

Thanks for reporting this, we will investigate. It's interesting that we only log the headers if the body is empty.

Tratcher commented 3 years ago

The response headers are logged in your first example just not all of them.

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
      Response:
      StatusCode: 200
      Content-Type: application/json; charset=utf-8

The missing headers are all ones added dynamically by the server when finalizing the response.

      Date: [Redacted]
      Server: Kestrel
      Transfer-Encoding: chunked

The difference you observe between the scenarios is because of when the headers are logged. When body logging is enabled the header logging happens during the first body write, before the server generates those automatic values. When body logging is disabled the headers aren't logged until the end of the request.

Possible fix: when body logging is enabled, log the headers just after the first write rather than before it. That will let them finish generating first.

Priority: Low. While this is inconsistent, these automatic headers are less important than app headers in most scenarios.

WeihanLi commented 3 years ago

@Tratcher thanks for your investigation, currently, we may log before the request is handled, not sure if it's a good idea to log only when the request had been handled, and I think maybe it's better to add a try-finally clause to ensure the logs would be logged even when there's an exception

ghost commented 2 years ago

Thanks for contacting us. We're moving this issue to the .NET 8 Planning milestone for future evaluation / consideration. Because it's not immediately obvious that this is a bug in our framework, we would like to keep this around to collect more feedback, which can later help us determine the impact of it. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

drew-cooper commented 2 years ago

I'm also experience this issue, but in my case it's headers that are added in the HttpResponse.OnStarting callback. These headers are logged when Response Body logging is off, but not otherwise. The callback is set up in Middleware which is after the HttpLoggingMiddleware and before the ASP.Net Controller pipeline.

Tratcher commented 2 years ago

dotnet / aspnetcore