ObjectDisposedException intermittently crashes test process from DefaultHttpClientFactory.ExpiryTimer_Tick #90386

martincostello · 2023-08-11T10:56:48Z

Description

I have some repositories that I've hooked up to ingest the daily builds of .NET 8. In this morning's update I have two repos (one public, one private) where the existing test suite is starting to fail due to this error:

The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
   at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.<>c.<.cctor>b__22_0(Object s)
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.TimerQueue.FireNextTimers()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

It appears that something running in the background for HttpClientFactory is trying to use the service provider after it's torn down and throwing an exception. This doesn't seem to happen 100% of the time though based on the attempts for this workflow run where macOS passes every time, Windows and Linux fail twice, and then all three pass.

Edit: Fails on macOS too in a third repo

Reproduction Steps

Clone martincostello/alexa-london-travel-site@74309e7 and run build.ps1 in the root of the repository.

Expected behavior

The tests pass.

Actual behavior

The tests sometimes crashes with the above error on Linux and Windows.

Regression?

Yes.

Known Workarounds

No response

Configuration

.NET SDK 8.0.100-rc.1.23410.12
Microsoft.AspNetCore.* 8.0.0-rc.1.23410.15

Other information

Maybe have been introduced by #89531.

The text was updated successfully, but these errors were encountered:

ghost · 2023-08-11T10:56:56Z

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

Issue Details

Description

I have some repositories that I've hooked up to ingest the daily builds of .NET 8. In this morning's update I have two repos (one public, one private) where the existing test suite is starting to fail due to this error:

The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
   at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.<>c.<.cctor>b__22_0(Object s)
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.TimerQueue.FireNextTimers()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

It appears that something running in the background for HttpClientFactory is trying to use the service provider after it's torn down and throwing an exception. This doesn't seem to happen 100% of the time though based on the attempts for this workflow run where macOS passes every time, Windows and Linux fail twice, and then all three pass.

Reproduction Steps

Clone martincostello/alexa-london-travel-site@74309e7 and run build.ps1 in the root of the repository.

Expected behavior

The tests pass.

Actual behavior

The tests sometimes crashes with the above error on Linux and Windows.

Regression?

Yes.

Known Workarounds

No response

Configuration

.NET SDK 8.0.100-rc.1.23410.12
Microsoft.AspNetCore.* 8.0.0-rc.1.23410.15

Other information

Maybe have been introduced by #89531.

Author:	martincostello
Assignees:	-
Labels:	`untriaged`, `area-Extensions-DependencyInjection`
Milestone:	-

martincostello · 2023-08-11T11:05:59Z

Yeah, looks like it's because of this: https://github.com/dotnet/runtime/pull/89531/files#diff-940dba6ffc5ae548fca7105241869c1a78442c04b968f129ce645407022e83cbR98

/cc @CarnaViire

CarnaViire · 2023-08-11T11:37:10Z

@martincostello can you please point me to the specific test that triggers the exception? Would it be possible to you to create a standalone minimal repro?

martincostello · 2023-08-11T11:41:39Z

Sorry I don't know specifically which one it is as it seems to be failing due to a background thread sometime after some test happens to do an HTTP call through HttpClient (and lots of the tests do that) - it's likely one of the "integration" tests that run with an HTTP server which for the first project I've linked to are here.

I can try making a standalone repro, but if you need that I'm not going to be able to have the time to do that until next week.

martincostello · 2023-08-11T11:44:52Z

Based on the fact all the tests themselves are passing seems like you just need to run "enough" tests for the background timer to fire to do some cleanup after the HTTP server is torn down at the end of the test run, which then kills dotnet test due to the unhandled exception.

CarnaViire · 2023-08-11T11:45:48Z

I can try making a standalone repro, but if you need that I'm not going to be able to have the time to do that until next week.

No worries. I think I know what happened -- DefaultHttpClientFactory's timer is not disposed when it should be, so it ended up firing when everything including ServiceProvider is already torn down. This was present before, but became prominent since the ILogger object is now Lazy.

ghost · 2023-08-11T11:51:25Z

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

Issue Details

Description

I have some repositories that I've hooked up to ingest the daily builds of .NET 8. In this morning's update I have two repos (one public, one private) where the existing test suite is starting to fail due to this error:

The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
   at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.<>c.<.cctor>b__22_0(Object s)
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.TimerQueue.FireNextTimers()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

It appears that something running in the background for HttpClientFactory is trying to use the service provider after it's torn down and throwing an exception. This doesn't seem to happen 100% of the time though based on the attempts for this workflow run where macOS passes every time, Windows and Linux fail twice, and then all three pass.

Edit: Fails on macOS too in a third repo

Reproduction Steps

Clone martincostello/alexa-london-travel-site@74309e7 and run build.ps1 in the root of the repository.

Expected behavior

The tests pass.

Actual behavior

The tests sometimes crashes with the above error on Linux and Windows.

Regression?

Yes.

Known Workarounds

No response

Configuration

.NET SDK 8.0.100-rc.1.23410.12
Microsoft.AspNetCore.* 8.0.0-rc.1.23410.15

Other information

Maybe have been introduced by #89531.

Author:	martincostello
Assignees:	CarnaViire
Labels:	`area-Extensions-DependencyInjection`, `area-Extensions-HttpClientFactory`
Milestone:	8.0.0

ghost · 2023-08-11T11:51:53Z

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

Issue Details

Description

I have some repositories that I've hooked up to ingest the daily builds of .NET 8. In this morning's update I have two repos (one public, one private) where the existing test suite is starting to fail due to this error:

The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
   at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.<>c.<.cctor>b__22_0(Object s)
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.TimerQueue.FireNextTimers()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

It appears that something running in the background for HttpClientFactory is trying to use the service provider after it's torn down and throwing an exception. This doesn't seem to happen 100% of the time though based on the attempts for this workflow run where macOS passes every time, Windows and Linux fail twice, and then all three pass.

Edit: Fails on macOS too in a third repo

Reproduction Steps

Clone martincostello/alexa-london-travel-site@74309e7 and run build.ps1 in the root of the repository.

Expected behavior

The tests pass.

Actual behavior

The tests sometimes crashes with the above error on Linux and Windows.

Regression?

Yes.

Known Workarounds

No response

Configuration

.NET SDK 8.0.100-rc.1.23410.12
Microsoft.AspNetCore.* 8.0.0-rc.1.23410.15

Other information

Maybe have been introduced by #89531.

Author:	martincostello
Assignees:	CarnaViire
Labels:	`area-Extensions-DependencyInjection`, `area-Extensions-HttpClientFactory`
Milestone:	8.0.0

martincostello · 2023-08-21T11:48:09Z

@CarnaViire I'm not sure if this issue has been fully resolved. I'm still experiencing this as of .NET SDK version 8.0.100-rc.2.23420.6.

The stack trace seems to have changed, and I see the error logged multiple times now instead of just once.

The active test run was aborted. Reason: Test host process crashed : Unhandled exception. Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
--- End of stack trace from previous location ---
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
--- End of stack trace from previous location ---
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
--- End of stack trace from previous location ---
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Unhandled exception. System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService(IServiceProvider provider, Type serviceType)
   at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.GetRequiredService[T](IServiceProvider provider)
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.<.ctor>b__14_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
--- End of stack trace from previous location ---
   at System.Lazy`1.CreateValue()
   at Microsoft.Extensions.Http.DefaultHttpClientFactory.ExpiryTimer_Tick(Object state)
   at Microsoft.Extensions.Http.ActiveHandlerTrackingEntry.Timer_Tick()
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()

karelz · 2023-08-29T09:36:06Z

~~@martincostello can you please file a separate issue and link this one if it is still a problem?~~

Never mind, you filed it and it was already closed -- see #90919

karelz · 2023-08-29T09:36:34Z

Fixed in 8.0 (main) in PR #90503.

ghost added untriaged New issue has not been triaged by the area owner area-Extensions-DependencyInjection labels Aug 11, 2023

martincostello mentioned this issue Aug 11, 2023

Update .NET SDK to 8.0.100-rc.1.23410.12 martincostello/alexa-london-travel-site#1856

Merged

CarnaViire self-assigned this Aug 11, 2023

CarnaViire added this to the 8.0.0 milestone Aug 11, 2023

ghost removed the untriaged New issue has not been triaged by the area owner label Aug 11, 2023

CarnaViire added the area-Extensions-HttpClientFactory label Aug 11, 2023

CarnaViire added area-Extensions-HttpClientFactory and removed area-Extensions-HttpClientFactory labels Aug 11, 2023

CarnaViire removed the area-Extensions-DependencyInjection label Aug 11, 2023

CarnaViire mentioned this issue Aug 13, 2023

HttpClientFactory prevent throwing if ILogger couldn't be created #90503

Merged

ghost added the in-pr There is an active PR which will close this issue when it is merged label Aug 13, 2023

CarnaViire closed this as completed in #90503 Aug 14, 2023

ghost removed the in-pr There is an active PR which will close this issue when it is merged label Aug 14, 2023

This was referenced Aug 21, 2023

Update .NET SDK to 8.0.100-rc.2.23420.6 martincostello/dependabot-helper#814

Closed

ObjectDisposedException intermittently crashes test process from DefaultHttpClientFactory.ExpiryTimer_Tick #90919

Closed

karelz added the bug label Aug 29, 2023

ghost locked as resolved and limited conversation to collaborators Sep 28, 2023

ObjectDisposedException intermittently crashes test process from DefaultHttpClientFactory.ExpiryTimer_Tick #90386

ObjectDisposedException intermittently crashes test process from DefaultHttpClientFactory.ExpiryTimer_Tick #90386

Comments

martincostello commented Aug 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

ghost commented Aug 11, 2023

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

Uh oh!

martincostello commented Aug 11, 2023

Uh oh!

CarnaViire commented Aug 11, 2023

Uh oh!

martincostello commented Aug 11, 2023

Uh oh!

martincostello commented Aug 11, 2023

Uh oh!

CarnaViire commented Aug 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ghost commented Aug 11, 2023

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

Uh oh!

ghost commented Aug 11, 2023

Description

Reproduction Steps

Expected behavior

Actual behavior

Regression?

Known Workarounds

Configuration

Other information

Uh oh!

martincostello commented Aug 21, 2023

Uh oh!

karelz commented Aug 29, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

karelz commented Aug 29, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

martincostello commented Aug 11, 2023 •

edited

Loading

CarnaViire commented Aug 11, 2023 •

edited

Loading

karelz commented Aug 29, 2023 •

edited

Loading

karelz commented Aug 29, 2023 •

edited

Loading