[API Proposal]: Add logging APIs to System.ClientModel

[m-redding]

Background and motivation

The System.ClientModel library provides building blocks for .NET clients that call cloud services.

Currently, this library does not provide built-in functionality for logging. There are two scenarios when logs should be produced: HTTP request/response logging and information from the System.ClientModel HTTP pipeline (i.e. everything else). This distinction is important for the discussion of these APIs.

Logging HTTP requests and responses from System.ClientModel requires careful consideration in regards to the logging implementations already available in HttpClientFactory and the ASP.NET middleware. After an in-depth investigation and team discussion, we decided the HTTP logging available does not meet the needs for all System.ClientModel logging scenarios. Therefore, we must have HTTP logging built into the library itself.

Additional logs that should be produced by the pipeline (i.e. everything else) are information about retries and information about the transport layer (exceptions and delays). The motivation for these logs is relatively straightforward. Based on interactions with customers in the Azure.Core package, these logs have proven to be helpful to diagnose and solve issues in customer apps and client libraries.

Motivation for adding public APIs

Simple logging to Event Source can be implemented without adding any public APIs. Adding public APIs is meant to achieve the following goals, in order of importance:

1. Support for ILogger
2. Customization of sanitization of headers and query parameters in logs
3. HTTP request and response logs can be disabled, but other logs such as retries and exceptions can still be written
4. Option to enable content logging for HTTP requests and responses
5. Logging can be disabled entirely

API Proposal

namespace System.ClientModel.Primitives
{
    public class ClientPipelineOptions { 
        public ClientPipelineOptions(); 
+       public ClientLoggingOptions? ClientLoggingOptions { get; set; }
+       public PipelinePolicy? MessageLoggingPolicy { get; set; }
        public TimeSpan? NetworkTimeout { get; set; }
        public PipelinePolicy? RetryPolicy { get; set; }
        public PipelineTransport? Transport { get; set; }
        public void AddPolicy(PipelinePolicy policy, PipelinePosition position); 
        public virtual void Freeze(); 
        protected void AssertNotFrozen();
    } 
+    public class ClientLoggingOptions { 
+       public ClientLoggingOptions(); 
+       public ILoggerFactory? LoggerFactory { get; set; }
+       public IList<string> AllowedHeaderNames { get; }
+       public IList<string> AllowedQueryParameters { get; }
+       public bool? EnableLogging { get; set; }
+       public bool? EnableMessageLogging { get; set; }
+       public bool? EnableMessageContentLogging { get; set; }
+       public int? MessageContentSizeLimit { get; set; }
+       public virtual void Freeze(); 
+       protected void AssertNotFrozen(); 
+   } 
    public ClientRetryPolicy : PipelinePolicy {
        public ClientRetryPolicy(int maxRetries = 3);
+       public ClientRetryPolicy(int maxRetries, bool enableLogging, ILoggerFactory? loggerFactory);
        public static ClientRetryPolicy Default { get; }
        public override sealed void Process(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex);
        public override sealed ValueTask ProcessAsync(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex);
        protected virtual TimeSpan GetNextDelay(PipelineMessage message, int tryCount); 
        protected virtual void OnRequestSent(PipelineMessage message); 
        protected virtual ValueTask OnRequestSentAsync(PipelineMessage message); 
        protected virtual void OnSendingRequest(PipelineMessage message); 
        protected virtual ValueTask OnSendingRequestAsync(PipelineMessage message); 
        protected virtual void OnTryComplete(PipelineMessage message); 
        protected virtual bool ShouldRetry(PipelineMessage message, Exception? exception); 
        protected virtual ValueTask<bool> ShouldRetryAsync(PipelineMessage message, Exception? exception); 
        protected virtual void Wait(TimeSpan time, CancellationToken cancellationToken); 
        protected virtual Task WaitAsync(TimeSpan time, CancellationToken cancellationToken); 
    }
    public class HttpClientPipelineTransport : PipelineTransport, IDisposable {
        public HttpClientPipelineTransport(); 
        public HttpClientPipelineTransport(HttpClient client); 
+       public HttpClientPipelineTransport(HttpClient? client, bool enableLogging, ILoggerFactory? loggerFactory); 
        public static HttpClientPipelineTransport Shared { get; }
        public void Dispose(); 
        protected override PipelineMessage CreateMessageCore();
        protected virtual void Dispose(bool disposing); 
        protected virtual void OnReceivedResponse(PipelineMessage message, HttpResponseMessage httpResponse);
        protected virtual void OnSendingRequest(PipelineMessage message, HttpRequestMessage httpRequest); 
        protected override sealed void ProcessCore(PipelineMessage message); 
        protected override sealed ValueTask ProcessCoreAsync(PipelineMessage message); 
    }
+   public class MessageLoggingPolicy : PipelinePolicy { 
+       public MessageLoggingPolicy(ClientLoggingOptions? options = null); 
+       public static MessageLoggingPolicy Default { get; }
+       public sealed override void Process(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex); 
+       public sealed override ValueTask ProcessAsync(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex); 
+   }
}
   public abstract class PipelineTransport : PipelinePolicy { 
        protected PipelineTransport(); 
+       protected PipelineTransport(bool enableLogging, ILoggerFactory? loggerFactory); 
        public PipelineMessage CreateMessage(); 
        public void Process(PipelineMessage message); 
        public override sealed void Process(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex); 
        public ValueTask ProcessAsync(PipelineMessage message); 
        public override sealed ValueTask ProcessAsync(PipelineMessage message, IReadOnlyList<PipelinePolicy> pipeline, int currentIndex); 
        protected abstract PipelineMessage CreateMessageCore(); 
        protected abstract void ProcessCore(PipelineMessage message); 
        protected abstract ValueTask ProcessCoreAsync(PipelineMessage message); 
    }
} 

API description

ClientLoggingOptions

This class is an options bag that allows a System.ClientModel-based client to configure logging within its pipeline. These options apply to all logging within the pipeline: the Http request/response logging in MessageLoggingPolicy and logs written in ClientRetryPolicy and PipelineTransport.

• public ILoggerFactory? LoggerFactory {get; set; } will be used to create instances of ILogger to use to write logs. If an ILoggerFactory is not provided, logs will be written to Event Source instead.
• public IList<string> AllowedHeaderNames { get; } will be used to determine which header keys to include values for in logs. All headers not on this list will have their values sanitized.
• public IList<string> AllowedQueryParameters { get; } will be used to determine which query parameters to include values for in logs. All query parameters not on this list will have their values sanitized.
• public bool? EnableLogging { get; set; } will be used to determine whether logging should be enabled. If this value is set to false, logs will not be written at all. This is true even if an ILoggerFactory is set or the Event Source is enabled. This option takes precedence over all other options.
• public bool? EnableMessageLogging { get; set; } will be used to determine whether information about Http request and responses.
• public bool? EnableMessageContentLogging { get; set; } will be used to determine whether HTTP request content and HTTP response content should be logged. If a value is not provided, content logging will be disabled.
• public int? MessageContentSizeLimit { get; set; } will be used to determine the size limit for content logging.
• public virtual void Freeze(); and protected void AssertNotFrozen(); are part of the pipeline options pattern that has already been established.

MessageLoggingPolicy

This policy handles HTTP message logging. It logs information about HTTP requests and responses. This policy is added to the pipeline just before the transport if ClientLoggingOptions.EnableLogging and ClientLoggingOptions.EnableMessageLogging are set to true or are not set at all. If either is set to false then this policy is not added to the HTTP pipeline and information about HTTP requests and responses is not logged.

This class is public so in the future we can add virtual methods that allow customization of HTTP message logging beyond the options class.

Additions to ClientPipelineOptions

• public ClientLoggingOptions? ClientLoggingOptions { get; set; } allows configuration of logging within the client pipeline.
• public PipelinePolicy? MessageLoggingPolicy { get; set; } follows the pipeline options pattern for default policies added to the pipeline. If this property is set to a PipelinePolicy, that PipelinePolicy instance will be added to the pipeline as the logging policy instead of creating a new one.

Additional constructors on ClientRetryPolicy, PipelineTransport, and HttpClientPipelineTransport

These new constructors allow each policy to write logs. Since System.ClientModel provides building blocks for clients, these policies need to be easily extensible by clients implementing them.

API Usage

Default scenario

If a client is using default options, the pipeline will write basic logs to Event Source when "System.ClientModel" Event Source is enabled. Below is an example using an EventListener to collect logs, but logs can be collected using codeless options as well, such as Visual Studio or PerfView.

using ConsoleWriterEventListener listener = new(); // Enables logs written from "System.ClientModel"

// Create and use System.ClientModel-based client as usual

string? key = Environment.GetEnvironmentVariable("MAPS_API_KEY");
ApiKeyCredential credential = new(key!);
MapsClient client = new(new Uri("https://atlas.microsoft.com"), credential);

Using ClientLoggingOptions for simple customizations

If customers pass an ILoggerFactory to the client using ClientLoggingOptions, logs will be written to ILogger instances created from this factory, instead of Event Source.

using ILoggerFactory factory = LoggerFactory.Create(builder =>
{
    builder.AddConsole();
});

ClientLoggingOptions loggingOptions = new()
{
    LoggerFactory = factory
};

MapsClientOptions options = new()
{
    ClientLoggingOptions = loggingOptions
};

// Create and use System.ClientModel-based client as usual

string? key = Environment.GetEnvironmentVariable("MAPS_API_KEY");
ApiKeyCredential credential = new(key!);
MapsClient client = new(new Uri("https://atlas.microsoft.com"), credential, options);

Sample using ClientLoggingOptions to disable logging entirely. Logs will never be written to EventSource nor ILogger regardless of any other options set.

ClientLoggingOptions options = new()
{
    EnableLogging = false
};

Sample using ClientLoggingOptions to enable and customize content logging. Content logging impacts performance and is disabled by default. It is intended to be used as a debugging tool.

ClientLoggingOptions options = new()
{
    EnableMessageContentLogging = true,
    MessageContentSizeLimit = 1024
};

Sample using ClientLoggingOptions to disable HTTP message logging (information about requests and responses). Information about retries and exceptions from the transport will still be logged.

ClientLoggingOptions options = new()
{
    EnableMessageLogging = false
};

Sample using ClientLoggingOptions to customize sanitization.

ClientLoggingOptions options = new();
options.AllowedHeaderNames.Add("Accept-Language");
options.AllowedQueryParameters.Add("resource");

Advanced scenarios

Example using a custom retry policy

This is a simple, illustrative example of how the new constructor can be used to create a custom retry policy. The new constructor allows users to add additional logs to the retry policy, and also preserves the logging behavior in the base class.

Definition:

internal class CustomRetryPolicy : ClientRetryPolicy
{
    private ILogger<CustomRetryPolicy> _logger;

    public CustomRetryPolicy(ILoggerFactory factory) : base(3, true, factory)
    {
        _logger = factory.CreateLogger<CustomRetryPolicy>();
    }

    protected override bool ShouldRetry(PipelineMessage message, Exception? exception)
    {
        bool shouldRetry = base.ShouldRetry(message, exception);
        if (shouldRetry)
        {
            _logger.LogInformation("Request should be retried.");
        }
        return shouldRetry;
    }
}

Usage:

ILoggerFactory factory = LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Trace));

CustomRetryPolicy customRetryPolicy = new(factory);

var options = new LibraryClientOptions()
{
    ClientLoggingOptions = new()
    {
        LoggerFactory = factory
    },
    RetryPolicy = customRetryPolicy
};

LibraryClient client = new(new Uri("https://www.example.com"), options);

Example using a custom transport

This is a simple, illustrative example of how the new constructor can be used to create a custom transport. The new constructor allows users to add additional logs to the retry policy, and also preserves the logging behavior in the base class.

Definition:

internal class SimpleCustomTransportPolicy : PipelineTransport
{
    private static readonly HttpClient _sharedDefaultClient = new();
    private readonly ILogger _logger;

    public SimpleCustomTransportPolicy(ILoggerFactory factory) : base(enableLogging: false, loggerFactory: factory)
    {
        _logger = factory.CreateLogger<SimpleCustomTransportPolicy>();
    }

    protected override PipelineMessage CreateMessageCore()
    {
        SimplePipelineRequest request = new();
        SimplePipelineMessage message = new(request);
        return message;
    }

    protected override void ProcessCore(PipelineMessage message)
    {
        // For illustrative purposes only, this is not a working implementation

        HttpRequestMessage request = new(new HttpMethod(message.Request.Method), message.Request.Uri);
        // Populate request from message

        _logger.LogInformation("Sending request.");

        HttpResponseMessage response = _sharedDefaultClient.Send(request);
        // Populate response on message
    }

    protected override async ValueTask ProcessCoreAsync(PipelineMessage message)
    {
        // For illustrative purposes only, this is not a working implementation

        HttpRequestMessage request = new(new HttpMethod(message.Request.Method), message.Request.Uri);
        // Populate request from message

        _logger.LogInformation("Sending request.");

        HttpResponseMessage response = await _sharedDefaultClient.SendAsync(request).ConfigureAwait(false);
        // Populate response on message
    }
}

Usage:

ILoggerFactory factory = LoggerFactory.Create(builder => builder.AddConsole().SetMinimumLevel(LogLevel.Trace));

SimpleCustomTransportPolicy transport = new(factory);

var options = new LibraryClientOptions()
{
    ClientLoggingOptions = new()
    {
        LoggerFactory = factory
    },
    Transport = transport
};

LibraryClient client = new(new Uri("https://www.example.com"), options);

Example using HttpClient for HTTP logs instead of System.ClientModel

ServiceCollection services = new();

services.AddHttpClient();
services.AddExtendedHttpClientLogging();

services.AddOptions<LibraryClientOptions>();

services.AddSingleton<LibraryClient>(serviceProvider =>
{
    // Configure client to use HttpClient logging instead of SCM HTTP logging.
    // Preserve other SCM-based client logging.
    HttpClient httpClient = serviceProvider.GetRequiredService<HttpClient>();
    LibraryClientOptions options = serviceProvider.GetRequiredService<LibraryClientOptions>();
    options.ClientLoggingOptions ??= new();
    options.ClientLoggingOptions.EnableMessageLogging = false;
    options.Transport = new HttpClientPipelineTransport(httpClient, true, options.ClientLoggingOptions.LoggerFactory);
    return new LibraryClient(new Uri("https://www.example.com"), options);
});

Alternative Designs

    public class ClientLoggingOptions { 
       public ClientLoggingOptions(); 
       public ILoggerFactory? LoggerFactory { get; set; }
       public IList<string> AllowedHeaderNames { get; }
       public IList<string> AllowedQueryParameters { get; }
-      public bool? EnableLogging { get; set; }
-      public bool? EnableMessageLogging { get; set; }
-      public bool? EnableMessageContentLogging { get; set; }
+      public MessageLoggingFields MessageLoggingFields { get; set; }
       public int? MessageContentSizeLimit { get; set; }
       public virtual void Freeze(); 
       protected void AssertNotFrozen(); 
   } 

[Flags]
public enum MessageLoggingFields
{
    /// <summary>
    /// No information is logged about HTTP requests or responses.
    /// </summary>
    None = 0x0,

    /// <summary>
    /// Log information about HTTP messages.
    /// </summary>
    Message = 0x1,

    /// <summary>
    /// Log the content of HTTP messages.
    /// </summary>
    MessageContent = 0x2,

    /// <summary>
    /// Log information about exceptions thrown in the transport.
    /// </summary>
    TransportExceptions = 0x4,

    /// <summary>
    /// Log information about retry attempts in the retry policy.
    /// </summary>
    RetryAttempts = 0x8,

    /// <summary>
    /// Log everything.
    /// </summary>
    All = Message | MessageContent | TransportExceptions | RetryAttempts
}

Risks

No response

[dotnet-policy-service]

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

[tarekgh]

Please open this issue in the repo https://github.com/Azure/azure-sdk-for-net/tree/main/sdk/core/System.ClientModel.

[stephentoub]

@terrajobst, @eerhardt, I assume we want to review this?

[dotnet-policy-service]

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

[tarekgh]

@stephentoub Is this issue occurring in runtime solely for the purpose of the design review, or are we planning to incorporate any code from the Azure SDK into the runtime? For now, I've updated the area label to meta since this isn't directly related to the logging extensions.

[stephentoub]

Is this issue occurring in runtime solely for the purpose of the design review, or are we planning to incorporate any code from the Azure SDK into the runtime? For now, I've updated the area label to meta since this isn't directly related to the logging extensions.

Design review