Flaky test: DataGridViewRow_PaintCells_Invoke_Success deadlock

[RussKie]

Problem description:

Observing almost permanent test deadlocks locally and on build agents, especially after correcting test decorations in #3064.
Inspecting a memory dump of a locally hung test process I got the following:

 	System.Windows.Forms.Primitives.dll!Interop.User32.SendMessageW(IHandle hWnd = {System.Windows.Forms.DataGridView}, Interop.User32.WM Msg = CHANGEUISTATE, System.IntPtr wParam = 0x0000000000030001, System.IntPtr lParam = 0x0000000000000000) Line 36	C#	Symbols loaded.
 	System.Windows.Forms.dll!System.Windows.Forms.Control.ShowFocusCues.get() Line 3710	C#	Symbols loaded.
 	System.Windows.Forms.dll!System.Windows.Forms.DataGridViewTextBoxCell.PaintPrivate(System.Drawing.Graphics graphics = {System.Drawing.Graphics}, System.Drawing.Rectangle clipBounds = {X = 1 Y = 2 Width = 100 Height = 100}, System.Drawing.Rectangle cellBounds = {X = 42 Y = 2 Width = 100 Height = 100}, int rowIndex = 0, System.Windows.Forms.DataGridViewElementStates cellState = Displayed, object formattedValue = "", string errorText = "", System.Windows.Forms.DataGridViewCellStyle cellStyle = {System.Windows.Forms.DataGridViewCellStyle}, System.Windows.Forms.DataGridViewAdvancedBorderStyle advancedBorderStyle = {System.Windows.Forms.DataGridViewAdvancedBorderStyle}, System.Windows.Forms.DataGridViewPaintParts paintParts = All, bool computeContentBounds = false, bool computeErrorIconBounds = false, bool paint = true) Line 705	C#	Symbols loaded.
 	System.Windows.Forms.dll!System.Windows.Forms.DataGridViewTextBoxCell.Paint(System.Drawing.Graphics graphics = {System.Drawing.Graphics}, System.Drawing.Rectangle clipBounds = {X = 1 Y = 2 Width = 100 Height = 100}, System.Drawing.Rectangle cellBounds = {X = 42 Y = 2 Width = 100 Height = 100}, int rowIndex = 0, System.Windows.Forms.DataGridViewElementStates cellState = Displayed, object value = null, object formattedValue = "", string errorText = "", System.Windows.Forms.DataGridViewCellStyle cellStyle = {System.Windows.Forms.DataGridViewCellStyle}, System.Windows.Forms.DataGridViewAdvancedBorderStyle advancedBorderStyle = {System.Windows.Forms.DataGridViewAdvancedBorderStyle}, System.Windows.Forms.DataGridViewPaintParts paintParts = All) Line 606	C#	Symbols loaded.
 	System.Windows.Forms.dll!System.Windows.Forms.DataGridViewCell.PaintWork(System.Drawing.Graphics graphics = {System.Drawing.Graphics}, System.Drawing.Rectangle clipBounds = {X = 1 Y = 2 Width = 100 Height = 100}, System.Drawing.Rectangle cellBounds = {X = 42 Y = 2 Width = 100 Height = 100}, int rowIndex = 0, System.Windows.Forms.DataGridViewElementStates cellState = Displayed, System.Windows.Forms.DataGridViewCellStyle cellStyle = {System.Windows.Forms.DataGridViewCellStyle}, System.Windows.Forms.DataGridViewAdvancedBorderStyle advancedBorderStyle = {System.Windows.Forms.DataGridViewAdvancedBorderStyle}, System.Windows.Forms.DataGridViewPaintParts paintParts = All) Line 4287	C#	Symbols loaded.
 	System.Windows.Forms.dll!System.Windows.Forms.DataGridViewRow.PaintCells(System.Drawing.Graphics graphics = {System.Drawing.Graphics}, System.Drawing.Rectangle clipBounds = {X = 1 Y = 2 Width = 100 Height = 100}, System.Drawing.Rectangle rowBounds = {X = 1 Y = 2 Width = 100 Height = 100}, int rowIndex = 0, System.Windows.Forms.DataGridViewElementStates rowState = Displayed, bool isFirstDisplayedRow = true, bool isLastVisibleRow = false, System.Windows.Forms.DataGridViewPaintParts paintParts = All) Line 1617	C#	Symbols loaded.
>	System.Windows.Forms.Tests.dll!System.Windows.Forms.Tests.DataGridViewRowTests.DataGridViewRow_PaintCells_Invoke_Success(System.Windows.Forms.DataGridViewRow row = {System.Windows.Forms.DataGridViewRow}, System.Drawing.Rectangle clipBounds = {X = 1 Y = 2 Width = 100 Height = 100}, System.Drawing.Rectangle rowBounds = {X = 1 Y = 2 Width = 100 Height = 100}, int rowIndex = 0, System.Windows.Forms.DataGridViewElementStates rowState = Displayed, bool isFirstDisplayedRow = true, bool isLastVisibleRow = false, System.Windows.Forms.DataGridViewPaintParts paintParts = All) Line 3263	C#	Symbols loaded.

There doesn't appear any other threads with code from System.Windows.Forms, so it looks like this code deadlocks on itself.

[weltkante]

Ouch, that is a bad hang. Looks like its waiting for a control on a thread without message loop.

Now I'm wondering whether test data is generated on a separate thread. If so that would be a major problem for creating any thread-bound object in test data because it can make any test flaky /cc @hughbe FYI

I'll start passing the ThreadID through the test data arguments and assert that the tests run on the same thread as the objects were created on.

[weltkante]

Yup thats the problem, test data is generating thread bound objects on a different thread. We probably need a WinFormsMemberData as welll (or have WinFormsTheory change how MemberData is executed, don't know which is easier to achieve)

@AArnott @RussKie is this something we'd also want propagated back into Xunit.StaFact, or should we start creating local test infrastructure instead considering that we can't use the nuget package anyways due to #3122 ?

@hughbe this particular test data is also breaking other rules because it shares a DataGridView over multiple test data rows and never disposes the actual control, so even after fixing the thread test data is created on these tests will still leak DataGridView controls, risking deadlocks in other tests.

[hughbe]

Yes unfortunately these tests were designed pretty badly. I'm working on a full overhaul by removing DataGridViewRow parameters within testdata, but I'm a bit busy on other stuff

[AArnott]

So if I understand correctly, an [StaTheory] test has a data-generating attribute whose method is running but not on the same STA thread that the test runs on? I'd never considered that requirement but it makes sense to fix this. I don't know whether xunit even gives the discovery attribute power to execute the data generating attribute. If so, I can fix this.

Even if you fork my project and/or use a git submodule, etc., I'd love to keep the code as similar between our codebases as possible. This is an example of good stuff you're finding that our customers who want to test WinForms will likely also hit.

[AArnott]

OK, so I did some digging. There appears to be no way we can ensure the data objects are created on the STA thread. In fact when running in the Test Explorer, they weren't created at all -- they were deserialized. The data generating attribute ran out of proc and its results had been serialized, only to be reconstituted later in the test executing process.

I wasn't testing with thread-affinitized data objects, and I have no idea how this would work with objects that can't theoretically be serialized. But suffice it to say, xunit calls the data generating attributes before ever getting to my xunit.stafact code. So I don't think there's anything I can do.

[weltkante]

sure, just asking if there is interest in flowing this back, I can open an issue with a repro scenario over at the StaFact repo, debugging the winforms tests is still a pain until some of the other issues here get fixed :-)

[edit] sorry didn't see your second response before writing mine

they weren't created at all -- they were deserialized

I need to be debugging this, but considering that you can generate non-serializable objects in test data this seems weird. I had debugged this recently for #3122 to make sure my workarounds actually work, and I don't think the data items get deserialized (I may be mistaken of course).

There appears to be no way we can ensure the data objects are created on the STA thread.

I'll take a closer look myself later today and we'll see if I come to the same conclusion. Thanks for doing a quick check though.

[AArnott]

Ok, good news. I created a custom type and return it in my MemberData member. My goal was that my custom type would not be serializable, but I didn't have to do anything special to achieve that.
xunit/TE does run it out of proc, but it evidently detects this isn't a primitive/serializable(?) type and then it reruns the data generator in proc just before running the test.

The best news is that xunit.stafact does control the thread that this in-proc re-generation of data runs on:

 	Xunit.StaFact.Tests.dll!StaTheoryTests.NonSerializableObject.NonSerializableObject() Line 27	C#
 	Xunit.StaFact.Tests.dll!StaTheoryTests.NonSerializableData.get() Line 34	C#
 	[Native to Managed Transition]	
 	[Managed to Native Transition]	
 	xunit.core.dll!Xunit.MemberDataAttributeBase.GetData(System.Reflection.MethodInfo testMethod) Line 66	C#
 	xunit.core.dll!Xunit.Sdk.DataDiscoverer.GetData(Xunit.Abstractions.IAttributeInfo dataAttribute, Xunit.Abstractions.IMethodInfo testMethod) Line 25	C#
 	xunit.execution.desktop.dll!Xunit.Sdk.XunitTheoryTestCaseRunner.AfterTestCaseStartingAsync() Line 92	C#
 	xunit.execution.desktop.dll!Xunit.Sdk.TestCaseRunner<Xunit.Sdk.IXunitTestCase>.RunAsync() Line 81	C#
>	Xunit.StaFact.dll!Xunit.Sdk.UITheoryTestCase.RunAsync(Xunit.Abstractions.IMessageSink diagnosticMessageSink, Xunit.Sdk.IMessageBus messageBus, object[] constructorArguments, Xunit.Sdk.ExceptionAggregator aggregator, System.Threading.CancellationTokenSource cancellationTokenSource) Line 29	C#
 	xunit.execution.desktop.dll!Xunit.Sdk.XunitTestMethodRunner.RunTestCaseAsync(Xunit.Sdk.IXunitTestCase testCase) Line 45	C#

So I'll file a bug and see if we can get this fixed.

[AArnott]

Can someone download the build artifact from this PR build and validate that it resolves your issue?
AArnott/Xunit.StaFact#42

[weltkante]

Thread IDs are consistent now, so as far as I can tell it works. Test also doesn't hang.

[AArnott]

Thanks for the validation. This is now pushed to nuget.

https://github.com/AArnott/Xunit.StaFact/releases/tag/v1.0.31-beta

[weltkante]

great, thanks again for looking into it!

(for the record, this is blocked on #3122 because fixes in stafact currently cannot flow to winforms, I used the workaround mentioned in the issue to test locally)

[RussKie]

#3122 is high on my list, I just have a massive backlog do deal with

[weltkante]

Can this be closed? #3122 is merged and the tests disabled in #3211 seem to be active again in master. Anything else to look at?

[RussKie]

Yes, thank you for keeping track of this 👍