Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[HttpClientFactory] Remove dependency on ILoggerFactory #89531

Merged
merged 4 commits into from
Aug 9, 2023
Merged

[HttpClientFactory] Remove dependency on ILoggerFactory #89531

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
f372f4d
Remove dependency on ILoggerFactory
CarnaViire Jul 26, 2023
e203665
Add test
CarnaViire Jul 27, 2023
eca759d
PR feedback & add more tests
CarnaViire Aug 1, 2023
aab7c2d
PR feedback
CarnaViire Aug 2, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 9 additions & 9 deletions src/libraries/Microsoft.Extensions.Http/src/DefaultHttpClientFactory.cs
View file
Open in desktop
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 @@ public DefaultHttpClientFactory(
_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,10 @@ public DefaultHttpClientFactory(

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

_logger = new Lazy<ILogger>(
CarnaViire marked this conversation as resolved.
Show resolved Hide resolved
() => _services.GetRequiredService<ILoggerFactory>().CreateLogger<DefaultHttpClientFactory>(),
LazyThreadSafetyMode.ExecutionAndPublication);
}

public HttpClient CreateClient(string name)
Expand Down Expand Up @@ -204,7 +204,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 +262,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 +283,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 +294,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
15 changes: 9 additions & 6 deletions ...libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandlerBuilderFilter.cs
View file
Open in desktop
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,16 +13,17 @@ 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 Lazy<ILoggerFactory> _loggerFactory;
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;
_optionsMonitor = optionsMonitor;

_loggerFactory = new Lazy<ILoggerFactory>(serviceProvider.GetRequiredService<ILoggerFactory>, LazyThreadSafetyMode.PublicationOnly);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add a comment explaining why.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why PublicationOnly in this lazy and ExecutionAndPublication in DefaultHttpClientFactory lazy?

Copy link
Member Author

@CarnaViire CarnaViire Aug 2, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess we don't need to guard this one at all, given that DI should already guard creation of a singleton.

DefaultHttpClientFactory lazy is creating ILogger, which is most possibly a new instance every time CreateLogger is invoked, so I want to avoid unnecessary allocations.

}

public Action<HttpMessageHandlerBuilder> Configure(Action<HttpMessageHandlerBuilder> next)
Expand All @@ -42,8 +45,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.Value.CreateLogger($"System.Net.Http.HttpClient.{loggerName}.LogicalHandler");
ILogger innerLogger = _loggerFactory.Value.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
Open in desktop
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
82 changes: 82 additions & 0 deletions ...oft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/HttpClientLoggerTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<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>()
.SetHandlerLifetime(TimeSpan.FromSeconds(1));

var serviceProvider = services.BuildServiceProvider();

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

_ = await prodClient.GetAsync(Url);

await Task.Delay(TimeSpan.FromSeconds(3));
CarnaViire marked this conversation as resolved.
Show resolved Hide resolved

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