Skip to content
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Diagnostics.CodeAnalysis;
using System.Net.Http;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection.Extensions;
Expand All @@ -10,6 +11,7 @@
using Microsoft.Extensions.Http.Logging.Internal;
using Microsoft.Extensions.Options;
using Microsoft.Extensions.Telemetry.Internal;
using Microsoft.Shared.DiagnosticIds;
using Microsoft.Shared.Diagnostics;

namespace Microsoft.Extensions.DependencyInjection;
Expand All @@ -34,7 +36,32 @@ public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBu
{
_ = Throw.IfNull(builder);

return AddExtendedHttpClientLoggingInternal(builder);
return AddExtendedHttpClientLoggingInternal(builder, configureOptionsBuilder: null, wrapHandlersPipeline: true);
}

/// <summary>
/// Adds an <see cref="IHttpClientAsyncLogger" /> to emit logs for outgoing requests for a named <see cref="HttpClient"/>.
/// </summary>
/// <param name="builder">The <see cref="IHttpClientBuilder" />.</param>
/// <param name="wrapHandlersPipeline">
/// When <see langword="true"/>, the logger is placed at the beginning of the request pipeline, wrapping all other handlers.
/// When <see langword="false"/>, the logger is placed at the end of the pipeline, right before the primary message handler.
/// This affects what gets logged: with <see langword="true"/>, one log entry is emitted per logical request with total duration;
/// with <see langword="false"/> and resilience strategies like retries enabled, a separate log entry is emitted for each attempt with per-attempt duration.
/// </param>
/// <returns>The value of <paramref name="builder"/>.</returns>
/// <remarks>
/// All other loggers are removed - including the default one, registered via <see cref="HttpClientBuilderExtensions.AddDefaultLogger(IHttpClientBuilder)"/>.
/// A lot of the information logged by this method (like bodies, methods, host, path, and duration) will be added as enrichment tags to the structured log. Make sure
/// you have a way of viewing structured logs in order to view this extra information.
/// </remarks>
/// <exception cref="ArgumentNullException">Argument <paramref name="builder"/> is <see langword="null"/>.</exception>
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBuilder builder, bool wrapHandlersPipeline)
{
_ = Throw.IfNull(builder);

return AddExtendedHttpClientLoggingInternal(builder, configureOptionsBuilder: null, wrapHandlersPipeline);
}

/// <summary>
Expand All @@ -54,7 +81,34 @@ public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBu
_ = Throw.IfNull(builder);
_ = Throw.IfNull(section);

return AddExtendedHttpClientLoggingInternal(builder, options => options.Bind(section));
return AddExtendedHttpClientLoggingInternal(builder, options => options.Bind(section), wrapHandlersPipeline: true);
}

/// <summary>
/// Adds an <see cref="IHttpClientAsyncLogger" /> to emit logs for outgoing requests for a named <see cref="HttpClient"/>.
/// </summary>
/// <param name="builder">The <see cref="IHttpClientBuilder" />.</param>
/// <param name="section">The <see cref="IConfigurationSection"/> to use for configuring <see cref="LoggingOptions"/>.</param>
/// <param name="wrapHandlersPipeline">
/// When <see langword="true"/>, the logger is placed at the beginning of the request pipeline, wrapping all other handlers.
/// When <see langword="false"/>, the logger is placed at the end of the pipeline, right before the primary message handler.
/// This affects what gets logged: with <see langword="true"/>, one log entry is emitted per logical request with total duration;
/// with <see langword="false"/> and resilience strategies like retries enabled, a separate log entry is emitted for each attempt with per-attempt duration.
/// </param>
/// <returns>The value of <paramref name="builder"/>.</returns>
/// <remarks>
/// All other loggers are removed - including the default one, registered via <see cref="HttpClientBuilderExtensions.AddDefaultLogger(IHttpClientBuilder)"/>.
/// A lot of the information logged by this method (like bodies, methods, host, path, and duration) will be added as enrichment tags to the structured log. Make sure
/// you have a way of viewing structured logs in order to view this extra information.
/// </remarks>
/// <exception cref="ArgumentNullException">Any of the arguments is <see langword="null"/>.</exception>
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBuilder builder, IConfigurationSection section, bool wrapHandlersPipeline)
{
_ = Throw.IfNull(builder);
_ = Throw.IfNull(section);

return AddExtendedHttpClientLoggingInternal(builder, options => options.Bind(section), wrapHandlersPipeline);
}

/// <summary>
Expand All @@ -74,10 +128,40 @@ public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBu
_ = Throw.IfNull(builder);
_ = Throw.IfNull(configure);

return AddExtendedHttpClientLoggingInternal(builder, options => options.Configure(configure));
return AddExtendedHttpClientLoggingInternal(builder, options => options.Configure(configure), wrapHandlersPipeline: true);
}

/// <summary>
/// Adds an <see cref="IHttpClientAsyncLogger" /> to emit logs for outgoing requests for a named <see cref="HttpClient"/>.
/// </summary>
/// <param name="builder">The <see cref="IHttpClientBuilder" />.</param>
/// <param name="configure">The delegate to configure <see cref="LoggingOptions"/> with.</param>
/// <param name="wrapHandlersPipeline">
/// When <see langword="true"/>, the logger is placed at the beginning of the request pipeline, wrapping all other handlers.
/// When <see langword="false"/>, the logger is placed at the end of the pipeline, right before the primary message handler.
/// This affects what gets logged: with <see langword="true"/>, one log entry is emitted per logical request with total duration;
/// with <see langword="false"/> and resilience strategies like retries enabled, a separate log entry is emitted for each attempt with per-attempt duration.
/// </param>
/// <returns>The value of <paramref name="builder"/>.</returns>
/// <remarks>
/// All other loggers are removed - including the default one, registered via <see cref="HttpClientBuilderExtensions.AddDefaultLogger(IHttpClientBuilder)"/>.
/// A lot of the information logged by this method (like bodies, methods, host, path, and duration) will be added as enrichment tags to the structured log. Make sure
/// you have a way of viewing structured logs in order to view this extra information.
/// </remarks>
/// <exception cref="ArgumentNullException">Any of the arguments is <see langword="null"/>.</exception>
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
public static IHttpClientBuilder AddExtendedHttpClientLogging(this IHttpClientBuilder builder, Action<LoggingOptions> configure, bool wrapHandlersPipeline)
{
_ = Throw.IfNull(builder);
_ = Throw.IfNull(configure);

return AddExtendedHttpClientLoggingInternal(builder, options => options.Configure(configure), wrapHandlersPipeline);
}

private static IHttpClientBuilder AddExtendedHttpClientLoggingInternal(IHttpClientBuilder builder, Action<OptionsBuilder<LoggingOptions>>? configureOptionsBuilder = null)
private static IHttpClientBuilder AddExtendedHttpClientLoggingInternal(
IHttpClientBuilder builder,
Action<OptionsBuilder<LoggingOptions>>? configureOptionsBuilder,
bool wrapHandlersPipeline)
{
var optionsBuilder = builder.Services
.AddOptionsWithValidateOnStart<LoggingOptions, LoggingOptionsValidator>(builder.Name);
Expand All @@ -97,6 +181,6 @@ private static IHttpClientBuilder AddExtendedHttpClientLoggingInternal(IHttpClie
.RemoveAllLoggers()
.AddLogger(
serviceProvider => serviceProvider.GetRequiredKeyedService<HttpClientLogger>(builder.Name),
wrapHandlersPipeline: true);
wrapHandlersPipeline);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -115,4 +115,4 @@ private static IConfigurationSection GetConfigSection(HttpClientLatencyTelemetry
.Build()
.GetSection($"{nameof(HttpClientLatencyTelemetryOptions)}");
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@

using System;
using System.Collections.Generic;
using System.Linq;
using System.Net;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
Expand Down Expand Up @@ -404,6 +406,136 @@ public void AddHttpClientLogging_ServiceCollection_CreatesClientSuccessfully()
Assert.NotNull(httpClient);
}

[Fact]
public async Task LatencyInfo_IsPopulated_WhenLoggerWrapsHandlersPipeline()
{
await using var sp = new ServiceCollection()
.AddLatencyContext()
.AddRedaction()
.AddHttpClientLatencyTelemetry()
.AddHttpClient("test")
.ConfigurePrimaryHttpMessageHandler(() => new ServerNameStubHandler("TestServer"))
.AddExtendedHttpClientLogging(wrapHandlersPipeline: true)
.Services
.AddFakeLogging()
.BuildServiceProvider();

var client = sp.GetRequiredService<IHttpClientFactory>().CreateClient("test");

using var response = await client.GetAsync("http://localhost/api");
Assert.Equal(HttpStatusCode.OK, response.StatusCode);

var collector = sp.GetFakeLogCollector();
var record = collector.LatestRecord;
Assert.NotNull(record);

var latencyInfo = record.GetStructuredStateValue("LatencyInfo");
Assert.False(string.IsNullOrEmpty(latencyInfo));
Assert.StartsWith("v1.0,", latencyInfo);
Assert.Contains("TestServer", latencyInfo);
}

[Fact]
public async Task AddExtendedHttpClientLogging_WrapHandlersPipelineParameter_LogsCorrectNumberOfAttempts()
{
int attemptCount = 0;
var serviceCollection = new ServiceCollection();

serviceCollection.AddTransient(_ =>
new TestMessageHandler(_ =>
{
attemptCount++;
return attemptCount % 3 == 0 // every 3rd attempt succeeds
? new HttpResponseMessage(HttpStatusCode.OK)
: throw new HttpRequestException("Simulated failure");
}));

serviceCollection.AddTransient<TestRetryHandler>();

serviceCollection
.AddFakeRedaction()
.AddFakeLogging()
.AddHttpClient("outer")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>()
.AddHttpMessageHandler<TestRetryHandler>()
.AddExtendedHttpClientLogging(o => o.LogRequestStart = true, wrapHandlersPipeline: true);

serviceCollection
.AddHttpClient("inner")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>()
.AddHttpMessageHandler<TestRetryHandler>()
.AddExtendedHttpClientLogging(o => o.LogRequestStart = true, wrapHandlersPipeline: false);

using var services = serviceCollection.BuildServiceProvider();
var factory = services.GetRequiredService<IHttpClientFactory>();
var collector = services.GetFakeLogCollector();

var outerClient = factory.CreateClient("outer");
attemptCount = 0;
collector.Clear();

_ = await outerClient.GetAsync("http://localhost/api");

var outerLogs = collector.GetSnapshot();
Assert.Equal(2, outerLogs.Count); // 1 request start + 1 request stop

var innerClient = factory.CreateClient("inner");
attemptCount = 0;
collector.Clear();

_ = await innerClient.GetAsync("http://localhost/api");

var innerLogs = collector.GetSnapshot();
Assert.Equal(6, innerLogs.Count); // 3 attempts × (1 start + 1 stop/failed)
}

private sealed class TestMessageHandler(Func<HttpRequestMessage, HttpResponseMessage> responseFactory)
: HttpMessageHandler
{
protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
return Task.FromResult(responseFactory(request));
}
}

private sealed class TestRetryHandler : DelegatingHandler
{
private const int MaxRetries = 2;

protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
HttpRequestException? lastException = null;

for (int attempt = 0; attempt <= MaxRetries; attempt++)
{
try
{
return await base.SendAsync(request, cancellationToken);
}
catch (HttpRequestException ex)
{
lastException = ex;
if (attempt == MaxRetries)
{
throw;
}
}
}

throw lastException!;
}
}

private sealed class ServerNameStubHandler(string serverName) : HttpMessageHandler
{
protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
var response = new HttpResponseMessage(HttpStatusCode.OK);
response.Headers.TryAddWithoutValidation(TelemetryConstants.ServerApplicationNameHeader, serverName);
return Task.FromResult(response);
}
}

private static void EnsureSingleLogger<T>(IServiceProvider serviceProvider, string serviceKey)
where T : IHttpClientLogger
{
Expand Down
Loading