HttpClientFactory doesn't clean up after itself

[ItsVeryWindy]

Description

Recently I ran into an issue running tests using dotnet test that it would crash without any obvious reason.
Running my tests also showed memory would steadily increase over time whilst they were being run which indicated the presence of a memory leak.
Analysing the memory dump there were 1000s of timers holding on to objects that I would've expected to be disposed of all centered around ActiveHandlerTrackingEntry.

Reproduction Steps

Judging by the code, I'd say you could just get away with a for loop that creates a service collection, adds the http client factory, creates a service provider and then create a dozen or so http clients with it.

Expected behavior

When the service provider it's associated with is disposed of, all resources the http client factory is associated with should be disposed of and freed up, including any timers that it creates.

Actual behavior

Timers still hang around in the background, long after that instance of the http client factory is no longer in use. Which eventually consumes all available resources.

Regression?

No response

Known Workarounds

When running the tests ensuring the handler lifetime is set to infinite effectively bypasses the handler lifetime logic that creates the timers. Which stops the crashes that I was experiencing.

Configuration

Running .net 8.
MacOS and Linux, ARM64 and x64.
I don't think the configuration matters.

Other information

No response

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

[julealgon]

@CarnaViire is this all due to lack of custom lifetime scope support in Microsoft DI? That's what this sounds like to me...

If the HttpMessageHandler pooling was implemented within a custom lifetime, the lifetime scope would be disposed with the container which would naturally trigger disposal of anything created inside it. I assume this is handled today in an "ad-hoc manner" and that's one of the reasons why it opens the door for these problems.

[CarnaViire]

I will investigate

[CarnaViire]

My investigation has show that the factory resources are not leaking, they are eventually cleaned up. Yes, it doesn't happen right away upon container disposal, but it happens after all the handlers expire (dependent on HandlerLifetime value) plus all the HttpClients and anything that could be holding onto them are garbage collected, plus the clean up timer fired one last time after the GC. Clean up starts every 10s after the first handler expires (by default 2 min).

Here is the code I used for the verification, in addition to the loop that creates SP -- gets HttpClient -- disposes SP, I've added a manual trigger of GC and a wait for a specified period of time. The period of time is just a bit longer than (serviceLifetime + cleanup timer interval) value.

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

namespace _113494
{
    class Program
    {
        static async Task Main(string[] args)
        {
            for (int i = 0; i < 10; i++)
            {
                var services = new ServiceCollection();
                services.AddLogging(builder =>
                {
                    builder.AddConsole().SetMinimumLevel(LogLevel.Trace);
                });

                services.AddScoped<DisposableService>();
                services.AddTransient<TrackingHandler>();

                services.AddHttpClient("TestClient")
                        .AddHttpMessageHandler<TrackingHandler>()
                        .RemoveAllLoggers()
                        .SetHandlerLifetime(TimeSpan.FromSeconds(1)); // Set a short lifetime to force handler to expire quickly.

                using var serviceProvider = services.BuildServiceProvider();
                var httpClientFactory = serviceProvider.GetRequiredService<IHttpClientFactory>();
                var client = httpClientFactory.CreateClient("TestClient");
                Console.WriteLine($"Iteration {i + 1}: HttpClient acquired");

                try
                {
                    _ = await client.GetAsync("https://example.com");
                }
                catch (Exception)
                {
                    // ignore
                }
            }

            Console.WriteLine("Waiting for handlers to expire (lifetime = 1s)...");
            await Task.Delay(TimeSpan.FromSeconds(2));

            Console.WriteLine("Forcing garbage collection... collecting HttpClients to enable expired handler cleanup");
            GC.Collect();
            GC.WaitForPendingFinalizers();
            Console.WriteLine("GC finished");

            Console.WriteLine("Waiting for the cleanup timer to fire (every 10s)...");
            await Task.Delay(TimeSpan.FromSeconds(15));
            Console.WriteLine("15s wait completed");

            // Output disposal statistics
            DisposableService.PrintStats();
            TrackingHandler.PrintStats();

            Console.WriteLine("Press any key to exit...");
            Console.ReadKey();
        }
    }
    public class DisposableService : IDisposable
    {
        private static int s_ctorCount;
        private static int s_disposeCount;
        public string DebugId { get; } = $"{nameof(DisposableService)}#{Interlocked.Increment(ref s_ctorCount)}";

        private bool _disposed;

        public DisposableService()
        {
            Console.WriteLine($"{DebugId} created");
        }

        private void Dispose(bool disposing)
        {
            if (_disposed)
            {
                return;
            }
            _disposed = true;

            Interlocked.Increment(ref s_disposeCount);
            Console.WriteLine(disposing ? $"{DebugId} disposed" : $"{DebugId} finalized without disposing");
        }

        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }

        ~DisposableService()
        {
            Dispose(false);
        }

        public static void PrintStats()
        {
            Console.WriteLine($"{nameof(DisposableService)} instances created: {s_ctorCount}, disposed: {s_disposeCount}");
        }
    }

    public class TrackingHandler : DelegatingHandler
    {
        private static int s_ctorCount;
        private static int s_disposeCount;
        public int Id { get; } = Interlocked.Increment(ref s_ctorCount);
        public string DebugId => $"{nameof(TrackingHandler)}#{Id}";

        private readonly DisposableService _service;
        private bool _disposed;

        public TrackingHandler(DisposableService service)
        {
            _service = service;
            Console.WriteLine($"{DebugId} created with {_service.DebugId}");
        }

        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
            => await base.SendAsync(request, cancellationToken);

        protected override void Dispose(bool disposing)
        {
            if (_disposed)
            {
                return;
            }
            _disposed = true;

            Interlocked.Increment(ref s_disposeCount);
            Console.WriteLine(disposing ? $"{DebugId} disposed" : $"{DebugId} finalized without disposing");
            base.Dispose(disposing);
        }

        public static void PrintStats()
        {
            Console.WriteLine($"{nameof(TrackingHandler)} instances created: {s_ctorCount}, disposed: {s_disposeCount}");
        }
    }
}

Output that shows all the disposables being cleaned up:

➜ 113494  dotnet run
DisposableService#1 created
TrackingHandler#1 created with DisposableService#1
Iteration 1: HttpClient acquired
DisposableService#2 created
TrackingHandler#2 created with DisposableService#2
Iteration 2: HttpClient acquired
DisposableService#3 created
TrackingHandler#3 created with DisposableService#3
Iteration 3: HttpClient acquired
DisposableService#4 created
TrackingHandler#4 created with DisposableService#4
Iteration 4: HttpClient acquired
DisposableService#5 created
TrackingHandler#5 created with DisposableService#5
Iteration 5: HttpClient acquired
DisposableService#6 created
TrackingHandler#6 created with DisposableService#6
Iteration 6: HttpClient acquired
DisposableService#7 created
TrackingHandler#7 created with DisposableService#7
Iteration 7: HttpClient acquired
DisposableService#8 created
TrackingHandler#8 created with DisposableService#8
Iteration 8: HttpClient acquired
DisposableService#9 created
TrackingHandler#9 created with DisposableService#9
Iteration 9: HttpClient acquired
DisposableService#10 created
TrackingHandler#10 created with DisposableService#10
Iteration 10: HttpClient acquired
Waiting for handlers to expire (lifetime = 1s)...
Forcing garbage collection... collecting HttpClients to enable expired handler cleanup
GC finished
Waiting for the cleanup timer to fire (every 10s)...
TrackingHandler#1 disposed
DisposableService#1 disposed
TrackingHandler#2 disposed
DisposableService#2 disposed
TrackingHandler#3 disposed
DisposableService#3 disposed
TrackingHandler#4 disposed
DisposableService#4 disposed
TrackingHandler#5 disposed
DisposableService#5 disposed
TrackingHandler#6 disposed
DisposableService#6 disposed
TrackingHandler#7 disposed
DisposableService#7 disposed
TrackingHandler#8 disposed
DisposableService#8 disposed
TrackingHandler#9 disposed
DisposableService#9 disposed
TrackingHandler#10 disposed
DisposableService#10 disposed
15s wait completed
DisposableService instances created: 10, disposed: 10
TrackingHandler instances created: 10, disposed: 10
Press any key to exit...

The timers are also eventually properly garbage collected (verified by a heap dump)

Even though I don't consider it a bug, this is something we might consider to optimize in the future, though I an not sure how many users would need to create and dispose the whole providers in a loop...

@ItsVeryWindy can you please check out the example and let me know whether this is a scenario you had in mind, and if yes, then what is the difference. Thanks!

[ItsVeryWindy]

Thanks for looking into it 👍

The loop was more just to demonstrate how it could be triggered. As mentioned above, we're running tests, in our case we're running a suite of tests, lets say approximately 3000 or so, each one of these tests boots up a AspNetCore TestServer and disposes it at the end of the test, each one will create approximately 20 or so different clients/lifetimes. So over the lifespan of the tests 60000 lifetimes will be created.

I don't know if it's specific to our setup or ootb but somewhere in the handlers there's something hanging on to the Host itself, but I guess the important thing is that whilst the timers exist it prevents any resources that those handlers are using from being garbage collected.

Depending on the project, most of test suites are actually fairly quick and can complete in less than two minutes.

[CarnaViire]

whilst the timers exist it prevents any resources that those handlers are using from being garbage collected

It does not -- well, they eventually let them go 😅 It's a bit more complex because there are different timers.

1. The expiration timers (their callbacks, to be precise) do hold onto the related handlers for the duration of the handler lifetime. These are started on every handler creation, and they fire only once, after which they are disposed.

Timings:

T_c    ----/ h      /----> T_e = T_c + h
handler    /handler /      handler 
created    /lifetime/      expired

2. After the expiration, if it is a first expired handler in the queue, the cleanup timer is started. The cleanup timer never holds on the handlers, only on their weak references -- more specifically, the cleanup timer is waiting for the handlers to be garbage collected. The following regular cleanup is scheduled only if there's anything left to clean.

Timings:

                                                                                      (loop) <--+
                                                                                                |
T_s = T_e ----/ d      /----> T + d    ==={ if ?      }----/I = 10s /----> T_n = T_s + d + I ---+
cleanup       /cleanup /      cleanup     {any expired}    /cleanup /      next
started       /duration/      completed   {is pending }    /interval/      cleanup
                                            |
                                            +--{ else }-----------------------------------------> (exit)

@ItsVeryWindy I suspect that you don't change the handler lifetimes, so they remain the default 2 minutes? If so, it explains why all the handlers are still alive during the tests (that are under 2 min in total).

Can you try setting all the handler lifetimes to 1s (minimal allowed value)? Then the handlers are expected to be cleaned up within 10-20s after GC being triggered, as I have shown in the snippet above. You don't have to trigger GC manually, it should happen automatically, but you can try that as well to see if that will make the memory consumption pattern more predictable.

P.S.: you can set up the handler lifetime as a default setting via ConfigureHttpClientDefaults, so that you won't have to touch every single AddHttpClient:

services.ConfigureHttpClientDefaults(b => b.SetHandlerLifetime(TimeSpan.FromSeconds(1)));

[Maximys]

@CarnaViire , if I correctly understand, IHttpClientFactory implemented by DefaultHttpClientFactory and it have static field _cleanupCallback , which use very intresting method CleanupTimer_Tick().
I think, we can inherit DefaultHttpClientFactory from IDisposable and reuse logic from CleanupTimer_Tick . What do you think about it? I can try to make this changes

[CarnaViire]

@Maximys in general, yes, and I will be more than happy to guide you through if you wish to contribute!

As I mentioned above, there are 2 kinds of timers associated with 2 types of handler entries (active and expired), so we will just need to reuse the logic of stopping the timer and disposing the handler(s) together with the handler scope(s) for both of them.