HttpLogging redaction and enrichment

eng/scripts/CodeCheck.ps1

@@ -253,7 +253,10 @@ try {
                     }
                 }
                 # Check for changes in Unshipped in servicing branches
-                if ($targetBranch -like 'release*' -and $targetBranch -notlike '*preview*' -and $file -like '*PublicAPI.Unshipped.txt') {
+                if ($targetBranch -like 'release*' `
+                    -and $targetBranch -notlike '*preview*' `
+                    -and $targetBranch -notlike '*rc*' `
+                    -and $file -like '*PublicAPI.Unshipped.txt') {
                     $changedAPIBaselines.Add($file)
                 }
             }
@@ -263,7 +266,8 @@ try {
 
         if ($changedAPIBaselines.count -gt 0) {
             LogError ("Detected modification to baseline API files. PublicAPI.Shipped.txt files should only " +
-                "be updated after a major release. See /docs/APIBaselines.md for more information.")
+                "be updated after a major release. PublicAPI.Unshipped.txt should only be updated in main or pre-release branches. " +
+                "See /docs/APIBaselines.md for more information.")
             LogError "Modified API baseline files:"
             foreach ($file in $changedAPIBaselines) {
                 LogError $file

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/HttpLoggingExtensions.cs

@@ -20,8 +20,8 @@ public static void ResponseLog(this ILogger logger, HttpResponseLog responseLog)
         exception: null,
         formatter: HttpResponseLog.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,7 @@ public static void ResponseLog(this ILogger logger, HttpResponseLog responseLog)
 
     [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, "Response Duration: {Duration}ms, Body: {Body}", EventName = "ResponseDurationAndBody")]
+    public static partial void ResponseBodyWithDuration(this ILogger logger, string body, double duration);
 }

src/Middleware/HttpLogging/src/HttpLoggingFields.cs

@@ -135,6 +135,11 @@ public enum HttpLoggingFields : long
     /// </summary>
     ResponseBody = 0x800,
 
+    /// <summary>
+    /// Log how long it took to process the request and return a response in total milliseconds.
+    /// </summary>
+    Duration = 0x1000,
+
     /// <summary>
     /// Flag for logging a collection of HTTP Request properties,
     /// including <see cref="RequestPath"/>, <see cref="RequestProtocol"/>,
@@ -158,9 +163,9 @@ 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"/>, <see cref="ResponseHeaders"/>, and <see cref="Duration"/>.
     /// </summary>
-    ResponsePropertiesAndHeaders = ResponseStatusCode | ResponseHeaders,
+    ResponsePropertiesAndHeaders = ResponseStatusCode | ResponseHeaders | Duration,
 
     /// <summary>
     /// Flag for logging the entire HTTP Request.
@@ -180,7 +185,7 @@ 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.

src/Middleware/HttpLogging/src/HttpLoggingInterceptorContext.cs

@@ -0,0 +1,147 @@
+// 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.Builder;
+using Microsoft.AspNetCore.Http;
+
+namespace Microsoft.AspNetCore.HttpLogging;
+
+/// <summary>
+/// The context used for <see cref="IHttpLoggingInterceptor"/>.
+/// </summary>
+/// <remarks>
+/// Settings will be pre-initialized with the relevant values from <see cref="HttpLoggingOptions" /> and updated with endpoint specific
+/// values from <see cref="HttpLoggingAttribute"/> or
+/// <see cref="HttpLoggingEndpointConventionBuilderExtensions.WithHttpLogging{TBuilder}(TBuilder, HttpLoggingFields, int?, int?)" />.
+/// All settings can be modified per request. All settings will carry over from
+/// <see cref="IHttpLoggingInterceptor.OnRequestAsync(HttpLoggingInterceptorContext)"/>
+/// to <see cref="IHttpLoggingInterceptor.OnResponseAsync(HttpLoggingInterceptorContext)"/> except the <see cref="Parameters"/>
+/// which are cleared after logging the request.
+/// </remarks>
+public sealed class HttpLoggingInterceptorContext
+{
+    private HttpContext? _httpContext;
+
+    /// <summary>
+    /// The request context.
+    /// </summary>
+    /// <remarks>
+    /// This property should not be set by user code except for testing purposes.
+    /// </remarks>
+    public HttpContext HttpContext
+    {
+        get => _httpContext ?? throw new InvalidOperationException("HttpContext was not initialized");
+        // Public for 3rd party testing of interceptors.
+        // We'd make this a required constructor/init parameter but ObjectPool requires a parameterless constructor.
+        set => _httpContext = value ?? throw new ArgumentNullException(nameof(value));
+    }
+
+    /// <summary>
+    /// What parts of the request and response to log.
+    /// </summary>
+    /// <remarks>
+    /// This is pre-populated with the value from <see cref="HttpLoggingOptions.LoggingFields"/>,
+    /// <see cref="HttpLoggingAttribute.LoggingFields"/>, or
+    /// <see cref="HttpLoggingEndpointConventionBuilderExtensions.WithHttpLogging{TBuilder}(TBuilder, HttpLoggingFields, int?, int?)"/>.
+    /// </remarks>
+    public HttpLoggingFields LoggingFields { get; set; }
+
+    /// <summary>
+    /// Gets or sets the maximum number of bytes of the request body to log.
+    /// </summary>
+    /// <remarks>
+    /// This is pre-populated with the value from <see cref="HttpLoggingOptions.RequestBodyLogLimit"/>,
+    /// <see cref="HttpLoggingAttribute.RequestBodyLogLimit"/>, or
+    /// <see cref="HttpLoggingEndpointConventionBuilderExtensions.WithHttpLogging{TBuilder}(TBuilder, HttpLoggingFields, int?, int?)"/>.
+    /// </remarks>
+    public int RequestBodyLogLimit { get; set; }
+
+    /// <summary>
+    /// Gets or sets the maximum number of bytes of the response body to log.
+    /// </summary>
+    /// <remarks>
+    /// This is pre-populated with the value from <see cref="HttpLoggingOptions.ResponseBodyLogLimit"/>,
+    /// <see cref="HttpLoggingAttribute.ResponseBodyLogLimit"/>, or
+    /// <see cref="HttpLoggingEndpointConventionBuilderExtensions.WithHttpLogging{TBuilder}(TBuilder, HttpLoggingFields, int?, int?)"/>.
+    /// </remarks>
+    public int ResponseBodyLogLimit { get; set; }
+
+    internal long StartTimestamp { get; set; }
+    internal TimeProvider TimeProvider { get; set; } = null!;
+
+    /// <summary>
+    /// Data that will be logged as part of the request or response. Values specified in <see cref="LoggingFields"/>
+    /// will be added automatically after all interceptors run. These values are cleared after logging the request.
+    /// All other relevant settings will carry over to the response.
+    /// </summary>
+    public IList<KeyValuePair<string, object?>> Parameters { get; } = new List<KeyValuePair<string, object?>>();
+
+    /// <summary>
+    /// Adds data that will be logged as part of the request or response. See <see cref="Parameters"/>.
+    /// </summary>
+    /// <param name="key">The parameter name.</param>
+    /// <param name="value">The parameter value.</param>
+    public void AddParameter(string key, object? value)
+    {
+        Parameters.Add(new(key, value));
+    }
+
+    /// <summary>
+    /// Adds the given fields to what's currently enabled in <see cref="LoggingFields"/>.
+    /// </summary>
+    /// <param name="fields"></param>
+    public void Enable(HttpLoggingFields fields)
+    {
+        LoggingFields |= fields;
+    }
+
+    /// <summary>
+    /// Checks if any of the given fields are currently enabled in <see cref="LoggingFields"/>.
+    /// </summary>
+    public bool IsAnyEnabled(HttpLoggingFields fields)
+    {
+        return (LoggingFields & fields) != HttpLoggingFields.None;
+    }
+
+    /// <summary>
+    /// Removes the given fields from what's currently enabled in <see cref="LoggingFields"/>.
+    /// </summary>
+    /// <param name="fields"></param>
+    public void Disable(HttpLoggingFields fields)
+    {
+        LoggingFields &= ~fields;
+    }
+
+    /// <summary>
+    /// Checks if any of the given fields are currently enabled in <see cref="LoggingFields"/>
+    /// and disables them so that a custom log value can be provided instead.
+    /// </summary>
+    /// <param name="fields">One or more field flags to check.</param>
+    /// <returns><see langword="true" /> if any of the fields were previously enabled.</returns>
+    public bool TryDisable(HttpLoggingFields fields)
+    {
+        if (IsAnyEnabled(fields))
+        {
+            Disable(fields);
+            return true;
+        }
+
+        return false;
+    }
+
+    internal void Reset()
+    {
+        _httpContext = null;
+        LoggingFields = HttpLoggingFields.None;
+        RequestBodyLogLimit = 0;
+        ResponseBodyLogLimit = 0;
+        StartTimestamp = 0;
+        TimeProvider = null!;
+        Parameters.Clear();
+    }
+
+    internal double GetDuration()
+    {
+        return TimeProvider.GetElapsedTime(StartTimestamp).TotalMilliseconds;
+    }
+}