How I did it 4 years ago
We shipped an application that was running behind a pretty...obscure WAF. They promised us that their product would not interfere in anyway with our application. That was wrong. They stripped almost all of our "custom" headers. To "prove" this I built a middleware that stored all unique headers that we received and sent out. I then created an endpoint that dumped all the headers.
I created a custom middleware, LogHeadersMiddleware.
public class LogHeadersMiddleware
{
private readonly RequestDelegate _next;
private readonly ILogger<LogHeadersMiddleware> _logger;
public static readonly List<string> RequestHeaders = new List<string>();
public static readonly List<string> ResponseHeaders = new List<string>();
public LogHeadersMiddleware(RequestDelegate next, ILogger<LogHeadersMiddleware> logger)
{
_next = next;
_logger = logger;
}
public async Task Invoke(HttpContext context)
{
var uniqueRequestHeaders = context.Request.Headers
.Where(x => RequestHeaders.All(r => r != x.Key))
.Select(x => x.Key);
RequestHeaders.AddRange(uniqueRequestHeaders);
await _next.Invoke(context);
var uniqueResponseHeaders = context.Response.Headers
.Where(x => ResponseHeaders.All(r => r != x.Key))
.Select(x => x.Key);
ResponseHeaders.AddRange(uniqueResponseHeaders);
// Log unique headers with ILogger
...
}
}
I then registered it like this early in the middleware pipeline
app.UseLogHeadersMiddleware();
app.Map("/show-headers", ShowHeaders);
So by going to /show-headers you would see a dump of all the (unique) headers that our application had recieved and sent out.
The new way
Microsoft has now added support for HTTP logging in ASP.NET Core.
They have created their own middleware, you can enable it like this:
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
// Important to have it as early as possible
app.UseHttpLogging();
...
...
...
}
If you don't do any customization, the following stuff will be logged by default (both request and response):
Request path
Status code
Querystring
Headers
Example - default implementation
POST request to /user/login
Body
{
"username": "josef",
"password": "MyPassword"
}
Request
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
Request:
Protocol: HTTP/1.1
Method: POST
Scheme: http
PathBase:
Path: /user/login
QueryString:
Accept: */*
Connection: keep-alive
Host: localhost:5000
User-Agent: PostmanRuntime/7.28.1
Accept-Encoding: gzip, deflate, br
Content-Type: application/json
Content-Length: 60
Response
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
Response:
StatusCode: 200
Content-Type: application/json; charset=utf-8
Date: [Redacted]
Server: [Redacted]
Transfer-Encoding: chunked
As you can see, with the default configuration, nothing sensitive is logged.
Let's see how we can configure the middleware to log some sensitive data.
Example - logging request/response body
Request body (DANGEROUS)
This will log the request headers and body
services.AddHttpLogging(options =>
{
options.LoggingFields = HttpLoggingFields.RequestPropertiesAndHeaders |
HttpLoggingFields.RequestBody;
});
Body
{
"username": "josef",
"password": "MyPassword"
}
Request
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
Request:
Protocol: HTTP/1.1
Method: POST
Scheme: http
PathBase:
Path: /user/login
QueryString:
Accept: */*
Connection: keep-alive
Host: localhost:5000
User-Agent: PostmanRuntime/7.28.1
Accept-Encoding: gzip, deflate, br
Content-Type: application/json
Content-Length: 60
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
RequestBody: {
"username": "josef",
"password": "MyPassword"
}
Response body (DANGEROUS)
This will log the response headers and body
services.AddHttpLogging(options =>
{
options.LoggingFields = HttpLoggingFields.ResponsePropertiesAndHeaders |
HttpLoggingFields.ResponseBody;
});
Body
{
"username": "josef",
"password": "MyPassword"
}
Response
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[1]
Response:
StatusCode: 200
Content-Type: application/json; charset=utf-8
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
ResponseBody: {"token":"very secret token"}
As you can see, we are now logging the request and response body. This can be very powerful during development/debugging but you would most likely never want to do this in production. By blindly logging the request/response headers/body you can (most likely will) log sensitive data. If you feel that you have the need to log headers and bodies, make sure that you use an opt-in strategy instead, something like this:
services.AddHttpLogging(options =>
{
options.LoggingFields = HttpLoggingFields.RequestPropertiesAndHeaders |
HttpLoggingFields.ResponsePropertiesAndHeaders;
options.ResponseHeaders.Add("Non-Sensitive");
});
When calling the following action...
[HttpGet("api/weather")]
public IActionResult Index()
{
Response.Headers.Add("Sensitive", "034D4CD7-2FEB-4B19-86A3-CFCD5DB291AA");
Response.Headers.Add("Non-Sensitive", "Hello");
return new OkObjectResult(new
{
data = "Hello World"
});
}
...only the Non-Sensitive header value will be logged
Request
info: Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware[2]
Response:
StatusCode: 200
Content-Type: application/json; charset=utf-8
Date: [Redacted]
Server: [Redacted]
Transfer-Encoding: chunked
Sensitive: [Redacted]
Non-Sensitive: Hello
Performance
It's also important to think about how the performance of your application can suffer when logging the request/response body.
GET
Without HttpLogging
❯ .\bombardier.exe -c 125 -n 100000 http://localhost:5000/api/weather
Bombarding http://localhost:5000/api/weather with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 2287/s 43s
Done!
Statistics Avg Stdev Max
Reqs/sec 2292.70 326.38 7095.61
Latency 54.52ms 2.29ms 109.00ms
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 727.39KB/s
Default settings for HttpLogging
❯ .\bombardier.exe -c 125 -n 100000 http://localhost:5000/api/weather
Bombarding http://localhost:5000/api/weather with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 1492/s 1m6s
Done!
Statistics Avg Stdev Max
Reqs/sec 1496.73 287.61 4500.00
Latency 83.52ms 15.73ms 0.86s
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 474.86KB/s
Request/Response body logging enabled
❯ .\bombardier.exe -c 125 -n 100000 http://localhost:5000/api/weather
Bombarding http://localhost:5000/api/weather with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 1466/s 1m8s
Done!
Statistics Avg Stdev Max
Reqs/sec 1471.50 285.97 5090.86
Latency 84.96ms 17.64ms 0.87s
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 466.79KB/s
When turning on HttpLogging the throughput goes from ~2300 req/s to ~1500 req/s.
POST
Without HttpLogging
❯ .\bombardier.exe -m POST http://localhost:5000/user/login -c 125 -n 100000 --duration 1s -l -H "Content-Type: application/json" -f "login.json"
Bombarding http://localhost:5000/user/login with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 2112/s 47s
Done!
Statistics Avg Stdev Max
Reqs/sec 2118.76 444.32 6498.38
Latency 59.03ms 14.41ms 576.00ms
Latency Distribution
50% 57.00ms
75% 59.96ms
90% 70.00ms
95% 75.00ms
99% 90.81ms
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 771.02KB/s
Default settings for HttpLogging
❯ .\bombardier.exe -m POST http://localhost:5000/user/login -c 125 -n 100000 --duration 1s -l -H "Content-Type: application/json" -f "login.json"
Bombarding http://localhost:5000/user/login with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 1388/s 1m12s
Done!
Statistics Avg Stdev Max
Reqs/sec 1392.11 328.62 8995.50
Latency 89.92ms 19.01ms 1.09s
Latency Distribution
50% 88.00ms
75% 91.00ms
90% 97.00ms
95% 111.00ms
99% 125.00ms
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 506.18KB/s
Request/Response body logging enabled
❯ .\bombardier.exe -m POST http://localhost:5000/user/login -c 125 -n 100000 --duration 1s -l -H "Content-Type: application/json" -f "login.json"
Bombarding http://localhost:5000/user/login with 100000 request(s) using 125 connection(s)
100000 / 100000 [==========================================] 100.00% 1281/s 1m18s
Done!
Statistics Avg Stdev Max
Reqs/sec 1284.89 311.66 4550.25
Latency 97.31ms 21.58ms 1.22s
Latency Distribution
50% 95.00ms
75% 99.00ms
90% 108.00ms
95% 119.00ms
99% 150.00ms
HTTP codes:
1xx - 0, 2xx - 100000, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 467.73KB/s
As we can see, by logging more stuff, the performance takes a toll. When logging the request/response body we are losing an additional ~100 req/s.
