Deadlock when using FindComponent(s) with WaitForX

[rmihael]

Today we started to see random hang-ups while running bUnit tests. After some debugging, it boiled down to these two threads mutually locking each other:

Worker thread @33878491
	Monitor.Enter() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/3da0403ae6e540a7a79283e509f3945b8d7e00/18E/Monitor.cs:line 48
	TestRenderer.FindComponents<SolidCube.Components.Shared.TreeItem>() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/26/TestRenderer.cs:line 251
	TestRenderer.FindComponents<SolidCube.Components.Shared.TreeItem>() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/26/TestRenderer.cs:line 111
	RenderedFragmentExtensions.FindComponents<SolidCube.Components.Shared.TreeItem>() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/b1aaada6d19e4b1a9a6620aa89b26c4b2aa00/27/RenderedFragmentExtensions.cs:line 83
	RenderedComponentExtensions.<>c__DisplayClass1_0<TreeItem>.<WaitForComponents>b__0()
	WaitForAssertionHelper.<>c__DisplayClass6_0.<.ctor>b__0()
	WaitForHelper<object>.OnAfterRender() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/14/WaitForHelper.cs:line 106
	new WaitForHelper<object>() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/14/WaitForHelper.cs:line 73
	new WaitForAssertionHelper()
	RenderedFragmentWaitForHelperExtensions.WaitForAssertion()
	RenderedComponentExtensions.WaitForComponents<SolidCube.Components.Shared.TreeItem>()

Worker thread @33878451
	Monitor.Enter() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/3da0403ae6e540a7a79283e509f3945b8d7e00/18E/Monitor.cs:line 48
	WaitForHelper<object>.OnAfterRender() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/14/WaitForHelper.cs:line 97
	RenderedFragment.Bunit.IRenderedFragmentBase.OnRender() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/b1aaada6d19e4b1a9a6620aa89b26c4b2aa00/4A/RenderedFragment.cs:line 158
	TestRenderer.UpdateDisplayAsync()
	Renderer.ProcessRenderQueue()
	Renderer.ProcessPendingRender() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/28489e7a98534715a55deed8cf7572df6b200/3E/Renderer.cs:line 438
	TestRenderer.ProcessPendingRender() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/8adb50b4d399477b881862854de9b0cb13c00/26/TestRenderer.cs:line 125
	Renderer.DispatchEventAsync() at /Users/rmihael/Library/Application Support/JetBrains/Rider2021.2/resharper-host/SourcesCache/28489e7a98534715a55deed8cf7572df6b200/3E/Renderer.cs:line 285
	TestRenderer.<>n__0()
	TestRenderer.<>c__DisplayClass15_0.<DispatchEventAsync>b__0()
	RendererSynchronizationContext.<>c.<<InvokeAsync>b__9_0>d.MoveNext()
	AsyncMethodBuilderCore.Start<Microsoft.AspNetCore.Components.Rendering.RendererSynchronizationContext.<>c.<<InvokeAsync>b__9_0>d>()
	AsyncVoidMethodBuilder.Start<Microsoft.AspNetCore.Components.Rendering.RendererSynchronizationContext.<>c.<<InvokeAsync>b__9_0>d>()
	RendererSynchronizationContext.<>c.<InvokeAsync>b__9_0()
	RendererSynchronizationContext.ExecuteSynchronously()
	RendererSynchronizationContext.<>c.<.cctor>b__23_0()
	ExecutionContext.RunInternal()
	ExecutionContext.Run()
	RendererSynchronizationContext.ExecuteBackground()
	RendererSynchronizationContext.<>c.<.cctor>b__23_1()
	ContinuationTaskFromTask.InnerInvoke()
	Task.<>c.<.cctor>b__277_0()
	ExecutionContext.RunFromThreadPoolDispatchLoop()
	Task.ExecuteWithThreadLocal()
	Task.ExecuteEntryUnsafe()
	Task.ExecuteFromThreadPool()
	ThreadPoolWorkQueue.Dispatch()
	_ThreadPoolWaitCallback.PerformWaitCallback()
	[Native to Managed Transition]

It seems that Renderer.DispatchEventAsync calls TestRenderer.ProcessPendingRender which locks TestRenderer.renderTreeAccessLock and then proceed to WaitForHelper.OnAfterRender where it waits on WaitForHelder.lockObject. On the other thread WaitForHelper.OnAfterRender locks WaitForHelper.lockObject and then proceeds to TestRenderer.FindComponents where it waits for TestRenderer.renderTreeAccessLock.

Version info:

• bUnit version: 1.3.42
• .NET Runtime and Blazor version: .NET 5.0.402, AspNetCore 5.0.8
• OS type and version: MacOS 11.5.2

Additional context:

We saw hang-ups sporadically before, but now they are very consistent. It happened after we replaced Blazor.EventsAggregator dependency with native C# events. Many methods that were async before now sync, possibly resulting in a more deterministic flow.

[egil]

Thanks for reporting this.

I cannot say anything specific since you have not shared your test code. That said, you mention that have way more sync code paths in your code than before, so it might mean you can remove some of the WaitFor* calls in your tests. They are generally only needed when a rendered component cannot complete all it's rendering work synchronously, and have to await e.g. data from the test code.

[rmihael]

I would gladly share our test code. However, it's a part of a large application and based on SpecFlow, so it's rather useless if taken out of context. I can try to make a simpler XUnit test reproducing the problem, but I cannot share code for application components. Will such a test be helpful for you to diagnose the problem?

[egil]

Yes, a small sample/example test project is great for debugging. Something I can run locally. Try to reduce the code as much as possible to remove any noice.

[SviatoslavK]

Hi Egil!
I'm working with @rmihael on the same project. Sorry for such a long reply. It's been difficult to allocate time to work on the sample project between upcoming release and the started war... Finally we did it! Please, find the sample project in the attachment
TestExample.zip

[linkdotnet]

I tried to reproduce your example... besides the 26 minutes of runtime (due to the 1000 elements) the tests went green:

[egil]

Hi @SviatoslavK, hope everything is well.

I had a look and can confirm that there is a potential race condition here. I also have an idea for a solution, but as with all things concurrency, this isn't necessarily going to be simple, since the locks that I have in the TestRenderer that you see in your stack trace are there for a good reason.

[egil]

Let me explain what the problem is:

In the TestRenderer, we currently have a lock in place to prevent test code in thread 1 from traversing it in thread 2, which can lead to other race conditions, where users are not able to get their assertions passing before the render tree changes again (e.g. if a component renders, then waits a few milliseconds, and then renders again). FindComponents is how we traverse the render tree.

1. When a render is triggered/queued, the ProcessPendingRender method is called and the lock is entered when possible.
2. base.ProcessPendingRender() is called inside the lock, which starts rendering cycle.
3. When the render cycle completes, base.ProcessPendingRender() calls UpdateDisplayAsync.
4. UpdateDisplayAsync then call all IRenderedFragment the user has a handle on and tells them to update themselves with the latest changes to the DOM tree.
5. UpdateDisplayAsync then triggers all WaitForXXX predicate/assertions that gets a chance to inspect component or DOM state before a new render cycle can start.
6. After UpdateDisplayAsync finishes, control returns to ProcessPendingRender which release the lock.

The deadlock can happen if FindComponents is used in step 5 in a "WaitForXXX" predicate/assertion, since that would be blocked by the render lock, since that lock is still entered. until UpdateDisplayAsync completes.

[vedion]

Hi,

We also have this problem with the tests deadlocking.

[egil]

Hi,

We also have this problem with the tests deadlocking.

Hi @vedion, can you share a minimal example from your end that causes the deadlock? That would really help find a solution.
Also, does this happens consistently in your tests, or is it just once in a while?