Skip to content

Commit

Permalink
[HttpClientFactory] Remove dependency on ILoggerFactory (#89531)
Browse files Browse the repository at this point in the history 
* Remove dependency on ILoggerFactory

* Add test

* PR feedback & add more tests

* PR feedback
  • Loading branch information
@CarnaViire
CarnaViire committed Aug 9, 2023
1 parent 57b26bb commit b355725
Show file tree
Hide file tree
Showing 4 changed files with 120 additions and 30 deletions.
22 changes: 13 additions & 9 deletions src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,12 +18,12 @@ namespace Microsoft.Extensions.Http
internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandlerFactory
{
private static readonly TimerCallback _cleanupCallback = (s) => ((DefaultHttpClientFactory)s!).CleanupTimer_Tick();
private readonly ILogger _logger;
private readonly IServiceProvider _services;
private readonly IServiceScopeFactory _scopeFactory;
private readonly IOptionsMonitor<HttpClientFactoryOptions> _optionsMonitor;
private readonly IHttpMessageHandlerBuilderFilter[] _filters;
private readonly Func<string, Lazy<ActiveHandlerTrackingEntry>> _entryFactory;
private readonly Lazy<ILogger> _logger;

// Default time of 10s for cleanup seems reasonable.
// Quick math:
Expand Down Expand Up @@ -61,13 +61,11 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle
public DefaultHttpClientFactory(
IServiceProvider services,
IServiceScopeFactory scopeFactory,
ILoggerFactory loggerFactory,
IOptionsMonitor<HttpClientFactoryOptions> optionsMonitor,
IEnumerable<IHttpMessageHandlerBuilderFilter> filters)
{
ThrowHelper.ThrowIfNull(services);
ThrowHelper.ThrowIfNull(scopeFactory);
ThrowHelper.ThrowIfNull(loggerFactory);
ThrowHelper.ThrowIfNull(optionsMonitor);
ThrowHelper.ThrowIfNull(filters);

Expand All @@ -76,8 +74,6 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle
_optionsMonitor = optionsMonitor;
_filters = filters.ToArray();

_logger = loggerFactory.CreateLogger<DefaultHttpClientFactory>();

// case-sensitive because named options is.
_activeHandlers = new ConcurrentDictionary<string, Lazy<ActiveHandlerTrackingEntry>>(StringComparer.Ordinal);
_entryFactory = (name) =>
Expand All @@ -93,6 +89,14 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle

_cleanupTimerLock = new object();
_cleanupActiveLock = new object();

// We want to prevent a circular depencency between ILoggerFactory and IHttpClientFactory, in case
// any of ILoggerProvider instances use IHttpClientFactory to send logs to an external server.
// Logger will be created during the first ExpiryTimer_Tick execution. Lazy guarantees thread safety
// to prevent creation of unnecessary ILogger objects in case several handlers expired at the same time.
_logger = new Lazy<ILogger>(
() => _services.GetRequiredService<ILoggerFactory>().CreateLogger<DefaultHttpClientFactory>(),
LazyThreadSafetyMode.ExecutionAndPublication);
}

public HttpClient CreateClient(string name)
Expand Down Expand Up @@ -204,7 +208,7 @@ internal void ExpiryTimer_Tick(object? state)
var expired = new ExpiredHandlerTrackingEntry(active);
_expiredHandlers.Enqueue(expired);

Log.HandlerExpired(_logger, active.Name, active.Lifetime);
Log.HandlerExpired(_logger.Value, active.Name, active.Lifetime);

StartCleanupTimer();
}
Expand Down Expand Up @@ -262,7 +266,7 @@ internal void CleanupTimer_Tick()
try
{
int initialCount = _expiredHandlers.Count;
Log.CleanupCycleStart(_logger, initialCount);
Log.CleanupCycleStart(_logger.Value, initialCount);

var stopwatch = ValueStopwatch.StartNew();

Expand All @@ -283,7 +287,7 @@ internal void CleanupTimer_Tick()
}
catch (Exception ex)
{
Log.CleanupItemFailed(_logger, entry.Name, ex);
Log.CleanupItemFailed(_logger.Value, entry.Name, ex);
}
}
else
Expand All @@ -294,7 +298,7 @@ internal void CleanupTimer_Tick()
}
}

Log.CleanupCycleEnd(_logger, stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count);
Log.CleanupCycleEnd(_logger.Value, stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count);
}
finally
{
Expand Down
18 changes: 12 additions & 6 deletions ...libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Threading;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Http.Logging;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
Expand All @@ -11,15 +13,19 @@ namespace Microsoft.Extensions.Http
// Internal so we can change the requirements without breaking changes.
internal sealed class LoggingHttpMessageHandlerBuilderFilter : IHttpMessageHandlerBuilderFilter
{
private readonly ILoggerFactory _loggerFactory;
// we want to prevent a circular depencency between ILoggerFactory and IHttpMessageHandlerBuilderFilter, in case
// any of ILoggerProvider instances use IHttpClientFactory to send logs to an external server
private ILoggerFactory? _loggerFactory;
private ILoggerFactory LoggerFactory => _loggerFactory ??= _serviceProvider.GetRequiredService<ILoggerFactory>();
private readonly IServiceProvider _serviceProvider;
private readonly IOptionsMonitor<HttpClientFactoryOptions> _optionsMonitor;

public LoggingHttpMessageHandlerBuilderFilter(ILoggerFactory loggerFactory, IOptionsMonitor<HttpClientFactoryOptions> optionsMonitor)
public LoggingHttpMessageHandlerBuilderFilter(IServiceProvider serviceProvider, IOptionsMonitor<HttpClientFactoryOptions> optionsMonitor)
{
ThrowHelper.ThrowIfNull(loggerFactory);
ThrowHelper.ThrowIfNull(serviceProvider);
ThrowHelper.ThrowIfNull(optionsMonitor);

_loggerFactory = loggerFactory;
_serviceProvider = serviceProvider;
_optionsMonitor = optionsMonitor;
}

Expand All @@ -42,8 +48,8 @@ public Action<HttpMessageHandlerBuilder> Configure(Action<HttpMessageHandlerBuil
// We want all of our logging message to show up as-if they are coming from HttpClient,
// but also to include the name of the client for more fine-grained control.
ILogger outerLogger = _loggerFactory.CreateLogger($"System.Net.Http.HttpClient.{loggerName}.LogicalHandler");
ILogger innerLogger = _loggerFactory.CreateLogger($"System.Net.Http.HttpClient.{loggerName}.ClientHandler");
ILogger outerLogger = LoggerFactory.CreateLogger($"System.Net.Http.HttpClient.{loggerName}.LogicalHandler");
ILogger innerLogger = LoggerFactory.CreateLogger($"System.Net.Http.HttpClient.{loggerName}.ClientHandler");
// The 'scope' handler goes first so it can surround everything.
builder.AdditionalHandlers.Insert(0, new LoggingScopeHttpMessageHandler(outerLogger, options));
Expand Down
27 changes: 12 additions & 15 deletions ...oft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,8 +30,6 @@ public DefaultHttpClientFactoryTest()

public IServiceScopeFactory ScopeFactory { get; }

public ILoggerFactory LoggerFactory { get; } = NullLoggerFactory.Instance;

public IOptionsMonitor<HttpClientFactoryOptions> Options { get; }

public IEnumerable<IHttpMessageHandlerBuilderFilter> EmptyFilters = Array.Empty<IHttpMessageHandlerBuilderFilter>();
Expand All @@ -46,7 +44,7 @@ public void Factory_MultipleCalls_DoesNotCacheHttpClient()
count++;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act 1
var client1 = factory.CreateClient();
Expand All @@ -69,7 +67,7 @@ public void Factory_MultipleCalls_CachesHandler()
count++;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act 1
var client1 = factory.CreateClient();
Expand Down Expand Up @@ -98,7 +96,7 @@ public void Factory_DisposeClient_DoesNotDisposeHandler()
b.PrimaryHandler = mockHandler.Object;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act
using (factory.CreateClient())
Expand All @@ -124,7 +122,7 @@ public void Factory_DisposeHandler_DoesNotDisposeInnerHandler()
b.PrimaryHandler = mockHandler.Object;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act
using (factory.CreateHandler())
Expand All @@ -144,7 +142,7 @@ public void Factory_CreateClient_WithoutName_UsesDefaultOptions()
count++;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act
var client = factory.CreateClient();
Expand All @@ -163,7 +161,7 @@ public void Factory_CreateClient_WithName_UsesNamedOptions()
count++;
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters);
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters);

// Act
var client = factory.CreateClient("github");
Expand Down Expand Up @@ -227,7 +225,7 @@ public void Factory_CreateClient_FiltersCanDecorateBuilder()
b.AdditionalHandlers.Add((DelegatingHandler)expected[4]);
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, new[]
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, new[]
{
filter1.Object,
filter2.Object,
Expand Down Expand Up @@ -256,7 +254,7 @@ public void Factory_CreateClient_FiltersCanDecorateBuilder()
public async Task Factory_CreateClient_WithExpiry_CanExpire()
{
// Arrange
var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters)
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters)
{
EnableExpiryTimer = true,
EnableCleanupTimer = true,
Expand Down Expand Up @@ -299,7 +297,7 @@ public async Task Factory_CreateClient_WithExpiry_CanExpire()
public async Task Factory_CreateClient_WithExpiry_HandlerCanBeReusedBeforeExpiry()
{
// Arrange
var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters)
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters)
{
EnableExpiryTimer = true,
EnableCleanupTimer = true,
Expand Down Expand Up @@ -354,7 +352,7 @@ public async Task Factory_CleanupCycle_DisposesEligibleHandler()
b.AdditionalHandlers.Add(disposeHandler);
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters)
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters)
{
EnableExpiryTimer = true,
EnableCleanupTimer = true,
Expand Down Expand Up @@ -424,7 +422,7 @@ public async Task Factory_CleanupCycle_DisposesLiveHandler()
b.AdditionalHandlers.Add(disposeHandler);
});

var factory = new TestHttpClientFactory(Services, ScopeFactory, LoggerFactory, Options, EmptyFilters)
var factory = new TestHttpClientFactory(Services, ScopeFactory, Options, EmptyFilters)
{
EnableExpiryTimer = true,
EnableCleanupTimer = true,
Expand Down Expand Up @@ -515,10 +513,9 @@ private class TestHttpClientFactory : DefaultHttpClientFactory
public TestHttpClientFactory(
IServiceProvider services,
IServiceScopeFactory scopeFactory,
ILoggerFactory loggerFactory,
IOptionsMonitor<HttpClientFactoryOptions> optionsMonitor,
IEnumerable<IHttpMessageHandlerBuilderFilter> filters)
: base(services, scopeFactory, loggerFactory, optionsMonitor, filters)
: base(services, scopeFactory, optionsMonitor, filters)
{
ActiveEntryState = new Dictionary<ActiveHandlerTrackingEntry, (TaskCompletionSource<ActiveHandlerTrackingEntry>, Task)>();
CleanupTimerStarted = new ManualResetEventSlim(initialState: false);
Expand Down
83 changes: 83 additions & 0 deletions ...oft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -371,6 +371,89 @@ public async Task WrapHandlerPipeline_LogCorrectNumberOfEvents()
Assert.Equal(4, innerLogger.RequestFailedLogCount);
}

[Fact]
public async Task LoggerFactoryWithHttpClientFactory_NoCircularDependency_PublicLogging()
{
var sink = new TestSink();
var services = new ServiceCollection();
services.AddTransient<TestMessageHandler>();
services.AddSingleton<TestSink>(sink);
services.AddSingleton<TestLoggerProvider>();

services.AddLogging(b => b.SetMinimumLevel(LogLevel.Trace));
services.AddSingleton<ILoggerProvider>(sp => sp.GetRequiredService<TestLoggerProvider>());
services.AddHttpClient("TestLoggerProvider")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>()
.RemoveAllLoggers();

services.AddHttpClient("Production")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>();

var serviceProvider = services.BuildServiceProvider();

var loggerFactory = serviceProvider.GetService<ILoggerFactory>();
Assert.NotNull(loggerFactory);

var prodClient = serviceProvider.GetRequiredService<IHttpClientFactory>().CreateClient("Production");

_ = await prodClient.GetAsync(Url);

Assert.Equal(DefaultLoggerEventsPerRequest, sink.Writes.Count(w => w.LoggerName.StartsWith("System.Net.Http.HttpClient.Production")));
Assert.Equal(0, sink.Writes.Count(w => w.LoggerName.StartsWith("System.Net.Http.HttpClient.TestLoggerProvider")));
}

[ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported), nameof(PlatformDetection.IsPreciseGcSupported))]
public async Task LoggerFactoryWithHttpClientFactory_NoCircularDependency_DebugLogging()
{
var sink = new TestSink();
var services = new ServiceCollection();
services.AddTransient<TestMessageHandler>();
services.AddSingleton<TestSink>(sink);
services.AddSingleton<TestLoggerProvider>();

services.AddLogging(b => b.SetMinimumLevel(LogLevel.Trace));
services.AddSingleton<ILoggerProvider>(sp => sp.GetRequiredService<TestLoggerProvider>());
services.AddHttpClient("TestLoggerProvider")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>()
.RemoveAllLoggers();

services.AddHttpClient("Production")
.ConfigurePrimaryHttpMessageHandler<TestMessageHandler>();

var serviceProvider = services.BuildServiceProvider();

var httpClientFactory = (DefaultHttpClientFactory)serviceProvider.GetRequiredService<IHttpClientFactory>();
var prodClient = httpClientFactory.CreateClient("Production");

_ = await prodClient.GetAsync(Url);

httpClientFactory.StartCleanupTimer(); // we need to create a timer instance before triggering cleanup; normally it happens after the first expiry
httpClientFactory.CleanupTimer_Tick(); // trigger cleanup to write debug logs

Assert.Equal(2, sink.Writes.Count(w => w.LoggerName == typeof(DefaultHttpClientFactory).FullName));
}

private sealed class TestLoggerProvider : ILoggerProvider
{
private readonly HttpClient _httpClient;
private readonly TestSink _testSink;

public TestLoggerProvider(IHttpClientFactory httpClientFactory, TestSink testSink)
{
_httpClient = httpClientFactory.CreateClient("TestLoggerProvider");
_testSink = testSink;
_testSink.MessageLogged += _ => _httpClient.GetAsync(Url).GetAwaiter().GetResult(); // simulating sending logs on the wire
}

public ILogger CreateLogger(string categoryName)
{
var logger = new TestLogger(categoryName, _testSink, enabled: true);
return logger;
}

public void Dispose() => _httpClient.Dispose();
}

private class TestCountingLogger : IHttpClientLogger
{
public int RequestStartLogCount { get; private set; }
Expand Down

0 comments on commit b355725

Please sign in to comment.