[release/8.0] HttpClient logging based on new .NET 8 runtime APIs (#4224)

bench/Libraries/Microsoft.Extensions.Http.Telemetry.PerformanceTests/BenchEnricher.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System;
 using System.Net.Http;
 using Microsoft.Extensions.Telemetry.Enrichment;
 
@@ -11,8 +12,7 @@ internal sealed class BenchEnricher : IHttpClientLogEnricher
     private const string Key = "Performance in .NET Extensions";
     private const string Value = "is paramount.";
 
-    public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null,
-        HttpResponseMessage? response = null)
+    public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null)
     {
         if (request is not null)
         {

eng/common/tools.ps1

@@ -296,7 +296,7 @@ function InstallDotNet([string] $dotnetRoot,
     if ($runtime -eq "aspnetcore") { $runtimePath = $runtimePath + "\Microsoft.AspNetCore.App" }
     if ($runtime -eq "windowsdesktop") { $runtimePath = $runtimePath + "\Microsoft.WindowsDesktop.App" }
     $runtimePath = $runtimePath + "\" + $version
-  
+
     $dotnetVersionLabel = "runtime toolset '$runtime/$architecture v$version'"
 
     if (Test-Path $runtimePath) {

src/LegacySupport/TaskWaitAsync/TaskExtensions.cs

@@ -38,7 +38,7 @@ private static async Task<TResult> WaitTaskAsync<TResult>(Task<TResult> task, Ca
     {
         var tcs = new TaskCompletionSource<TResult>(TaskCreationOptions.RunContinuationsAsynchronously);
         using (cancellationToken.Register(
-                   static o => ((TaskCompletionSource<TResult>)o!).SetCanceled(), tcs, false))
+                static state => ((TaskCompletionSource<TResult>)state!).SetCanceled(), tcs, false))
         {
             var t = await Task.WhenAny(task, tcs.Task).ConfigureAwait(false);
 #pragma warning disable VSTHRD103 // Call async methods when in an async method

src/Libraries/Microsoft.Extensions.Http.Telemetry/Latency/Internal/HttpClientLatencyLogEnricher.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System;
 using System.Linq;
 using System.Net.Http;
 using System.Net.Http.Headers;
@@ -14,7 +15,7 @@
 namespace Microsoft.Extensions.Http.Telemetry.Latency.Internal;
 
 /// <summary>
-/// The enrciher appends checkpoints for the outgoing http request.
+/// The enricher appends checkpoints for the outgoing http request.
 /// It also logs the server name from the response header to correlate logs between client and server.
 /// </summary>
 internal sealed class HttpClientLatencyLogEnricher : IHttpClientLogEnricher
@@ -30,7 +31,7 @@ public HttpClientLatencyLogEnricher(HttpClientLatencyContext latencyContext, ILa
         _enricherInvoked = tokenIssuer.GetCheckpointToken(HttpCheckpoints.EnricherInvoked);
     }
 
-    public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, HttpResponseMessage? response = null)
+    public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null)
     {
         if (response != null)
         {

src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/HttpClientLoggingTagNames.cs

@@ -7,7 +7,7 @@
 namespace Microsoft.Extensions.Http.Telemetry.Logging;
 
 /// <summary>
-/// Constants used for HTTP client logging dimensions.
+/// Constants used for HTTP client logging tags.
 /// </summary>
 public static class HttpClientLoggingTagNames
 {
@@ -57,10 +57,10 @@ public static class HttpClientLoggingTagNames
     public const string StatusCode = "httpStatusCode";
 
     /// <summary>
-    /// Gets a list of all dimension names.
+    /// Gets a list of all tag names.
     /// </summary>
-    /// <returns>A read-only <see cref="IReadOnlyList{String}"/> of all dimension names.</returns>
-    public static IReadOnlyList<string> DimensionNames { get; } =
+    /// <returns>A read-only <see cref="IReadOnlyList{String}"/> of all tag names.</returns>
+    public static IReadOnlyList<string> TagNames { get; } =
         Array.AsReadOnly(new[]
         {
             Duration,

src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/IHttpClientLogEnricher.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System;
 using System.Net.Http;
 using Microsoft.Extensions.Telemetry.Enrichment;
 
@@ -17,5 +18,6 @@ public interface IHttpClientLogEnricher
     /// <param name="collector">Tag collector to add tags to.</param>
     /// <param name="request"><see cref="HttpRequestMessage"/> object associated with the outgoing HTTP request.</param>
     /// <param name="response"><see cref="HttpResponseMessage"/> object associated with the outgoing HTTP request.</param>
-    void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request = null, HttpResponseMessage? response = null);
+    /// <param name="exception">An optional <see cref="Exception"/> that was thrown within the outgoing HTTP request processing.</param>
+    void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage request, HttpResponseMessage? response = null, Exception? exception = null);
 }

src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpClientLogger.cs

@@ -0,0 +1,242 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System;
+using System.Collections.Generic;
+using System.Diagnostics.CodeAnalysis;
+using System.Linq;
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Http.Logging;
+using Microsoft.Extensions.Http.Telemetry.Logging.Internal;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.ObjectPool;
+using Microsoft.Extensions.Options;
+using Microsoft.Extensions.Telemetry.Logging;
+using Microsoft.Shared.Pools;
+
+namespace Microsoft.Extensions.Http.Telemetry.Logging;
+
+internal sealed class HttpClientLogger : IHttpClientAsyncLogger
+{
+    private const string SyncLoggingExceptionMessage = "Synchronous logging is not supported";
+
+    private readonly ObjectPool<List<KeyValuePair<string, string>>> _headersPool =
+        PoolFactory.CreateListPool<KeyValuePair<string, string>>();
+
+    private readonly ObjectPool<LogRecord> _logRecordPool =
+        PoolFactory.CreateResettingPool<LogRecord>();
+
+    private readonly bool _logRequestStart;
+    private readonly bool _logResponseHeaders;
+    private readonly bool _logRequestHeaders;
+    private readonly bool _pathParametersRedactionSkipped;
+    private ILogger<HttpClientLogger> _logger;
+    private IHttpRequestReader _httpRequestReader;
+    private IHttpClientLogEnricher[] _enrichers;
+
+    public HttpClientLogger(
+        IServiceProvider serviceProvider,
+        ILogger<HttpClientLogger> logger,
+        IEnumerable<IHttpClientLogEnricher> enrichers,
+        IOptionsMonitor<LoggingOptions> optionsMonitor,
+        [ServiceKey] string? serviceKey = null)
+        : this(
+              logger,
+              serviceProvider.GetRequiredOrKeyedRequiredService<IHttpRequestReader>(serviceKey),
+              enrichers,
+              optionsMonitor.GetKeyedOrCurrent(serviceKey))
+    {
+    }
+
+    internal HttpClientLogger(
+        ILogger<HttpClientLogger> logger,
+        IHttpRequestReader httpRequestReader,
+        IEnumerable<IHttpClientLogEnricher> enrichers,
+        LoggingOptions options)
+    {
+        _logger = logger;
+        _httpRequestReader = httpRequestReader;
+        _enrichers = enrichers.Where(static x => x is not null).ToArray();
+        _logRequestStart = options.LogRequestStart;
+        _logResponseHeaders = options.ResponseHeadersDataClasses.Count > 0;
+        _logRequestHeaders = options.RequestHeadersDataClasses.Count > 0;
+        _pathParametersRedactionSkipped = options.RequestPathParameterRedactionMode == HttpRouteParameterRedactionMode.None;
+    }
+
+    [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "The logger shouldn't throw")]
+    public async ValueTask<object?> LogRequestStartAsync(HttpRequestMessage request, CancellationToken cancellationToken = default)
+    {
+        var logRecord = _logRecordPool.Get();
+
+        List<KeyValuePair<string, string>>? requestHeadersBuffer = null;
+        if (_logRequestHeaders)
+        {
+            requestHeadersBuffer = _headersPool.Get();
+        }
+
+        try
+        {
+            await _httpRequestReader.ReadRequestAsync(logRecord, request, requestHeadersBuffer, cancellationToken).ConfigureAwait(false);
+
+            if (_logRequestStart)
+            {
+                Log.OutgoingRequest(_logger, LogLevel.Information, logRecord);
+            }
+
+            return logRecord;
+        }
+        catch (Exception ex)
+        {
+            // If redaction is skipped, we can log unredacted request path; otherwise use "logRecord.Path" (even though it might not be set):
+            var pathToLog = _pathParametersRedactionSkipped
+                ? request.RequestUri?.AbsolutePath
+                : logRecord.Path;
+
+            Log.RequestReadError(_logger, ex, request.Method, request.RequestUri?.Host, pathToLog);
+
+            // Return back pooled objects (since the logRecord wasn't fully prepared):
+            _logRecordPool.Return(logRecord);
+
+            if (requestHeadersBuffer is not null)
+            {
+                _headersPool.Return(requestHeadersBuffer);
+            }
+
+            // Recommendation is to swallow the exception (logger shouldn't throw), so we don't re-throw here:
+            return null;
+        }
+    }
+
+    public async ValueTask LogRequestStopAsync(
+        object? context,
+        HttpRequestMessage request,
+        HttpResponseMessage response,
+        TimeSpan elapsed,
+        CancellationToken cancellationToken = default)
+            => await LogResponseAsync(context, request, response, null, elapsed, cancellationToken).ConfigureAwait(false);
+
+    public async ValueTask LogRequestFailedAsync(
+        object? context,
+        HttpRequestMessage request,
+        HttpResponseMessage? response,
+        Exception exception,
+        TimeSpan elapsed,
+        CancellationToken cancellationToken = default)
+            => await LogResponseAsync(context, request, response, exception, elapsed, cancellationToken).ConfigureAwait(false);
+
+    public object? LogRequestStart(HttpRequestMessage request)
+        => throw new NotSupportedException(SyncLoggingExceptionMessage);
+
+    public void LogRequestStop(object? context, HttpRequestMessage request, HttpResponseMessage response, TimeSpan elapsed)
+        => throw new NotSupportedException(SyncLoggingExceptionMessage);
+
+    public void LogRequestFailed(object? context, HttpRequestMessage request, HttpResponseMessage? response, Exception exception, TimeSpan elapsed)
+        => throw new NotSupportedException(SyncLoggingExceptionMessage);
+
+    private static LogLevel GetLogLevel(LogRecord logRecord)
+    {
+        const int HttpErrorsRangeStart = 400;
+        const int HttpErrorsRangeEnd = 599;
+        int statusCode = logRecord.StatusCode!.Value;
+
+        if (statusCode >= HttpErrorsRangeStart && statusCode <= HttpErrorsRangeEnd)
+        {
+            return LogLevel.Error;
+        }
+
+        return LogLevel.Information;
+    }
+
+    [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "The logger shouldn't throw")]
+    private async ValueTask LogResponseAsync(
+        object? context,
+        HttpRequestMessage request,
+        HttpResponseMessage? response,
+        Exception? exception,
+        TimeSpan elapsed,
+        CancellationToken cancellationToken)
+    {
+        if (context is not LogRecord logRecord)
+        {
+            var requestState = response is null
+                ? "failed"
+                : "completed";
+
+            Log.LoggerContextMissing(_logger, exception, requestState, request.Method, request.RequestUri?.Host);
+            return;
+        }
+
+        LoggerMessageState? loggerMessageState = null;
+        List<KeyValuePair<string, string>>? responseHeadersBuffer = null;
+        try
+        {
+            if (response is not null)
+            {
+                if (_logResponseHeaders)
+                {
+                    responseHeadersBuffer = _headersPool.Get();
+                }
+
+                await _httpRequestReader.ReadResponseAsync(logRecord, response, responseHeadersBuffer, cancellationToken).ConfigureAwait(false);
+            }
+
+            loggerMessageState = LoggerMessageHelper.ThreadLocalState;
+            FillLogRecord(logRecord, loggerMessageState, in elapsed, request, response, exception);
+
+            if (exception is null)
+            {
+                Log.OutgoingRequest(_logger, GetLogLevel(logRecord), logRecord);
+            }
+            else
+            {
+                Log.OutgoingRequestError(_logger, logRecord, exception);
+            }
+        }
+        catch (Exception ex)
+        {
+            // Logger shouldn't throw, so we just log the exception and don't re-throw it:
+            Log.ResponseReadError(_logger, ex, request.Method, logRecord.Host, logRecord.Path);
+        }
+        finally
+        {
+            var requestHeadersBuffer = logRecord.RequestHeaders; // Store the value first, and then return logRecord to the pool.
+            _logRecordPool.Return(logRecord);
+            loggerMessageState?.Clear();
+
+            if (responseHeadersBuffer is not null)
+            {
+                _headersPool.Return(responseHeadersBuffer);
+            }
+
+            if (requestHeadersBuffer is not null)
+            {
+                _headersPool.Return(requestHeadersBuffer);
+            }
+        }
+    }
+
+    [SuppressMessage("Design", "CA1031:Do not catch general exception types",
+        Justification = "We intentionally catch all exception types to make Telemetry code resilient to failures.")]
+    private void FillLogRecord(
+        LogRecord logRecord, LoggerMessageState loggerMessageState, in TimeSpan elapsed,
+        HttpRequestMessage request, HttpResponseMessage? response, Exception? exception)
+    {
+        foreach (var enricher in _enrichers)
+        {
+            try
+            {
+                enricher.Enrich(loggerMessageState, request, response, exception);
+            }
+            catch (Exception e)
+            {
+                Log.EnrichmentError(_logger, e, enricher.GetType().FullName, request.Method, logRecord.Host, logRecord.Path);
+            }
+        }
+
+        logRecord.EnrichmentTags = loggerMessageState;
+        logRecord.Duration = (long)elapsed.TotalMilliseconds;
+    }
+}

src/Libraries/Microsoft.Extensions.Http.Telemetry/Logging/Internal/HttpHeadersReader.cs

@@ -7,9 +7,9 @@
 using System.Net.Http;
 using System.Net.Http.Headers;
 using Microsoft.Extensions.Compliance.Classification;
+using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Telemetry.Internal;
-using Microsoft.Shared.Diagnostics;
 
 namespace Microsoft.Extensions.Http.Telemetry.Logging.Internal;
 
@@ -19,14 +19,14 @@ internal sealed class HttpHeadersReader : IHttpHeadersReader
     private readonly FrozenDictionary<string, DataClassification> _responseHeaders;
     private readonly IHttpHeadersRedactor _redactor;
 
-    public HttpHeadersReader(IOptions<LoggingOptions> options, IHttpHeadersRedactor redactor)
+    public HttpHeadersReader(IOptionsMonitor<LoggingOptions> optionsMonitor, IHttpHeadersRedactor redactor, [ServiceKey] string? serviceKey = null)
     {
-        _ = Throw.IfMemberNull(options, options.Value);
+        var options = optionsMonitor.GetKeyedOrCurrent(serviceKey);
 
         _redactor = redactor;
 
-        _requestHeaders = options.Value.RequestHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase);
-        _responseHeaders = options.Value.ResponseHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase);
+        _requestHeaders = options.RequestHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase);
+        _responseHeaders = options.ResponseHeadersDataClasses.ToFrozenDictionary(StringComparer.OrdinalIgnoreCase);
     }
 
     public void ReadRequestHeaders(HttpRequestMessage request, List<KeyValuePair<string, string>>? destination)