HttpLogging redaction and enrichment (#50163)

* Proof of concept for extending http logging

* Feedback, cleanup

* Nits

* Add duration

* Fix log, test

* Pool log contexts

* API review

* Cleanup, TimeProvider

* Duration

* Write temp files to the current dir, it might be on a different/faster drive.

* Cleanup

* Tests

* Fix CopyTo/Async #49989

* Apply suggestions from code review

Co-authored-by: Sébastien Ros <sebastienros@gmail.com>

* Clarify code check error

* Comments, copyto, TryOverride

* Usings

* Code review, comments, tests

* Restructuring

* Note when the request body was not fully logged #49063

* Powershell fix?

* Revert "Clarify code check error"

* Feedback

* Feedback

* Combine logs, log even if an exception happens

* Clarify

* Don't log empty response body

* Getting cozy

* Simplify Duration

* Less pooling

* Clean up comments

* Even less re-use

* Clean up Unshipped.txt

* Re-fix Unshipped

---------

Co-authored-by: Sébastien Ros <sebastienros@gmail.com>

src/Middleware/HttpLogging/samples/HttpLogging.Sample/SampleHttpLoggingInterceptor.cs

@@ -0,0 +1,87 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using Microsoft.AspNetCore.HttpLogging;
+
+namespace HttpLogging.Sample;
+
+internal sealed class SampleHttpLoggingInterceptor : IHttpLoggingInterceptor
+{
+    public ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext)
+    {
+        // Compare to ExcludePathStartsWith
+        if (!logContext.HttpContext.Request.Path.StartsWithSegments("/api"))
+        {
+            logContext.LoggingFields = HttpLoggingFields.None;
+        }
+
+        // Don't enrich if we're not going to log any part of the request
+        if (!logContext.IsAnyEnabled(HttpLoggingFields.Request))
+        {
+            return default;
+        }
+
+        if (logContext.TryDisable(HttpLoggingFields.RequestPath))
+        {
+            RedactPath(logContext);
+        }
+
+        if (logContext.TryDisable(HttpLoggingFields.RequestHeaders))
+        {
+            RedactRequestHeaders(logContext);
+        }
+
+        EnrichRequest(logContext);
+
+        return default;
+    }
+
+    private void RedactRequestHeaders(HttpLoggingInterceptorContext logContext)
+    {
+        foreach (var header in logContext.HttpContext.Request.Headers)
+        {
+            logContext.AddParameter(header.Key, "RedactedHeader"); // TODO: Redact header value
+        }
+    }
+
+    private void RedactResponseHeaders(HttpLoggingInterceptorContext logContext)
+    {
+        foreach (var header in logContext.HttpContext.Response.Headers)
+        {
+            logContext.AddParameter(header.Key, "RedactedHeader"); // TODO: Redact header value
+        }
+    }
+
+    public ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext)
+    {
+        // Don't enrich if we're not going to log any part of the response
+        if (!logContext.IsAnyEnabled(HttpLoggingFields.Response))
+        {
+            return default;
+        }
+
+        if (logContext.TryDisable(HttpLoggingFields.ResponseHeaders))
+        {
+            RedactResponseHeaders(logContext);
+        }
+
+        EnrichResponse(logContext);
+
+        return default;
+    }
+
+    private void EnrichResponse(HttpLoggingInterceptorContext logContext)
+    {
+        logContext.AddParameter("ResponseEnrichment", "Stuff");
+    }
+
+    private void EnrichRequest(HttpLoggingInterceptorContext logContext)
+    {
+        logContext.AddParameter("RequestEnrichment", "Stuff");
+    }
+
+    private void RedactPath(HttpLoggingInterceptorContext logContext)
+    {
+        logContext.AddParameter(nameof(logContext.HttpContext.Request.Path), "RedactedPath");
+    }
+}

src/Middleware/HttpLogging/samples/HttpLogging.Sample/Startup.cs

@@ -15,6 +15,7 @@ public void ConfigureServices(IServiceCollection services)
         {
             logging.LoggingFields = HttpLoggingFields.All;
         });
+        services.AddHttpLoggingInterceptor<SampleHttpLoggingInterceptor>();
     }
 
     // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.

src/Middleware/HttpLogging/src/BufferingStream.cs

@@ -47,7 +47,7 @@ public override int WriteTimeout
         set => _innerStream.WriteTimeout = value;
     }
 
-    public string GetString(Encoding? encoding)
+    public string GetString(Encoding encoding)
     {
         try
         {
@@ -57,13 +57,6 @@ public string GetString(Encoding? encoding)
                 return "";
             }
 
-            if (encoding == null)
-            {
-                // This method is used only for the response body
-                _logger.UnrecognizedMediaType("response");
-                return "";
-            }
-
             // Only place where we are actually using the buffered data.
             // update tail here.
             _tail.End = _tailBytesBuffered;
@@ -295,15 +288,7 @@ public override void EndWrite(IAsyncResult asyncResult)
         _innerStream.EndWrite(asyncResult);
     }
 
-    public override void CopyTo(Stream destination, int bufferSize)
-    {
-        _innerStream.CopyTo(destination, bufferSize);
-    }
-
-    public override Task CopyToAsync(Stream destination, int bufferSize, CancellationToken cancellationToken)
-    {
-        return _innerStream.CopyToAsync(destination, bufferSize, cancellationToken);
-    }
+    // Do not override CopyTo/Async, they call Read/Async internally.
 
     public override ValueTask<int> ReadAsync(Memory<byte> buffer, CancellationToken cancellationToken = default)
     {
@@ -314,9 +299,4 @@ public override ValueTask DisposeAsync()
     {
         return _innerStream.DisposeAsync();
     }
-
-    public override int Read(Span<byte> buffer)
-    {
-        return _innerStream.Read(buffer);
-    }
 }

src/Middleware/HttpLogging/src/HttpRequestLog.cs → src/Middleware/HttpLogging/src/HttpLog.cs

@@ -6,16 +6,18 @@
 
 namespace Microsoft.AspNetCore.HttpLogging;
 
-internal sealed class HttpRequestLog : IReadOnlyList<KeyValuePair<string, object?>>
+internal sealed class HttpLog : IReadOnlyList<KeyValuePair<string, object?>>
 {
     private readonly List<KeyValuePair<string, object?>> _keyValues;
+    private readonly string _title;
     private string? _cachedToString;
 
-    internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HttpRequestLog)state).ToString();
+    internal static readonly Func<object, Exception?, string> Callback = (state, exception) => ((HttpLog)state).ToString();
 
-    public HttpRequestLog(List<KeyValuePair<string, object?>> keyValues)
+    public HttpLog(List<KeyValuePair<string, object?>> keyValues, string title)
     {
         _keyValues = keyValues;
+        _title = title;
     }
 
     public KeyValuePair<string, object?> this[int index] => _keyValues[index];
@@ -35,10 +37,11 @@ public override string ToString()
     {
         if (_cachedToString == null)
         {
-            // Use 2kb as a rough average size for request headers
+            // Use 2kb as a rough average size for request/response headers
             var builder = new ValueStringBuilder(2 * 1024);
             var count = _keyValues.Count;
-            builder.Append("Request:");
+            builder.Append(_title);
+            builder.Append(':');
             builder.Append(Environment.NewLine);
 
             for (var i = 0; i < count - 1; i++)

src/Middleware/HttpLogging/src/HttpLoggingExtensions.cs

@@ -7,21 +7,21 @@ namespace Microsoft.AspNetCore.HttpLogging;
 
 internal static partial class HttpLoggingExtensions
 {
-    public static void RequestLog(this ILogger logger, HttpRequestLog requestLog) => logger.Log(
+    public static void RequestLog(this ILogger logger, HttpLog requestLog) => logger.Log(
         LogLevel.Information,
         new EventId(1, "RequestLog"),
         requestLog,
         exception: null,
-        formatter: HttpRequestLog.Callback);
-    public static void ResponseLog(this ILogger logger, HttpResponseLog responseLog) => logger.Log(
+        formatter: HttpLog.Callback);
+    public static void ResponseLog(this ILogger logger, HttpLog responseLog) => logger.Log(
         LogLevel.Information,
         new EventId(2, "ResponseLog"),
         responseLog,
         exception: null,
-        formatter: HttpResponseLog.Callback);
+        formatter: HttpLog.Callback);
 
-    [LoggerMessage(3, LogLevel.Information, "RequestBody: {Body}", EventName = "RequestBody")]
-    public static partial void RequestBody(this ILogger logger, string body);
+    [LoggerMessage(3, LogLevel.Information, "RequestBody: {Body}{Status}", EventName = "RequestBody")]
+    public static partial void RequestBody(this ILogger logger, string body, string status);
 
     [LoggerMessage(4, LogLevel.Information, "ResponseBody: {Body}", EventName = "ResponseBody")]
     public static partial void ResponseBody(this ILogger logger, string body);
@@ -34,4 +34,14 @@ internal static partial class HttpLoggingExtensions
 
     [LoggerMessage(7, LogLevel.Debug, "No Content-Type header for {Name} body.", EventName = "NoMediaType")]
     public static partial void NoMediaType(this ILogger logger, string name);
+
+    [LoggerMessage(8, LogLevel.Information, "Duration: {Duration}ms", EventName = "Duration")]
+    public static partial void Duration(this ILogger logger, double duration);
+
+    public static void RequestResponseLog(this ILogger logger, HttpLog log) => logger.Log(
+        LogLevel.Information,
+        new EventId(9, "RequestResponseLog"),
+        log,
+        exception: null,
+        formatter: HttpLog.Callback);
 }

src/Middleware/HttpLogging/src/HttpLoggingFields.cs

@@ -135,6 +135,11 @@ public enum HttpLoggingFields : long
     /// </summary>
     ResponseBody = 0x800,
 
+    /// <summary>
+    /// Flag for logging how long it took to process the request and response in milliseconds.
+    /// </summary>
+    Duration = 0x1000,
+
     /// <summary>
     /// Flag for logging a collection of HTTP Request properties,
     /// including <see cref="RequestPath"/>, <see cref="RequestProtocol"/>,
@@ -158,7 +163,7 @@ public enum HttpLoggingFields : long
 
     /// <summary>
     /// Flag for logging HTTP Response properties and headers.
-    /// Includes <see cref="ResponseStatusCode"/> and <see cref="ResponseHeaders"/>
+    /// Includes <see cref="ResponseStatusCode"/> and <see cref="ResponseHeaders"/>.
     /// </summary>
     ResponsePropertiesAndHeaders = ResponseStatusCode | ResponseHeaders,
 
@@ -180,11 +185,11 @@ public enum HttpLoggingFields : long
     /// Logging the response body has performance implications, as it requires buffering
     /// the entire response body up to <see cref="HttpLoggingOptions.ResponseBodyLogLimit"/>.
     /// </summary>
-    Response = ResponseStatusCode | ResponseHeaders | ResponseBody,
+    Response = ResponsePropertiesAndHeaders | ResponseBody,
 
     /// <summary>
     /// Flag for logging both the HTTP Request and Response.
-    /// Includes <see cref="Request"/> and <see cref="Response"/>.
+    /// Includes <see cref="Request"/>, <see cref="Response"/>, and <see cref="Duration"/>.
     /// Logging the request and response body has performance implications, as it requires buffering
     /// the entire request and response body up to the <see cref="HttpLoggingOptions.RequestBodyLogLimit"/>
     /// and <see cref="HttpLoggingOptions.ResponseBodyLogLimit"/>.
@@ -193,5 +198,5 @@ public enum HttpLoggingFields : long
     /// The HTTP Request <see cref="HttpRequest.QueryString"/> is not included with this flag as it may contain private information.
     /// If desired, it should be explicitly specified with <see cref="RequestQuery"/>.
     /// </remarks>
-    All = Request | Response
+    All = Request | Response | Duration
 }