[HttpClientFactory] Remove dependency on ILoggerFactory (#89531)

* Remove dependency on ILoggerFactory

* Add test

* PR feedback & add more tests

* PR feedback

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<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:
@@ -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);
 
@@ -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) =>
@@ -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)
@@ -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
             {

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<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;
         }
 
@@ -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));

src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs

@@ -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>();
@@ -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<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);

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<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; }