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:

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:

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<HttpContext, RequestLoggingLevel> 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!

[ghost]

Thanks for contacting us.
We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We will evaluate the request when we are planning the work for the next milestone. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[jkotalik]

API Proposal:

namespace Microsoft.Extensions.DependencyInjection
{
    public static class HttpLoggingServicesExtensions
    {
        public static IServiceCollection AddHttpLogging(this IServiceCollection services, Action<HttpLoggingOptions> configureOptions) { }
    }
}
namespace namespace Microsoft.AspNetCore.Builder
{
    public static class HttpLoggingBuilderExtensions
    {
        public static IApplicationBuilder UseHttpLogging(this IApplicationBuilder app) { }
    }
}
namespace Microsoft.AspNetCore.HttpLogging
{
    public class HttpLoggingOptions
    {
        public HttpLoggingFields LoggingFields { get; set; } = HttpLoggingFields.RequestPropertiesAndHeaders | HttpLoggingFields.ResponsePropertiesAndHeaders;

        public HashSet<string> AllowedRequestHeaders { get; } = new HashSet<string>(StringComparer.OrdinalIgnoreCase)
        {
            HeaderNames.Accept,
            HeaderNames.AcceptEncoding,
            HeaderNames.AcceptLanguage,
            HeaderNames.Allow,
            HeaderNames.Connection,
            HeaderNames.ContentLength,
            HeaderNames.ContentType,
            HeaderNames.Host,
            HeaderNames.UserAgent
        };
        public HashSet<string> AllowedResponseHeaders { get; } = new HashSet<string>(StringComparer.OrdinalIgnoreCase)
        {
            HeaderNames.ContentLength,
            HeaderNames.ContentType,
            HeaderNames.TransferEncoding
        };

        public List<KeyValuePair<MediaTypeHeaderValue, Encoding>> SupportedMediaTypes { get; } = new List<KeyValuePair<MediaTypeHeaderValue, Encoding>>()
        {
            new KeyValuePair<MediaTypeHeaderValue, Encoding>(new MediaTypeHeaderValue("application/json"), Encoding.UTF8),
            new KeyValuePair<MediaTypeHeaderValue, Encoding>(new MediaTypeHeaderValue("application/*+json"), Encoding.UTF8),
            new KeyValuePair<MediaTypeHeaderValue, Encoding>(new MediaTypeHeaderValue("application/xml"), Encoding.UTF8),
            new KeyValuePair<MediaTypeHeaderValue, Encoding>(new MediaTypeHeaderValue("application/*+xml"), Encoding.UTF8),
            new KeyValuePair<MediaTypeHeaderValue, Encoding>(new MediaTypeHeaderValue("text/*"), Encoding.UTF8),
        };

        public int RequestBodyLogLimit { get; set; } = 32 * 1024;

        public int ResponseBodyLogLimit { get; set; } = 32 * 1024;
    }

    [Flags]
    public enum HttpLoggingFields : long
    {
        None = 0,
        Path = 1,
        Query = 2,
        Protocol = 4,
        Method = 8,
        Scheme = 0x10,
        StatusCode = 0x20,
        RequestHeaders = 0x40,
        ResponseHeaders = 0x80,
        RequestBody = 0x100,
        ResponseBody = 0x200,
        RequestProperties = Path | Query | Protocol | Method | Scheme,
        RequestPropertiesAndHeaders = RequestProperties | RequestHeaders,
        ResponsePropertiesAndHeaders = StatusCode | ResponseHeaders,
        Request = RequestPropertiesAndHeaders | RequestBody,
        Response = StatusCode | ResponseHeaders | ResponseBody,
        All = Request | Response
    }
}

[BrennanConroy]

Namespace?

[magnusbakken]

With this proposal, how would you exclude specific endpoints, or conditionally enable/disable logging of specific items for specific endpoints?

[davidfowl]

@magnusbakken we skipped that feature for preview4 but have plans to tackle it for preview5. @jkotalik can you file that issue?

Also we need to have benchmarks for this middleware

[davidfowl]

@jkotalik can you update the proposal based on your latest changes?

[jkotalik]

Tomorrow morning; there are still more changes I need to make 😄

[jkotalik]

Console:

JSON:

[BrennanConroy]

The Console log should have a title so you can tell it's a request or response log easily.

[jkotalik]

Seq:

[davidfowl]

Is that X the redacted text?

[jkotalik]

RequestProperties -> no one loves this name, can't come up with something better. Offline suggestions appreciated
Trailers -> Add to enum now
Path, Query, etc -> prefix with Request/Response for clarity
Interfaces for Set and List (internal fields for middleware access)

[BrennanConroy]

Can we see an example of request and response bodies?
If I'm looking at the code correctly, it looks like the headers and other info is a separate log from the bodies, are we interested in linking them somehow so users can see which headers go with which bodies?

[jkotalik]

AllowedRequestHeaders -> RequestHeaders and same for response

[jkotalik]

Make sure that encoding last parts of the byte array are not splicing characters due to truncation.

[jkotalik]

MediaTypeHeaderValue has encoding, use that instead.

[jkotalik]

Default to UTF8 if one isn't specified in the MTHV

[jkotalik]

New type for MTHV list that allows supporting binary and Encodings

namespace Microsoft.AspNetCore.HttpLogging
{
public sealed class MediaTypeOptions
{
   AddBinary(MediaTypeHeaderValue);
   AddBinary(string);
   AddText(MediaTypeHeaderValue);
   AddText(string);
   AddText(string, Encoding);
   Clear();
}
}

And add MediaTypeOptions to the HttpLoggingOptions.

[jkotalik]

If I'm looking at the code correctly, it looks like the headers and other info is a separate log from the bodies, are we interested in linking them somehow so users can see which headers go with which bodies?

How would you suggest linking them?

[BrennanConroy]

Idk, delay the whole log until the body is written so they're part of the same message, or generate some ID that both logs use?

[jkotalik]

The response body can be consolidated today, but request cannot; if someone doesn't read the request body, the request wouldn't be logged.

@shirhatti what's the typical way these logs would be associated?

[shirhatti]

Via logging scopes. Request id is already on the scope

[jkotalik]

Initial implementation committed, closing as we have follow up issues filed.