HttpLogging redaction and enrichment

[jkotalik]

We need the ability to allow users to configure and customize what is logged for a request and response. For example if they would like to modify a header value that is logged to remove PII, or adding another key and value to the log.

Our current idea is to have a Func that people can implement that would take a context, and allow returning any KeyValuePair to be logged.

Currently, we were thinking of adding the extension point to where we log headers:

General API shape

Action<HttpLoggingContext> ModifyLog;

HttpLogContext
{
    HttpContext HttpContext { get; }
    List<KeyValuePair<string, string>> Logs { get; } // or maybe a dictionary
}

Example:

(httpLogContext) =>
{
   httpLogContext.Logs.Add(
       new KeyValuePair<string, string>(
           "RequestAborted", 
            httpLogContext.HttpContext.RequestAborted.IsCancellationRequested.ToString());
}

[davidfowl]

Attach these issues to an epic

[jkotalik]

@davidfowl @shirhatti @Tratcher I was going to start on this today/tomorrow. Do we want to bash out a design in the issue or do we want to have a meeting?

[Tratcher]

Last time we discussed it we weren't anywhere near a consensus. It would definitely require a meeting.

Is the API above the latest proposal?

[jkotalik]

@davidfowl @shirhatti can you reassign this?

[shirhatti]

Clearing milestone so this shows up in triage

[ghost]

We've moved this issue to the Backlog milestone. This means that it is not going to be worked on for the coming release. We will reassess the backlog following the current release and consider this item at that time. To learn more about our issue management process and to have better expectation regarding different types of issues you can read our Triage Process.

[Tratcher]

There's discussion of a different kind of redaction to consider: Instead of just hiding certain fields, use a one-way hash to obscure the data, but you'd still be able to correlate usages and look up known values.

Related: dotnet/runtime#81730

[Tratcher]

Some services also need to redact data within the request/response body log buffer.

[davidfowl]

Some services also need to redact data within the request/response body log buffer.

This means understanding the body right? This seems like a big deal (aka problem). Can you provide some examples?

[Tratcher]

Background and Motivation

We want to be able to consolidate functionality from https://github.com/dotnet/extensions/tree/main/src/Libraries/Microsoft.AspNetCore.Telemetry.Middleware/Logging so it can plug its custom redaction and enrichment logic without re-implementing everything else. This also includes adding support for durration.

Draft PR: #48679

Proposed API

namespace Microsoft.AspNetCore.Builder;

public static HttpLoggingBuilderExtensions
{
+ public static IServiceCollection AddHttpLoggingInterceptor<T>(this IServiceCollection services) where T is IHttpLoggingInterceptor
}

namespace Microsoft.AspNetCore.HttpLogging;

+ public interface IHttpLoggingInterceptor
+ {
+    void OnRequest(HttpLoggingContext logContext);
+    void OnResponse(HttpLoggingContext logContext);
+ }

+ public sealed class HttpLoggingContext : IResettable
+ {
+    public HttpContext HttpContext { get; set; }
+    public HttpLoggingFields LoggingFields { get; set; }
+    public int RequestBodyLogLimit { get; set; }
+    public int ResponseBodyLogLimit { get; set; }
+    public IList<KeyValuePair<string, object?>> Parameters { get; } = new List<KeyValuePair<string, object?>>();
+    public void Add(string key, object? value)
+    public void Enable(HttpLoggingFields fields)
+    public bool IsAnyEnabled(HttpLoggingFields fields)
+    public void Disable(HttpLoggingFields fields)
+    public bool TryOverride(HttpLoggingFields field)
+ }

[Flags]
public enum HttpLoggingFields : long
{
+   Duration // Also added to Response and ResponsePropertiesAndHeaders
}

Usage Examples

See also dotnet/extensions#4056

internal class SampleHttpLoggingInterceptor : IHttpLoggingInterceptor
{
    public void OnRequest(HttpLoggingContext 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;
        }

        if (logContext.TryOverride(HttpLoggingFields.RequestPath))
        {
            RedactPath(logContext);
        }

        if (logContext.TryOverride(HttpLoggingFields.RequestHeaders))
        {
            RedactRequestHeaders(logContext);
        }

        EnrichRequest(logContext);
    }

    private void RedactRequestHeaders(HttpLoggingContext logContext)
    {
        foreach (var header in logContext.HttpContext.Request.Headers)
        {
            logContext.Add(header.Key, "RedactedHeader"); // TODO: Redact header value
        }
    }

    private void RedactResponseHeaders(HttpLoggingContext logContext)
    {
        foreach (var header in logContext.HttpContext.Response.Headers)
        {
            logContext.Add(header.Key, "RedactedHeader"); // TODO: Redact header value
        }
    }

    public void OnResponse(HttpLoggingContext logContext)
    {
        // Don't enrich if we're not going to log any part of the response
        if (!logContext.IsAnyEnabled(HttpLoggingFields.Response))
        {
            return;
        }

        if (logContext.TryOverride(HttpLoggingFields.ResponseHeaders))
        {
            RedactResponseHeaders(logContext);
        }

        EnrichResponse(logContext);
    }

    private void EnrichResponse(HttpLoggingContext logContext)
    {
        logContext.Add("ResponseEnrichment", "Stuff");
    }

    private void EnrichRequest(HttpLoggingContext logContext)
    {
        logContext.Add("RequestEnrichment", "Stuff");
    }

    private void RedactPath(HttpLoggingContext logContext)
    {
        logContext.Add(nameof(logContext.HttpContext.Request.Path), "RedactedPath");
    }
}

Open questions

• There's an ask to delay logging the request until we've had a chance to inspect the response, so it can all be grouped into one log.
• Logging the response needs to be delayed until the body completes so we include the full Duration.
• Is modifying an existing flags enum value a breaking change? HttpLoggingFields.ResponsePropertiesAndHeaders

[ghost]

Thank you for submitting this for API review. This will be reviewed by @dotnet/aspnet-api-review at the next meeting of the ASP.NET Core API Review group. Please ensure you take a look at the API review process documentation and ensure that:

• The PR contains changes to the reference-assembly that describe the API change. Or, you have included a snippet of reference-assembly-style code that illustrates the API change.
• The PR describes the impact to users, both positive (useful new APIs) and negative (breaking changes).
• Someone is assigned to "champion" this change in the meeting, and they understand the impact and design of the change.

[halter73]

API Review Notes:

• Can the context's HttpContext property be made immutable?
  • Yes, but it needs to be configurable for external tests.
  • required init?
• What are Paremeters?
  • This is a new feature for intercepters to add new things to the logs.
  • HttpLoggingFields to get added to Parameters if they stay enabled.
    • How are the enums mapped to the parameter name?
    • Does the value in the KVP need to be object?
      • It avoids allocations if you don't need ot
• Should we put IResettable on public API?
  • No. It locks us in a little, and users might reference things late.
• Should the callbacks be async?
  • Probably, but one of the call sites might currently be sync. But those call sites are only sync Writes/Flushes that aren't enabled by default anyway. And even if they are enabled, they would just call GetAwaiter().GetResult() too.
  • ValueTask might be useful if you if you really want to optimize with IValueTask
• When exactly is OnResponse called?
• As soon as the headers are committed which could be a while before the actual log is emitted so it can include the response body buffer and the duration.
• Do we really want to combine the normal response log and response body log? Could this be too breaking.
• Do we need an OnResponseBodyAsync method? Seems like too much.
• Is OnResponse going to complain if you try to modify a field that has been written?
• What about the HttpLoggingContext name?
  • HttpLoggingInterceptorContext? Yes.
• Do we need Add? It's not clear it's for property
  • @Tratcher likes it
  • We're calling it AddParameter
• What does TryOverride return when only a subset of the fields are enabled?
  • Let's limit to a single field if it's not too crazy to check for this. We did call the parameter field.
  • It looks like BitOperations.PopCount might be good for this.

API Approved!

// Microsoft.AspNetCore.HttpLogging.dll
namespace Microsoft.AspNetCore.Builder;

public static HttpLoggingBuilderExtensions
{
+ public static IServiceCollection AddHttpLoggingInterceptor<T>(this IServiceCollection services) where T is IHttpLoggingInterceptor
}

namespace Microsoft.AspNetCore.HttpLogging;

+ public interface IHttpLoggingInterceptor
+ {
+    ValueTask OnRequestAsync(HttpLoggingInterceptorContext logContext);
+    ValueTask OnResponseAsync(HttpLoggingInterceptorContext logContext);
+ }

+ public sealed class HttpLoggingInterceptorContext
+ {
+    public required HttpContext HttpContext { get; init; }
+    public HttpLoggingFields LoggingFields { get; set; }
+    public int RequestBodyLogLimit { get; set; }
+    public int ResponseBodyLogLimit { get; set; }
+    public IList<KeyValuePair<string, object?>> Parameters { get; } = new List<KeyValuePair<string, object?>>(); 
+    public void AddParameter(string key, object? value)
+    public void Enable(HttpLoggingFields fields)
+    public bool IsAnyEnabled(HttpLoggingFields fields)
+    public void Disable(HttpLoggingFields fields)
+    public bool TryOverride(HttpLoggingFields field)
+ }

[Flags]
public enum HttpLoggingFields : long
{
+   Duration // Also added to Response and ResponsePropertiesAndHeaders
}

[adityamandaleeka]

@Tratcher Is this going to make RC1?

[Tratcher]

Unlikely, I'm busy with metrics.

[joperezr]

@Tratcher now that the metrics work is done, we may have a small window to still make it into RC1 if we can finish this up this week. Do you think that's doable or should we just aim for RC2 for this?

[Tratcher]

Unlikely, I'll only be able to work on it ~1 day this week.

[Tratcher]

Two minor API changes based on review feedback:

public sealed class HttpLoggingInterceptorContext
{
-    public bool TryOverride(HttpLoggingFields field)
+    public bool TryDisable(HttpLoggingFields field) // Aligns with public void Disable(HttpLoggingFields field)
}

public sealed class HttpLoggingOptions
{
+    /// <summary>
+    /// Gets or sets if the middleware will combine the request, request body, response, and response body logs into a single log entry.
+    /// The default is <see langword="false"/>.
+    /// </summary>
+    public bool CombineLogs { get; set; }
}