[API Proposal] HttpClientFactory logging configuration

[CarnaViire]

Original issue by @CarnaViire

Tracking all the community asks regarding HttpClientFactory logging in one place.

1. Make logging opt-in. Opt-out currently is possible only using a workaround to remove all IHttpMessageHandlerBuilderFilter registrations from the DI container. Related: Make it possible to disable the built-in HTTP client logging #81540, Microsoft.Extensions.Http is too heavy-weight for mobile usages #66863, Ability to disable default http request logging #85840

2. Make logging configurable. Related: Modify HttpClientFactory based HttpClient request logging #44411 -- 7 upvotes

   1. Ability to substitute by Networking Telemetry (incl. ActivityId). Related: [API Proposal]: Add http request/response correlation id to LoggingHttpMessageHandler (Microsoft.Extensions.Http.Logging) #76998
   2. Ability to redact URIs used for logging. Related: IHttpClientBuilder should have extension to redact query parameter from logging #68675, Modify HttpClientFactory based HttpClient request logging #44411
   3. Ability to write response body by analogy with ASP.NET's Http logging. Related: [API Proposal]: Add body content to HttpRequestException #86095

---

Background and motivation

There is a growing number of asks to make HttpClientFactory's logging opt out and/or configurable (see original issue description). Given the enrichable logging designed in dotnet/extensions, we want to have a flexible and extensible logging infrastructure and give users an API experience that feels consistent even if it spans more than one package.

API Proposal

// new
interface IHttpClientLogger
{
    // returns context object (e.g. LogRecord)
    ValueTask<object?> LogRequestStartAsync(
        HttpRequestMessage request,
        CancellationToken cancellationToken = default);

    ValueTask LogRequestStopAsync(
        object? context,
        HttpRequestMessage request,
        HttpResponseMessage response,
        TimeSpan elapsed,
        CancellationToken cancellationToken = default);

    ValueTask LogRequestFailedAsync(
        object? context,
        HttpRequestMessage request,
        HttpResponseMessage? response,
        Exception exception,
        TimeSpan elapsed,
        CancellationToken cancellationToken = default);
}

// new
interface IHttpClientLoggingBuilder
{
    string Name { get; }
    IServiceCollection Services { get; }

    // adds custom implementation
    // wrapHandlersPipeline -- whether a logging handler should be added to the top or to the bottom
    // of the handlers chain
    IHttpClientLoggingBuilder AddLogger(
        Func<IServiceProvider, IHttpClientLogger> httpClientLoggerFactory,
        bool wrapHandlersPipeline = false);

    // removes all loggers incl. default ones
    IHttpClientLoggingBuilder RemoveAllLoggers();
}

// new
static class HttpClientLoggingBuilderExtensions
{
    // adds (back) the default logging (LoggingHttpMessageHandler + LoggingScopeHttpMessageHandler)
    // useful if the logging was removed by RemoveAll before e.g. by ConfigureHttpClientDefaults
    public static IHttpClientLoggingBuilder AddDefaultLogger(this IHttpClientLoggingBuilder builder);

    // convenience method -- adds custom implementation from container
    public static IHttpClientLoggingBuilder AddLogger<TLogger>(
        this IHttpClientLoggingBuilder builder, bool wrapHandlersPipeline = false)
            where TLogger : IHttpClientLogger;
}

// existing
static class HttpClientBuilderExtensions
{
    // new
    public static IHttpClientBuilder ConfigureLogging(
        this IHttpClientBuilder builder, Action<IHttpClientLoggingBuilder> configure) {}
}

API Usage

1. Removing the logging

Related: #81540, #85840

services.AddHttpClient("foo").ConfigureLogging(b => b.RemoveAllLoggers());

// -OR-
// remove for all clients
services.ConfigureHttpCientDefaults(defaults =>
    defaults.ConfigureLogging(b => b.RemoveAllLoggers());

2. Implementing custom one-line console logging

Related: #44411, #76998, #68675, #86095

// registration
services.AddSingleton<MyConsoleLogger>();
services.AddHttpClient("bar").ConfigureLogging(b =>
    b.RemoveAllLoggers()
        .AddLogger<MyConsoleLogger>());

// ...

// logger implementation
public class MyConsoleLogger : IHttpClientLogger
{
    public ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default) => ValueTask.FromResult((object?)null);

    public ValueTask LogRequestStopAsync(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        Console.WriteLine($"{request.Method} {request.RequestUri?.AbsoluteUri} - {(int)response.StatusCode} {response.StatusCode} in {elapsed.TotalMilliseconds}ms");
        return ValueTask.CompletedTask;
    }

    public ValueTask LogRequestFailedAsync(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        Console.WriteLine($"{request.Method} {request.RequestUri?.AbsoluteUri} - FAILED {exception.GetType().FullName}: {exception.Message}");
        return ValueTask.CompletedTask;
    }
}

example output

client code:

await client.GetAsync("https://httpbin.dmuth.org/get");
await client.PostAsync("https://httpbin.dmuth.org/post", new ByteArrayContent(new byte[] { 42 }));
await client.GetAsync("http://httpbin.dmuth.org/status/500");
await client.GetAsync("http://localhost:1234");

console output:

GET https://httpbin.dmuth.org/get - 200 OK in 393.2039ms
POST https://httpbin.dmuth.org/post - 200 OK in 95.524ms
GET https://httpbin.dmuth.org/status/500 - 500 InternalServerError in 99.5025ms
GET http://localhost:1234/ - FAILED System.Net.Http.HttpRequestException: No connection could be made because the target machine actively refused it. (localhost:1234)

3. Same but for ILogger

Bonus: add client name to ILogger category name
Bonus 2: custom extension method

// registration
services.AddHttpClient("baz").ConfigureLogging(b => b.UseMyMinimalLogging());

// ...

// custom extension method
IHttpClientLoggingBuilder UseMyMinimalLogging(this IHttpClientLoggingBuilder builder)
{
    var name = builder.Name;
    return builder.RemoveAllLoggers()
        .AddLogger(sp => 
        {
            var loggerFactory = sp.GetRequiredService<ILoggerFactory>();
            var log = loggerFactory.CreateLogger($"{nameof(MyMinimalLogger)}.{name}");
            return new MyMinimalLogger(log);
        });
}

// ...

// logger implementation
public class MyMinimalLogger : IHttpClientLogger
{
    private ILogger _log;
    public MyMinimalLogger(ILogger log)
    {
        _log = log;
    }

    public ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default) => ValueTask.FromResult((object?)null);

    public ValueTask LogRequestStopAsync(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        _log.LogInformation($"{request.Method} {request.RequestUri?.AbsoluteUri} - {(int)response.StatusCode} {response.StatusCode} in {elapsed.TotalMilliseconds}ms");
        return ValueTask.CompletedTask;
    }

    public ValueTask LogRequestFailedAsync(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        _log.LogWarning($"{request.Method} {request.RequestUri?.AbsoluteUri} - FAILED {exception.GetType().FullName}: {exception.Message}");
        return ValueTask.CompletedTask;
    }
}

example output

client code:

await client.GetAsync("https://httpbin.dmuth.org/get");
await client.PostAsync("https://httpbin.dmuth.org/post", new ByteArrayContent(new byte[] { 42 }));
await client.GetAsync("http://httpbin.dmuth.org/status/500");
await client.GetAsync("http://localhost:1234");

console output:

info: MyMinimalLogger.baz[0]
      GET https://httpbin.dmuth.org/get - 200 OK in 393.2039ms
info: MyMinimalLogger.baz[0]
      POST https://httpbin.dmuth.org/post - 200 OK in 95.524ms
info: MyMinimalLogger.baz[0]
      GET https://httpbin.dmuth.org/status/500 - 500 InternalServerError in 99.5025ms
warn: MyMinimalLogger.baz[0]
      GET http://localhost:1234/ - FAILED System.Net.Http.HttpRequestException: No connection could be made because the target machine actively refused it. (localhost:1234)

4. Adding (back) the default HttpClientFactory logging

After removal, or after the logging would be potentially turned off by default in a future release

// remove for all clients
services.ConfigureHttpCientDefaults(defaults =>
    defaults.ConfigureLogging(b => b.RemoveAllLoggers());

// add back for a single client
services.AddHttpClient("qux").ConfigureLogging(b => b.AddDefaultLogger());

5. Implementing Microsoft.Extensions.Http.Telemetry logging

Related: #87247

Based on HttpLoggingHandler functionality from Extensions.

The logger itself in the gist https://gist.github.com/CarnaViire/08346da1634d357f6bcb8adefa01da67#file-httpclientlogger-cs

// registration
services.AddHttpClient("quux").ConfigureLogging(b => b.UseEnrichedLogging());

// ...

// custom extension method
IHttpClientLoggingBuilder UseEnrichedLogging(this IHttpClientLoggingBuilder builder) =>
    builder.RemoveAllLoggers()
        .AddLogger(services => 
        {
            var log = services.GetRequiredService<ILogger<HttpClientLogger>>();
            var httpRequestReader = services.GetRequiredService<IHttpRequestReader>();
            var enrichers = services.GetServices<IHttpClientLogEnricher>();
            var loggingOptions = services.GetRequiredService<IOptions<LoggingOptions>>();

            return new HttpClientLogger(log, httpRequestReader, enrichers, loggingOptions);
        });

6. Going forward

We can consider adding convenience methods for a configurable minimal logging in the future (with implementation based on the Example 3):

// existing (to be)
static class HttpClientLoggingBuilderExtensions
{
    // new
    IHttpClientLoggingBuilder AddMinimalLogger(
        this IHttpClientLoggingBuilder builder,
        Func<HttpRequestMessage, HttpResponseMessage?, Exception?, TimeSpan, string> formatter);
}

Logger implementation

internal class MinimalHttpClientLogger : IHttpClientLogger
{
    private ILogger _log;
    private Func<HttpRequestMessage, HttpResponseMessage?, Exception?, TimeSpan, string> _formatter;
    public MinimalHttpClientLogger(ILogger log, Func<HttpRequestMessage, HttpResponseMessage?, Exception?, TimeSpan, string> formatter)
    {
        _log = log;
        _formatter = formatter;
    }

    public ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default) => ValueTask.FromResult((object?)null);

    public ValueTask LogRequestStopAsync(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        _log.LogInformation(_formatter(request, response, null, elapsed));
        return ValueTask.CompletedTask;
    }

    public ValueTask LogRequestFailedAsync(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        _log.LogWarning(_formatter(request, response, exception, elapsed));
        return ValueTask.CompletedTask;
    }
}

Alternative Design

I believe we can expect most of the custom user logging to be sync rather than async. Having async-only interface would force the users to always do return ValueTask.CompletedTask; in the end of an inherently sync implementation, which might be a bit inconvenient. We might consider having sync methods on the interface as well, and default-implement async ones. We cannot drop async, as there's already a precedent for async logging in dotnet/extensions.

interface IHttpClientLogger
{
    object? LogRequestStart(HttpRequestMessage request, CancellationToken cancellationToken = default);
    void LogRequestStop(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed, CancellationToken cancellationToken = default);
    void LogRequestFailed(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception,TimeSpan elapsed, CancellationToken cancellationToken = default);

    ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default)
    {
        object? context = LogRequestStart(request, cancellationToken);
        return ValueTask.FromResult(context);
    }

    ValueTask LogRequestStopAsync(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        LogRequestStop(context, request, response, elapsed, cancellationToken);
        return ValueTask.CompletedTask;
    }

    ValueTask LogRequestFailedAsync(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception,TimeSpan elapsed, CancellationToken cancellationToken = default)
    {
        LogRequestFailed(context, request, response, exception, elapsed, cancellationToken);
        return ValueTask.CompletedTask;
    }
}

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Tracking all the community asks regarding HttpClientFactory logging in one place.

1. Make logging opt-in. Opt-out currently is possible only using a workaround to remove all IHttpMessageHandlerBuilderFilter registrations from the DI container. Related: Microsoft.Extensions.Http is too heavy-weight for mobile usages #66863

2. Make logging configurable. Related: Modify HttpClientFactory based HttpClient request logging #44411 -- 7 upvotes

   1. Ability to substitute by Networking Telemetry (incl. ActivityId). Related: [API Proposal]: Add http request/response correlation id to LoggingHttpMessageHandler (Microsoft.Extensions.Http.Logging) #76998
   2. Ability to redact URIs used for logging. Related: IHttpClientBuilder should have extension to redact query parameter from logging #68675, Modify HttpClientFactory based HttpClient request logging #44411

Author:	CarnaViire
Assignees:	-
Labels:	area-Extensions-HttpClientFactory
Milestone:	Future

[CarnaViire]

I'm currently considering something like

public static IHttpClientBuilder ConfigureLogging(this IHttpClientBuilder builder, Action<LoggingOptionsBuilder> configure) {}

public class LoggingOptionsBuilder
{
    public string Name { get; }
    public IServiceCollection Services { get; }
    public LoggingOptionsBuilder ClearProviders() {} // removes all logging
    public LoggingOptionsBuilder AddDefaultProviders() {} // adds the default logging (LoggingHttpMessageHandler + LoggingScopeHttpMessageHandler)

    // and then potential extensions... these are just out of my head, not fully thought through
    public LoggingOptionsBuilder AddClientHandler() {} // adds LoggingHttpMessageHandler
    public LoggingOptionsBuilder AddLogicalHandler() {} // adds LoggingScopeHttpMessageHandler
    public LoggingOptionsBuilder AddMinimal() {} // one-liner
    public LoggingOptionsBuilder AddMinimal(Func<HttpRequestMessage, HttpResponseMessage?, TimeSpan, string> getLogString) {} // configured one-liner
    public LoggingOptionsBuilder AddCustom(Action<HttpRequestMessage>? before = null, Action<HttpRequestMessage, HttpResponseMessage?, TimeSpan>? after = null, LogLevel level = LogLevel.Information) {}
}

[CarnaViire]

Next WIP take on logging configuration:

// new
interface IHttpClientLoggingProvider
{
    // returns context object (e.g. LogRecord)
    ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default);

    ValueTask LogRequestEndAsync(
        object? context,
        HttpRequestMessage request,
        HttpResponseMessage response,
        TimeSpan elapsed,
        CancellationToken cancellationToken = default);

    void LogRequestError(
        object? context,
        HttpRequestMessage request,
        HttpResponseMessage? response,
        Exception exception,
        TimeSpan elapsed);
}

// new
interface IHttpClientLoggingBuilder
{
    public string Name { get; }
    public IServiceCollection Services { get; }

    // adds custom implementation
    // wrapFullPipeline -- whether a logging handler should be added to the top or to the bottom of the handlers chain
    IHttpClientLoggingBuilder AddProvider(Func<IServiceProvider, IHttpClientLoggingProvider> providerFactory, bool wrapFullPipeline = false);

    // adds custom implementation from container
    IHttpClientLoggingBuilder AddProvider<TProvider>(bool wrapFullPipeline = false) where TProvider : IHttpClientLoggingProvider;

    IHttpClientLoggingBuilder ClearProviders(); // removes all logging
    IHttpClientLoggingBuilder AddDefaultProviders(); // adds the default logging (LoggingHttpMessageHandler + LoggingScopeHttpMessageHandler)
}

// existing
public static class HttpClientBuilderExtensions
{
   // new
   public static IHttpClientBuilder ConfigureLogging(this IHttpClientBuilder builder, Action<IHttpClientLoggingBuilder> configure) {}
}

I've checked that it should be possible to implement HttpLoggingHandler functionality from Extensions via the proposed IHttpClientLoggingProvider interface (https://gist.github.com/CarnaViire/08346da1634d357f6bcb8adefa01da67)

Any early feedback @noahfalk @JamesNK @samsp-msft @dpk83 @dotnet/ncl ?