Aspnetcore: Add RequestLoggingMiddleware

[davidfowl]

There's lots of advice on how to log the headers and body of an incoming and outgoing http request (and response) on the interwebs:

• https://stackoverflow.com/questions/46361958/asp-net-core-mvc-log-request-body
• https://elanderson.net/2017/02/log-requests-and-responses-in-asp-net-core/

To name a few of them. They are not done in very safe ways:

• Some buffer the entire request body of every request (not respecting the IHttpBufferingFeature). This results in memory bloats (a potential DoS)
• Some don't rewind the Stream properly.
• The implementations aren't lazy
• There are security implications as well (sensitive data may be in headers, other PII, GDPR?)

It seems like lots of people are doing this and doing it incorrectly and inefficiently, we should add a middleware here as this is very common and requires no new dependencies.

Strawman:

```C#
public class RequestLoggingMiddlewareExtensions
{
public IApplicationBuilder UseRequestLogging(this IApplicationBuilder app) { }
public IApplicationBuilder UseRequestLogging(this IApplicationBuilder app, RequestLoggingOptions options) { }
}

public class RequestLoggingOptions
{
// Determines if the cookie header is logged
public bool LogCookieHeader { get; set; }
// Determines if the authorization header is logged
public bool LogAuthorizationHeader { get; set; }
// Determines the verbosity of the logs
public RequestLoggingLevel RequestLogLevel { get; set; }
}

[Flags]
public enum RequestLoggingLevel
{
None = 0,
RequestHeaders = 1,
ResponseHeaders = 2,
RequestBody = 4,
ResponseBody = 8,
AllRequest = RequestHeaders | RequestBody
AllResponse = RequestHeaders | RequestBody
All = AllRequest | AllResponse
}
```

cc @Tratcher

[Tratcher]

HttpClientFactory has some of this.

Rather than having a bool for cookie and a bool for auth, it should be a collection where they can exclude whatever they like. Or you could invert it to an include collection. Do you need separate collections for request and response headers? Probably not.

Are the request/response first lines implicitly included in the Headers? Or do you assume Hosting is logging those separately? How about Exceptions?

RequestLoggingLevel => ComponentsToLog

All makes it awkward to add other components later (e.g. timing, session, etc.). What's the default?

It needs an event where you can determine the components to log per request.

The downside of logging the request/response body in a lazy way is that it gets spread out across the logs and takes extra work to re-assemble.

[jkotalik]

I was thinking about this too with regards to diagnosing failures on azure. Though this is useful, I think it will nice if we push for a more FREB like middleware, which will only activate when certain conditions are met (conditions like status code and request timeout). In production environments, no one would want to have the RequestLoggingMiddleware on if it logs per request; this would give a nice middleground between diagnostics and performance.

Maybe something like this:

```c#
public class RequestLoggingMiddlewareExtensions
{
public IApplicationBuilder UseRequestLogging(this IApplicationBuilder app) { }
public IApplicationBuilder UseRequestLogging(this IApplicationBuilder app, RequestLoggingOptions options) { }
}

public class RequestLoggingOptions
{
// Determines if the cookie header is logged
public bool LogCookieHeader { get; set; }
// Determines if the authorization header is logged
public bool LogAuthorizationHeader { get; set; }
// Determines the verbosity of the logs
public RequestLoggingLevel RequestLogLevel { get; set; }
// Whether to only log failed requests (status code 500+)
// Consider making this configurable with int ranges
public bool OnlyLogFailedRequests { get; set; }
// Determines the timeout for when we should log a long hanging request
public TimeSpan RequestTimeout { get; set; } = TimeSpan.FromSeconds(10);
}

[Flags]
public enum RequestLoggingLevel
{
None = 0,
RequestHeaders = 1,
ResponseHeaders = 2,
RequestBody = 4,
ResponseBody = 8,
AllRequest = RequestHeaders | RequestBody
AllResponse = RequestHeaders | RequestBody
All = AllRequest | AllResponse
}
```

[davidfowl]

Rather than having a bool for cookie and a bool for auth, it should be a collection where they can exclude whatever they like. Or you could invert it to an include collection. Do you need separate collections for request and response headers? Probably not.

Feels like overkill, do we know what other types of headers people will want to exclude? It's the most flexible option for sure but I need to see some more real use cases first.

It needs an event where you can determine the components to log per request.

Maybe, it's not a bad idea. What are some examples of this and how does this interact with the RequestLoggingLevel enum? Is it basically IsEnabled(HttpContext context)?

Are the request/response first lines implicitly included in the Headers? Or do you assume Hosting is logging those separately? How about Exceptions?

I thought about this a bit when I was writing the proposal and I almost included it but it's already included by hosting. This also doesn't log exceptions. The ExceptionHandler middleware would do that.

All makes it awkward to add other components later (e.g. timing, session, etc.). What's the default?

Yep, possibly, maybe we just leave it out. Default would be just headers. Maybe we add AllHeaders to the enum.

The downside of logging the request/response body in a lazy way is that it gets spread out across the logs and takes extra work to re-assemble.

Yes, but we have to do it that way. I don't want a middleware that buffers the entire request body. We can say responses/requests are written in 1K-4K chunks or something.

It's possible we want to consider using event source for this as well.

@jkotalik Why is there a timeout on this middleware?

Though this is useful, I think it will nice if we push for a more FREB like middleware, which will only activate when certain conditions are met (conditions like status code and request timeout)

The func that @Tratcher suggests can handle this.

[jkotalik]

The func that @Tratcher suggests can handle this.

No it can't, the only way you can get the status code would be after the response is done, meaning we have to buffer the entire request/response. I guess these are tangential asks then as you don't want to buffer.

[Tratcher]

Interesting point. You could have a second event on response start to check if you want to log the response.

[Tratcher]

It needs an event where you can determine the components to log per request.

Maybe, it's not a bad idea. What are some examples of this and how does this interact with the RequestLoggingLevel enum? Is it basically IsEnabled(HttpContext context)?

Func perhaps? Though you might need separate events for request and response.

[Tratcher]

Determines the timeout for when we should log a long hanging request

Interesting, an explicit notification for requests that are taking too long.

[clement911]

The downside of logging the request/response body in a lazy way is that it gets spread out across the logs and takes extra work to re-assemble.

Yes, but we have to do it that way. I don't want a middleware that buffers the entire request body. We can say responses/requests are written in 1K-4K chunks or something.

I guess I understand for file upload requests, but for the vast majority of requests with HTTP FORM POST or json bodies, the body will be loaded in memory to deserialize to an object anyway.
Is it possible to check the content-type and decide whether to log the body eagerly or lazily based on it?
e.g. if content-type is json then eager. if file-upload, then lazy?
Maybe I'm missing something...

[davidfowl]

I guess I understand for file upload requests, but for the vast majority of requests with HTTP FORM POST or json bodies, the body will be loaded in memory to deserialize to an object anyway.

The memory requires to represent an object in memory and the memory required to deserialize are different things. You can allocate 5 gigs to produce 5 mb (I've seen this before 😄 ). Like it or not, you need to have limits, just log in reasonably sized chunks. 100KB is enough to blow up the large object heap. Here's a primer on some of the issues you can run into when running ASP.NET Core applications https://github.com/sebastienros/memoryleak.

[Mikilll94]

Is this going to be implemented?

[Mikilll94]

To name a few of them. They are not done in very safe ways:

• Some buffer the entire request body of every request (not respecting the IHttpBufferingFeature). This results in memory bloats (a potential DoS)
• Some don't rewind the Stream properly.

@davidfowl
Could you elaborate more on how to do logging request and response bodies to avoid these problems?

[Tratcher]

@Mikilll94 the concept is called read-through or write-through logging. E.g. for request bodies you make a Stream that wraps the request body Stream. Every time the caller calls Read/Async you pass that call through to the inner stream. Once it completes you log the results before returning them to the caller. The result is no buffering and incremental logging. The same process would work for response body writes.

[Mikilll94]

@Tratcher
Thanks for explanation.

Are there any code examples on the Internet which shows how to correctly log requests and responses in ASP.NET Core?

[Tratcher]

I'm not aware of any fully built examples. Logging the full request and response is discouraged because A) it's expensive, B) it can log potentially sensitive information like user credentials.

[Mikilll94]

@Tratcher

I know that requests for some endpoints should not be logged, i.e. endpoints related to authentication, but requests from other endpoints can be logged.

@davidfowl

Maybe you know some fully-build examples done in the right way?

[xsoheilalizadeh]

@davidfowl, I'm working on a library to do something similar.

[Mikilll94]

@xsoheilalizadeh
Awesome!