.NET 6 中的 Http Logging 中间件

Intro

.NET 6 会引入一个 Http logging 的中间件，可以用来帮助我们比较方便记录请求和响应的信息

Sample

废话不多说，直接来看示例吧

var builder = WebApplication.CreateBuilder(args);builder.Services.AddControllers();
var app = builder.Build();app.UseHttpLogging();
app.MapControllers();app.Run();

dotnet run 运行起来项目，然后访问一个接口就可以看到打印出来的 Http logging 的日志了

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]Request:Protocol: HTTP/1.1Method: GETScheme: httpPathBase:Path: /weatherforecastAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9Connection: keep-aliveHost: localhost:5084User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.54 Safari/537.36Accept-Encoding: gzip, deflate, brAccept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7Cache-Control: [Redacted]Upgrade-Insecure-Requests: [Redacted]sec-ch-ua: [Redacted]sec-ch-ua-mobile: [Redacted]sec-ch-ua-platform: [Redacted]Sec-Fetch-Site: [Redacted]Sec-Fetch-Mode: [Redacted]Sec-Fetch-User: [Redacted]Sec-Fetch-Dest: [Redacted]
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]Response:StatusCode: 200Content-Type: application/json; charset=utf-8Date: [Redacted]Server: [Redacted]Transfer-Encoding: chunked

默认地，HttpLoggingMiddleware 会记录请求的基本信息（请求地址，协议版本）和请求头信息以及响应状态和响应头信息，对于不在默认列表里的请求头和响应头，值会显示为 [Redacted]，如果需要记录这个请求头/响应头的值则需要配置 HttpLoggingOptions，可以在注册服务的时候进行配置，配置示例如下：

builder.Services.AddHttpLogging(options =>
{options.RequestHeaders.Add("Cache-Control");options.ResponseHeaders.Add("Server");
});

修改之后，重新启动并请求我们的服务，日志输出如下：

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]Request:Protocol: HTTP/1.1Method: GETScheme: httpPathBase:Path: /weatherforecastAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9Connection: keep-aliveHost: localhost:5084User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.54 Safari/537.36Accept-Encoding: gzip, deflate, brAccept-Language: zh-CN,zh;q=0.9,en-US;q=0.8,en;q=0.7Cache-Control: max-age=0Upgrade-Insecure-Requests: [Redacted]sec-ch-ua: [Redacted]sec-ch-ua-mobile: [Redacted]sec-ch-ua-platform: [Redacted]Sec-Fetch-Site: [Redacted]Sec-Fetch-Mode: [Redacted]Sec-Fetch-User: [Redacted]Sec-Fetch-Dest: [Redacted]
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]Response:StatusCode: 200Content-Type: application/json; charset=utf-8Date: [Redacted]Server: KestrelTransfer-Encoding: chunked

注意看一下请求头里的 Cache-Control 和响应头里的 Server，原来都是 [Redacted]，配置之后就显示正确的值了，如果你要记录自定义的请求头信息，也是类似的配置

接着我们来配置一下记录请求信息和响应信息，可以配置 HttpLoggingOptions 中的 LoggingFields 来指定需要记录哪些信息

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

在上面的基础上增加 LoggingFields 的配置，这里直接配置上所有的信息，此时再来重新请求，查看日志如下：

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]Request:Protocol: HTTP/1.1Method: GETScheme: httpPathBase:Path: /weatherforecastHost: localhost:5084User-Agent: dotnet-HTTPie/0.1.1
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]Response:StatusCode: 200Content-Type: application/json; charset=utf-8
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[4]ResponseBody: [{"date":"2021-09-25T23:40:11.0164783+08:00","temperatureC":37,"temperatureF":98,"summary":"Cool"},{"date":"2021-09-26T23:40:11.0164836+08:00","temperatureC":50,"temperatureF":121,"summary":"Warm"},{"date":"2021-09-27T23:40:11.0164838+08:00","temperatureC":-7,"temperatureF":20,"summary":"Scorching"},{"date":"2021-09-28T23:40:11.016484+08:00","temperatureC":39,"temperatureF":102,"summary":"Freezing"},{"date":"2021-09-29T23:40:11.0164842+08:00","temperatureC":4,"temperatureF":39,"summary":"Balmy"}]

可以看到此时的 response body 也记录下来了

我们再来增加一个 POST 的 API 来验证一下 RequestBody 是不是可以正常记录

[HttpPost]
public IActionResult Post(System.Text.Json.JsonElement element) => Ok(element);

使用 dotnet-httpie 执行 http :5084/weatherforecast name=test

请求一下 API，输出日志如下：

info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]Request:Protocol: HTTP/1.1Method: POSTScheme: httpPathBase:Path: /weatherforecastHost: localhost:5084User-Agent: dotnet-HTTPie/0.1.1Content-Type: application/json; charset=utf-8Content-Length: 15
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[3]RequestBody: {"name":"test"}
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]Response:StatusCode: 200Content-Type: application/json; charset=utf-8
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[4]ResponseBody: {"name":"test"}

仔细看上面的示例的话会发现一个问题，当要记录 ResponseBody 的时候，Response header 的信息没有被完全记录下来，感觉像是一个 BUG，提了一个 issue 还没回复，感兴趣的可以参考：<https://github.com/dotnet/aspnetcore/issues/36920>

另外感觉这个中间件的日志级别都是 Information 级别的，如果可以根据响应状态来动态配置日志级别就好了，比如说响应状态码大于等于 500 的时候，日志级别记录为 ERROR, 这样就可以有效地去除很多不必要的日志了，提了一个简陋的 PR，有兴趣的可以参考：https://github.com/dotnet/aspnetcore/pull/36873

References

https://github.com/WeihanLi/SamplesInPractice/blob/master/net6sample/HttpLoggingMiddlewareSample/Program.cs
https://github.com/dotnet/aspnetcore/blob/v6.0.0-rc.1.21452.15/src/Middleware/HttpLogging/
https://github.com/dotnet/aspnetcore/blob/v6.0.0-rc.1.21452.15/src/Middleware/HttpLogging/src/HttpLoggingMiddleware.cs#L172
https://github.com/dotnet/aspnetcore/issues/36920
https://github.com/dotnet/aspnetcore/pull/36873