From b35572540e0904c6a23dc5466f73c361ed877dc1 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Wed, 9 Aug 2023 10:46:11 +0100 Subject: [PATCH] [HttpClientFactory] Remove dependency on ILoggerFactory (#89531) * Remove dependency on ILoggerFactory * Add test * PR feedback & add more tests * PR feedback --- .../src/DefaultHttpClientFactory.cs | 22 +++-- .../LoggingHttpMessageHandlerBuilderFilter.cs | 18 ++-- .../DefaultHttpClientFactoryTest.cs | 27 +++--- .../Logging/HttpClientLoggerTest.cs | 83 +++++++++++++++++++ 4 files changed, 120 insertions(+), 30 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs index ec14a145c03..e4a84960b9f 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs @@ -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 _optionsMonitor; private readonly IHttpMessageHandlerBuilderFilter[] _filters; private readonly Func> _entryFactory; + private readonly Lazy _logger; // Default time of 10s for cleanup seems reasonable. // Quick math: @@ -61,13 +61,11 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle public DefaultHttpClientFactory( IServiceProvider services, IServiceScopeFactory scopeFactory, - ILoggerFactory loggerFactory, IOptionsMonitor optionsMonitor, IEnumerable filters) { ThrowHelper.ThrowIfNull(services); ThrowHelper.ThrowIfNull(scopeFactory); - ThrowHelper.ThrowIfNull(loggerFactory); ThrowHelper.ThrowIfNull(optionsMonitor); ThrowHelper.ThrowIfNull(filters); @@ -76,8 +74,6 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle _optionsMonitor = optionsMonitor; _filters = filters.ToArray(); - _logger = loggerFactory.CreateLogger(); - // case-sensitive because named options is. _activeHandlers = new ConcurrentDictionary>(StringComparer.Ordinal); _entryFactory = (name) => @@ -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( + () => _services.GetRequiredService().CreateLogger(), + LazyThreadSafetyMode.ExecutionAndPublication); } public HttpClient CreateClient(string name) @@ -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(); } @@ -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(); @@ -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 @@ -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 { diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs index 9b982bbf3cc..a10a1f831e8 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs @@ -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; @@ -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(); + private readonly IServiceProvider _serviceProvider; private readonly IOptionsMonitor _optionsMonitor; - public LoggingHttpMessageHandlerBuilderFilter(ILoggerFactory loggerFactory, IOptionsMonitor optionsMonitor) + public LoggingHttpMessageHandlerBuilderFilter(IServiceProvider serviceProvider, IOptionsMonitor optionsMonitor) { - ThrowHelper.ThrowIfNull(loggerFactory); + ThrowHelper.ThrowIfNull(serviceProvider); ThrowHelper.ThrowIfNull(optionsMonitor); - _loggerFactory = loggerFactory; + _serviceProvider = serviceProvider; _optionsMonitor = optionsMonitor; } @@ -42,8 +48,8 @@ public Action Configure(Action Options { get; } public IEnumerable EmptyFilters = Array.Empty(); @@ -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(); @@ -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(); @@ -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()) @@ -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()) @@ -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(); @@ -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"); @@ -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, @@ -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, @@ -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, @@ -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, @@ -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, @@ -515,10 +513,9 @@ private class TestHttpClientFactory : DefaultHttpClientFactory public TestHttpClientFactory( IServiceProvider services, IServiceScopeFactory scopeFactory, - ILoggerFactory loggerFactory, IOptionsMonitor optionsMonitor, IEnumerable filters) - : base(services, scopeFactory, loggerFactory, optionsMonitor, filters) + : base(services, scopeFactory, optionsMonitor, filters) { ActiveEntryState = new Dictionary, Task)>(); CleanupTimerStarted = new ManualResetEventSlim(initialState: false); diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs index 0ba5611ed29..fb1d94310d5 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs @@ -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(); + services.AddSingleton(sink); + services.AddSingleton(); + + services.AddLogging(b => b.SetMinimumLevel(LogLevel.Trace)); + services.AddSingleton(sp => sp.GetRequiredService()); + services.AddHttpClient("TestLoggerProvider") + .ConfigurePrimaryHttpMessageHandler() + .RemoveAllLoggers(); + + services.AddHttpClient("Production") + .ConfigurePrimaryHttpMessageHandler(); + + var serviceProvider = services.BuildServiceProvider(); + + var loggerFactory = serviceProvider.GetService(); + Assert.NotNull(loggerFactory); + + var prodClient = serviceProvider.GetRequiredService().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(); + services.AddSingleton(sink); + services.AddSingleton(); + + services.AddLogging(b => b.SetMinimumLevel(LogLevel.Trace)); + services.AddSingleton(sp => sp.GetRequiredService()); + services.AddHttpClient("TestLoggerProvider") + .ConfigurePrimaryHttpMessageHandler() + .RemoveAllLoggers(); + + services.AddHttpClient("Production") + .ConfigurePrimaryHttpMessageHandler(); + + var serviceProvider = services.BuildServiceProvider(); + + var httpClientFactory = (DefaultHttpClientFactory)serviceProvider.GetRequiredService(); + 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; } -- GitLab