[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;
    }
}

[ghost]

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 ?

[noahfalk]

Thanks @CarnaViire! I started taking a look but its pretty late so I'll look closer tomorrow!

[CarnaViire]

Thanks @noahfalk!
I've discussed the API within my team, and there are small updates (mostly on the naming)

// 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
{
    public string Name { get; }
    public 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
    IHttpClientLoggingBuilder AddDefaultLogger(this IHttpClientLoggingBuilder builder);

    // convenience method -- adds custom implementation from container
    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) {}
}

[CarnaViire]

Usage examples:

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;
    }
}

[noahfalk]

This feels pretty good to me. It doesn't have the fine-grained customization and composition that ASP.NET added ( by fine-grained I mean the ability to customize and enrich the content of messages logged by the built-in logger). However given that HttpClient has 7 different scopes+log messages it emits from the default logging its likely complex to make all of them individually configurable and the most likely configuration users probably want is turn most of it off. Being able to call RemoveAllLoggers() to quickly get to a clean slate and then start again from something more minimal seems pretty reasonable.

We are still going to be in a position where users are choosing between the default, dotnet/extensions's implementation, or their own custom implementation. I'm guessing most users will be pretty happy with one of these choices as opposed to ASP.NET where it felt like each option had some desirable functionality and users might be sacrificing one to get the other.

I'm guessing dotnet/extensions might want to grab some name like AddLightweightLogger() or AddMinimalLogger() so if you also had designs on a similar name then we might need to discuss what is it in the future that we expect will distinguish those loggers to pick good names.

@dpk83 @geeknoid @samsp-msft @tarekgh - thoughts?

[noahfalk]

Also for simplicity and for slightly improved perf, you may want to make the interface synchronous rather than async. Did you have any particular use-case in mind that requires async calling patterns or this was aimed at future-proofing?

[CarnaViire]

Also for simplicity and for slightly improved perf, you may want to make the interface synchronous rather than async. Did you have any particular use-case in mind that requires async calling patterns or this was aimed at future-proofing?

Yes actually the need to use async came from dotnet/extensions implementation 😄 see https://github.com/dotnet/extensions/blob/a8c95411ab0ff3895869b2339ce85f573e259d35/src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpLoggingHandler.cs#L107-L110 and https://gist.github.com/CarnaViire/08346da1634d357f6bcb8adefa01da67#file-httpclientlogger-cs-L77-L81

As the methods return ValueTasks, in case of a successful synchronous completion nothing will be allocated, so I might be wrong, but I didn't expect perf to be impacted.

While having to do return ValueTask.CompletedTask; in the end of an inherently sync implementation might be inconvenient for a user implementing the interface, having the interface contain both sync and async options is inconvenient as well. But I can include it as an alternative design.

We are still going to be in a position where users are choosing between the default, dotnet/extensions's implementation, or their own custom implementation. I'm guessing most users will be pretty happy with one of these choices as opposed to ASP.NET where it felt like each option had some desirable functionality and users might be sacrificing one to get the other.

I agree 👍

I'm guessing dotnet/extensions might want to grab some name like AddLightweightLogger() or AddMinimalLogger() so if you also had designs on a similar name then we might need to discuss what is it in the future that we expect will distinguish those loggers to pick good names.

Of course! I expect it to be in the later releases for extensions as well, is that correct?

[noahfalk]

Yes actually the need to use async came from dotnet/extensions implementation

Aha. OK that makes sense to me. Ignore my suggestion about synchronous APIs :)

having the interface contain both sync and async options is inconvenient as well

I agree. I was originally (but no longer) wondering if we could do it with a synchronous API only.

I expect it to be in the later releases for extensions as well, is that correct?

I'm not sure what "it" you are refering to? I am expecting the dotnet/extensions usage of this proposed API (scenario 5 above) to happen during the .NET 8 release. I think scenario (5) is the thing dotnet/extensions may wish to call minimal or lightweight logging unless we come up with another name we think is more appropriate.

[CodeBlanch]

@CarnaViire @noahfalk @tarekgh @JamesNK

I've run into a semi-related issue in OpenTelemetry .NET. I'll post here but if I should create a separate issue LMK.

OpenTelemetry Logging is implemented as an ILoggerProvider. When the host requests the ILoggerFactory from the IServiceProvider the OpenTelemetry ILoggerProvider is created. OpenTelemetry allows users to register one or more exporters (like a sink) for sending their logs to different backends.

Some exporters may use HttpClient. Our Zipkin exporter (JSON over HTTP) and our OpenTelemetry Protocol exporter (protobuf over HTTP) are two examples.

We allow users to configure their HttpClient via IHttpClientFactory.

The issue I'm having is DefaultHttpClientFactory injects ILoggerFactory into its ctor.

This creates essentially a circular reference for OpenTelemetry.

ILoggerFactory -> OpenTelemetryLoggerProvider -> OtlpLogExporter -> IHttpClientFactory -> ILoggerFactory

Will any of the changes on this PR help with that? Possible to get ILoggerFactory out of the DefaultHttpClientFactory ctor somehow?

The only solution I have so far is to NOT try and build the HttpClient via IHttpClientFactory in the ctor of OtlpLogExporter and instead do it the first time some data is exported. But this isn't an ideal situation because if that fails for any reason, I can't surface the error. The OpenTelemetry SDK is not allowed to throw exceptions after it has started. So I'll have to just swallow it, log to our EventSource, and probably go dark (no telemetry will be exported). Users will have to notice the dropped telemetry, capture SDK logs, and then do some kind of fix.

Update: The solution proposed ^ doesn't work reliably. For very short-lived services it is possible the serviceProvider will be disposed before any telemetry is exported. During dispose we try and flush any data. But I can't access IHttpClientFactory during that flush because the IServiceProvider has already been marked as disposed.

[terrajobst]

Video

• Let's merge the logging builder with the client builder
• We should offer sync versions

namespace Microsoft.Extensions.Http.Logging
{
    public interface IHttpClientLogger
    {
        object? LogRequestStart(
            HttpRequestMessage request);

        void LogRequestStop(
            object? context,
            HttpRequestMessage request,
            HttpResponseMessage response,
            TimeSpan elapsed);

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

    public interface IHttpClientAsyncLogger : IHttpClientLogger
    {
        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);
    }
}

namespace Microsoft.Extensions.DependencyInjection
{
    public partial static class HttpClientBuilderExtensions
    {
        public static IHttpClientBuilder AddLogger(
            this IHttpClientBuilder builder,
            Func<IServiceProvider, IHttpClientLogger> httpClientLoggerFactory,
            bool wrapHandlersPipeline = false);

        public static IHttpClientBuilder RemoveAllLoggers(
            this IHttpClientBuilder builder
        );

        public static IHttpClientBuilder AddDefaultLogger(
            this IHttpClientBuilder builder);

        public static IHttpClientBuilder AddLogger<TLogger>(
            this IHttpClientBuilder builder,
            bool wrapHandlersPipeline = false)
            where TLogger : IHttpClientLogger;
    }
}

[ladeak]

Why the IHttpClientAsyncLogger extends IHttpClientLogger ? Shouldn't it be the opposite way around? If I am on .NET framework and I am on implementing a logger, isn't it forcing me to implement the sync logger as well, which will technically never be invoked there?

[CarnaViire]

@ladeak You can implement only a sync one though? The invoking code would see whether the logging is async or sync, and invoke sync code if the logger is sync-only.

So the only unfortunate case is when you have inherently-asyncronous logging, and you are writing exclusively for .NET Framework.... Because if you're writing for .NET Standard, you need both sync and async in this case

[CarnaViire]

@CodeBlanch thanks a lot for bringing this issue into view! I was not aware of this before.

So there are 2 parts that use ILogger/ILoggerFactory now, and the first one is per-client logging -- which will be fixed by this proposal - you would need to explicitly either turn off or write your custom logging though.

The second part is the debug logging of HttpClientFactory itself. This needs to be tackled separately. I plan to rewrite it to use our Private.InternalDiagnostics event source instead. Can you please create a separate issue @CodeBlanch? Or I can create it myself couple of days later.