From f372f4d39a31e08aae5e784baab928f272699660 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Wed, 26 Jul 2023 22:43:04 +0100 Subject: [PATCH 1/4] Remove dependency on ILoggerFactory --- .../src/DefaultHttpClientFactory.cs | 65 ++--------------- .../LoggingHttpMessageHandlerBuilderFilter.cs | 14 ++-- .../src/Logging/NetEventSource.cs | 70 +++++++++++++++++++ .../DefaultHttpClientFactoryTest.cs | 27 ++++--- 4 files changed, 94 insertions(+), 82 deletions(-) create mode 100644 src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs diff --git a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs index ec14a145c0394a..e48108e726529a 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs @@ -18,7 +18,6 @@ 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; @@ -61,13 +60,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 +73,6 @@ public DefaultHttpClientFactory( _optionsMonitor = optionsMonitor; _filters = filters.ToArray(); - _logger = loggerFactory.CreateLogger(); - // case-sensitive because named options is. _activeHandlers = new ConcurrentDictionary>(StringComparer.Ordinal); _entryFactory = (name) => @@ -204,7 +199,7 @@ internal void ExpiryTimer_Tick(object? state) var expired = new ExpiredHandlerTrackingEntry(active); _expiredHandlers.Enqueue(expired); - Log.HandlerExpired(_logger, active.Name, active.Lifetime); + if (NetEventSource.Log.IsEnabled()) NetEventSource.HandlerExpired(active.Name, active.Lifetime); StartCleanupTimer(); } @@ -262,7 +257,7 @@ internal void CleanupTimer_Tick() try { int initialCount = _expiredHandlers.Count; - Log.CleanupCycleStart(_logger, initialCount); + if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupCycleStart(initialCount); var stopwatch = ValueStopwatch.StartNew(); @@ -283,7 +278,7 @@ internal void CleanupTimer_Tick() } catch (Exception ex) { - Log.CleanupItemFailed(_logger, entry.Name, ex); + if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupItemFailed(entry.Name, ex); } } else @@ -294,7 +289,7 @@ internal void CleanupTimer_Tick() } } - Log.CleanupCycleEnd(_logger, stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count); + if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupCycleEnd(stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count); } finally { @@ -307,57 +302,5 @@ internal void CleanupTimer_Tick() StartCleanupTimer(); } } - - private static class Log - { - public static class EventIds - { - public static readonly EventId CleanupCycleStart = new EventId(100, "CleanupCycleStart"); - public static readonly EventId CleanupCycleEnd = new EventId(101, "CleanupCycleEnd"); - public static readonly EventId CleanupItemFailed = new EventId(102, "CleanupItemFailed"); - public static readonly EventId HandlerExpired = new EventId(103, "HandlerExpired"); - } - - private static readonly Action _cleanupCycleStart = LoggerMessage.Define( - LogLevel.Debug, - EventIds.CleanupCycleStart, - "Starting HttpMessageHandler cleanup cycle with {InitialCount} items"); - - private static readonly Action _cleanupCycleEnd = LoggerMessage.Define( - LogLevel.Debug, - EventIds.CleanupCycleEnd, - "Ending HttpMessageHandler cleanup cycle after {ElapsedMilliseconds}ms - processed: {DisposedCount} items - remaining: {RemainingItems} items"); - - private static readonly Action _cleanupItemFailed = LoggerMessage.Define( - LogLevel.Error, - EventIds.CleanupItemFailed, - "HttpMessageHandler.Dispose() threw an unhandled exception for client: '{ClientName}'"); - - private static readonly Action _handlerExpired = LoggerMessage.Define( - LogLevel.Debug, - EventIds.HandlerExpired, - "HttpMessageHandler expired after {HandlerLifetime}ms for client '{ClientName}'"); - - - public static void CleanupCycleStart(ILogger logger, int initialCount) - { - _cleanupCycleStart(logger, initialCount, null); - } - - public static void CleanupCycleEnd(ILogger logger, TimeSpan duration, int disposedCount, int finalCount) - { - _cleanupCycleEnd(logger, duration.TotalMilliseconds, disposedCount, finalCount, null); - } - - public static void CleanupItemFailed(ILogger logger, string clientName, Exception exception) - { - _cleanupItemFailed(logger, clientName, exception); - } - - public static void HandlerExpired(ILogger logger, string clientName, TimeSpan lifetime) - { - _handlerExpired(logger, lifetime.TotalMilliseconds, clientName, null); - } - } } } diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs index 9b982bbf3cc5b7..5b9d30dd85c31f 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Http.Logging; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -11,15 +12,16 @@ namespace Microsoft.Extensions.Http // Internal so we can change the requirements without breaking changes. internal sealed class LoggingHttpMessageHandlerBuilderFilter : IHttpMessageHandlerBuilderFilter { - private readonly ILoggerFactory _loggerFactory; + private readonly IServiceProvider _serviceProvider; private readonly IOptionsMonitor _optionsMonitor; + private ILoggerFactory LoggerFactory => _serviceProvider.GetRequiredService(); - 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 +44,8 @@ public Action Configure(Action + WriteEvent(CleanupCycleStartEventId, message); + + [NonEvent] + public static void CleanupCycleEnd(TimeSpan duration, int disposedCount, int finalCount) + { + Debug.Assert(Log.IsEnabled()); + Log.CleanupCycleEnd($"Ending HttpMessageHandler cleanup cycle after {duration.TotalMilliseconds}ms - processed: {disposedCount} items - remaining: {finalCount} items"); + } + + [Event(CleanupCycleEndEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] + public void CleanupCycleEnd(string message) => + WriteEvent(CleanupCycleEndEventId, message); + + [NonEvent] + public static void CleanupItemFailed(string clientName, Exception exception) + { + Debug.Assert(Log.IsEnabled()); + Log.CleanupItemFailed(clientName, exception.ToString(), $"HttpMessageHandler.Dispose() threw an unhandled exception for client: '{clientName}'"); + } + + [Event(CleanupItemFailedEventId, Keywords = Keywords.Debug, Level = EventLevel.Error)] + public void CleanupItemFailed(string clientName, string exception, string message) => + WriteEvent(CleanupItemFailedEventId, clientName, exception, message); + + [NonEvent] + public static void HandlerExpired(string clientName, TimeSpan lifetime) + { + Debug.Assert(Log.IsEnabled()); + Log.HandlerExpired(clientName, $"HttpMessageHandler expired after {lifetime} for client '{clientName}'"); + } + + [Event(HandlerExpiredEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] + public void HandlerExpired(string clientName, string message) => + WriteEvent(HandlerExpiredEventId, clientName, message); + } +} diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs index 1b1b8b305e4c8c..4ebd568b07ab74 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs +++ b/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 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); From e203665a63c7d158931d91f8eb00379861602dc6 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Thu, 27 Jul 2023 18:19:52 +0100 Subject: [PATCH 2/4] Add test --- .../src/Logging/NetEventSource.cs | 8 ++--- .../DefaultHttpClientFactoryTest.cs | 34 +++++++++++++++++++ 2 files changed, 38 insertions(+), 4 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs index 5cdca3695169f4..3af5d1a47963fc 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs @@ -31,7 +31,7 @@ public static void CleanupCycleStart(int initialCount) } [Event(CleanupCycleStartEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] - public void CleanupCycleStart(string message) => + private void CleanupCycleStart(string message) => WriteEvent(CleanupCycleStartEventId, message); [NonEvent] @@ -42,7 +42,7 @@ public static void CleanupCycleEnd(TimeSpan duration, int disposedCount, int fin } [Event(CleanupCycleEndEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] - public void CleanupCycleEnd(string message) => + private void CleanupCycleEnd(string message) => WriteEvent(CleanupCycleEndEventId, message); [NonEvent] @@ -53,7 +53,7 @@ public static void CleanupItemFailed(string clientName, Exception exception) } [Event(CleanupItemFailedEventId, Keywords = Keywords.Debug, Level = EventLevel.Error)] - public void CleanupItemFailed(string clientName, string exception, string message) => + private void CleanupItemFailed(string clientName, string exception, string message) => WriteEvent(CleanupItemFailedEventId, clientName, exception, message); [NonEvent] @@ -64,7 +64,7 @@ public static void HandlerExpired(string clientName, TimeSpan lifetime) } [Event(HandlerExpiredEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] - public void HandlerExpired(string clientName, string message) => + private void HandlerExpired(string clientName, string message) => WriteEvent(HandlerExpiredEventId, clientName, message); } } diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs index 4ebd568b07ab74..15afd2774e9127 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs @@ -387,6 +387,40 @@ public async Task Factory_CleanupCycle_DisposesEligibleHandler() Assert.False(factory.CleanupTimerStarted.IsSet, "Cleanup timer not started"); } + [Fact] + public void LoggerFactoryWithHttpClientFactory_NoCircularDependency() + { + var services = new ServiceCollection(); + + services.AddHttpClient("TestLoggerProvider").RemoveAllLoggers(); + + services.AddLogging(builder => builder.Services.AddSingleton()); + + using var serviceProvider = services.BuildServiceProvider(); + + var loggerFactory = serviceProvider.GetService(); + } + + private sealed class TestLoggerProvider : ILoggerProvider + { + private readonly HttpClient _httpClient; + + public TestLoggerProvider(IHttpClientFactory httpClientFactory) + { + _httpClient = httpClientFactory.CreateClient("TestLoggerProvider"); + } + + public ILogger CreateLogger(string categoryName) + { + return NullLogger.Instance; + } + + public void Dispose() + { + _httpClient.Dispose(); + } + } + // Separate to avoid the HttpClient getting its lifetime extended by // the state machine of the test. [MethodImpl(MethodImplOptions.NoInlining)] From eca759da89756568b75965244767ab95f25fddfc Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Tue, 1 Aug 2023 23:54:25 +0100 Subject: [PATCH 3/4] PR feedback & add more tests --- .../src/DefaultHttpClientFactory.cs | 65 ++++++++++++++- .../LoggingHttpMessageHandlerBuilderFilter.cs | 11 +-- .../src/Logging/NetEventSource.cs | 70 ---------------- .../DefaultHttpClientFactoryTest.cs | 34 -------- .../Logging/HttpClientLoggerTest.cs | 82 +++++++++++++++++++ 5 files changed, 149 insertions(+), 113 deletions(-) delete mode 100644 src/libraries/Microsoft.Extensions.Http/src/Logging/NetEventSource.cs diff --git a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs index e48108e726529a..e63ba64326a9c1 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs @@ -23,6 +23,7 @@ internal class DefaultHttpClientFactory : IHttpClientFactory, IHttpMessageHandle 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: @@ -88,6 +89,10 @@ public DefaultHttpClientFactory( _cleanupTimerLock = new object(); _cleanupActiveLock = new object(); + + _logger = new Lazy( + () => _services.GetRequiredService().CreateLogger(), + LazyThreadSafetyMode.ExecutionAndPublication); } public HttpClient CreateClient(string name) @@ -199,7 +204,7 @@ internal void ExpiryTimer_Tick(object? state) var expired = new ExpiredHandlerTrackingEntry(active); _expiredHandlers.Enqueue(expired); - if (NetEventSource.Log.IsEnabled()) NetEventSource.HandlerExpired(active.Name, active.Lifetime); + Log.HandlerExpired(_logger.Value, active.Name, active.Lifetime); StartCleanupTimer(); } @@ -257,7 +262,7 @@ internal void CleanupTimer_Tick() try { int initialCount = _expiredHandlers.Count; - if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupCycleStart(initialCount); + Log.CleanupCycleStart(_logger.Value, initialCount); var stopwatch = ValueStopwatch.StartNew(); @@ -278,7 +283,7 @@ internal void CleanupTimer_Tick() } catch (Exception ex) { - if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupItemFailed(entry.Name, ex); + Log.CleanupItemFailed(_logger.Value, entry.Name, ex); } } else @@ -289,7 +294,7 @@ internal void CleanupTimer_Tick() } } - if (NetEventSource.Log.IsEnabled()) NetEventSource.CleanupCycleEnd(stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count); + Log.CleanupCycleEnd(_logger.Value, stopwatch.GetElapsedTime(), disposedCount, _expiredHandlers.Count); } finally { @@ -302,5 +307,57 @@ internal void CleanupTimer_Tick() StartCleanupTimer(); } } + + private static class Log + { + public static class EventIds + { + public static readonly EventId CleanupCycleStart = new EventId(100, "CleanupCycleStart"); + public static readonly EventId CleanupCycleEnd = new EventId(101, "CleanupCycleEnd"); + public static readonly EventId CleanupItemFailed = new EventId(102, "CleanupItemFailed"); + public static readonly EventId HandlerExpired = new EventId(103, "HandlerExpired"); + } + + private static readonly Action _cleanupCycleStart = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CleanupCycleStart, + "Starting HttpMessageHandler cleanup cycle with {InitialCount} items"); + + private static readonly Action _cleanupCycleEnd = LoggerMessage.Define( + LogLevel.Debug, + EventIds.CleanupCycleEnd, + "Ending HttpMessageHandler cleanup cycle after {ElapsedMilliseconds}ms - processed: {DisposedCount} items - remaining: {RemainingItems} items"); + + private static readonly Action _cleanupItemFailed = LoggerMessage.Define( + LogLevel.Error, + EventIds.CleanupItemFailed, + "HttpMessageHandler.Dispose() threw an unhandled exception for client: '{ClientName}'"); + + private static readonly Action _handlerExpired = LoggerMessage.Define( + LogLevel.Debug, + EventIds.HandlerExpired, + "HttpMessageHandler expired after {HandlerLifetime}ms for client '{ClientName}'"); + + + public static void CleanupCycleStart(ILogger logger, int initialCount) + { + _cleanupCycleStart(logger, initialCount, null); + } + + public static void CleanupCycleEnd(ILogger logger, TimeSpan duration, int disposedCount, int finalCount) + { + _cleanupCycleEnd(logger, duration.TotalMilliseconds, disposedCount, finalCount, null); + } + + public static void CleanupItemFailed(ILogger logger, string clientName, Exception exception) + { + _cleanupItemFailed(logger, clientName, exception); + } + + public static void HandlerExpired(ILogger logger, string clientName, TimeSpan lifetime) + { + _handlerExpired(logger, lifetime.TotalMilliseconds, clientName, null); + } + } } } diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs index 5b9d30dd85c31f..37684b940987dc 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs @@ -2,6 +2,7 @@ // 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; @@ -12,17 +13,17 @@ namespace Microsoft.Extensions.Http // Internal so we can change the requirements without breaking changes. internal sealed class LoggingHttpMessageHandlerBuilderFilter : IHttpMessageHandlerBuilderFilter { - private readonly IServiceProvider _serviceProvider; + private readonly Lazy _loggerFactory; private readonly IOptionsMonitor _optionsMonitor; - private ILoggerFactory LoggerFactory => _serviceProvider.GetRequiredService(); public LoggingHttpMessageHandlerBuilderFilter(IServiceProvider serviceProvider, IOptionsMonitor optionsMonitor) { ThrowHelper.ThrowIfNull(serviceProvider); ThrowHelper.ThrowIfNull(optionsMonitor); - _serviceProvider = serviceProvider; _optionsMonitor = optionsMonitor; + + _loggerFactory = new Lazy(serviceProvider.GetRequiredService, LazyThreadSafetyMode.PublicationOnly); } public Action Configure(Action next) @@ -44,8 +45,8 @@ public Action Configure(Action - WriteEvent(CleanupCycleStartEventId, message); - - [NonEvent] - public static void CleanupCycleEnd(TimeSpan duration, int disposedCount, int finalCount) - { - Debug.Assert(Log.IsEnabled()); - Log.CleanupCycleEnd($"Ending HttpMessageHandler cleanup cycle after {duration.TotalMilliseconds}ms - processed: {disposedCount} items - remaining: {finalCount} items"); - } - - [Event(CleanupCycleEndEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] - private void CleanupCycleEnd(string message) => - WriteEvent(CleanupCycleEndEventId, message); - - [NonEvent] - public static void CleanupItemFailed(string clientName, Exception exception) - { - Debug.Assert(Log.IsEnabled()); - Log.CleanupItemFailed(clientName, exception.ToString(), $"HttpMessageHandler.Dispose() threw an unhandled exception for client: '{clientName}'"); - } - - [Event(CleanupItemFailedEventId, Keywords = Keywords.Debug, Level = EventLevel.Error)] - private void CleanupItemFailed(string clientName, string exception, string message) => - WriteEvent(CleanupItemFailedEventId, clientName, exception, message); - - [NonEvent] - public static void HandlerExpired(string clientName, TimeSpan lifetime) - { - Debug.Assert(Log.IsEnabled()); - Log.HandlerExpired(clientName, $"HttpMessageHandler expired after {lifetime} for client '{clientName}'"); - } - - [Event(HandlerExpiredEventId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)] - private void HandlerExpired(string clientName, string message) => - WriteEvent(HandlerExpiredEventId, clientName, message); - } -} diff --git a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs index 15afd2774e9127..4ebd568b07ab74 100644 --- a/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs +++ b/src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/DefaultHttpClientFactoryTest.cs @@ -387,40 +387,6 @@ public async Task Factory_CleanupCycle_DisposesEligibleHandler() Assert.False(factory.CleanupTimerStarted.IsSet, "Cleanup timer not started"); } - [Fact] - public void LoggerFactoryWithHttpClientFactory_NoCircularDependency() - { - var services = new ServiceCollection(); - - services.AddHttpClient("TestLoggerProvider").RemoveAllLoggers(); - - services.AddLogging(builder => builder.Services.AddSingleton()); - - using var serviceProvider = services.BuildServiceProvider(); - - var loggerFactory = serviceProvider.GetService(); - } - - private sealed class TestLoggerProvider : ILoggerProvider - { - private readonly HttpClient _httpClient; - - public TestLoggerProvider(IHttpClientFactory httpClientFactory) - { - _httpClient = httpClientFactory.CreateClient("TestLoggerProvider"); - } - - public ILogger CreateLogger(string categoryName) - { - return NullLogger.Instance; - } - - public void Dispose() - { - _httpClient.Dispose(); - } - } - // Separate to avoid the HttpClient getting its lifetime extended by // the state machine of the test. [MethodImpl(MethodImplOptions.NoInlining)] 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 0ba5611ed29879..e7b3df91dd6025 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,88 @@ 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() + .SetHandlerLifetime(TimeSpan.FromSeconds(1)); + + var serviceProvider = services.BuildServiceProvider(); + + var prodClient = serviceProvider.GetRequiredService().CreateClient("Production"); + + _ = await prodClient.GetAsync(Url); + + await Task.Delay(TimeSpan.FromSeconds(3)); + + Assert.InRange(sink.Writes.Count(w => w.LoggerName == typeof(DefaultHttpClientFactory).FullName), 1, 4); + } + + 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; } From aab7c2d8b0d2dced6e6f95145edcb1d5d3ba19f6 Mon Sep 17 00:00:00 2001 From: Natalia Kondratyeva Date: Wed, 2 Aug 2023 19:00:16 +0100 Subject: [PATCH 4/4] PR feedback --- .../src/DefaultHttpClientFactory.cs | 4 ++++ .../LoggingHttpMessageHandlerBuilderFilter.cs | 13 ++++++++----- .../Logging/HttpClientLoggerTest.cs | 11 ++++++----- 3 files changed, 18 insertions(+), 10 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs index e63ba64326a9c1..e4a84960b9f409 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs @@ -90,6 +90,10 @@ public DefaultHttpClientFactory( _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); diff --git a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs index 37684b940987dc..a10a1f831e8835 100644 --- a/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs +++ b/src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs @@ -13,7 +13,11 @@ namespace Microsoft.Extensions.Http // Internal so we can change the requirements without breaking changes. internal sealed class LoggingHttpMessageHandlerBuilderFilter : IHttpMessageHandlerBuilderFilter { - private readonly Lazy _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(IServiceProvider serviceProvider, IOptionsMonitor optionsMonitor) @@ -21,9 +25,8 @@ public LoggingHttpMessageHandlerBuilderFilter(IServiceProvider serviceProvider, ThrowHelper.ThrowIfNull(serviceProvider); ThrowHelper.ThrowIfNull(optionsMonitor); + _serviceProvider = serviceProvider; _optionsMonitor = optionsMonitor; - - _loggerFactory = new Lazy(serviceProvider.GetRequiredService, LazyThreadSafetyMode.PublicationOnly); } public Action Configure(Action next) @@ -45,8 +48,8 @@ public Action Configure(Action() - .SetHandlerLifetime(TimeSpan.FromSeconds(1)); + .ConfigurePrimaryHttpMessageHandler(); var serviceProvider = services.BuildServiceProvider(); - var prodClient = serviceProvider.GetRequiredService().CreateClient("Production"); + var httpClientFactory = (DefaultHttpClientFactory)serviceProvider.GetRequiredService(); + var prodClient = httpClientFactory.CreateClient("Production"); _ = await prodClient.GetAsync(Url); - await Task.Delay(TimeSpan.FromSeconds(3)); + 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.InRange(sink.Writes.Count(w => w.LoggerName == typeof(DefaultHttpClientFactory).FullName), 1, 4); + Assert.Equal(2, sink.Writes.Count(w => w.LoggerName == typeof(DefaultHttpClientFactory).FullName)); } private sealed class TestLoggerProvider : ILoggerProvider