Local tests are failing again - seemingly due to a race initializing the page/control

[j4james]

Windows Terminal version

Commit 547349a

Windows build number

10.0.19044.2364

Other Software

No response

Steps to reproduce

1. Check out a recent version of the project.
2. Build it.
3. Run the unit tests.

Expected Behavior

All tests should pass.

Actual Behavior

A number of the local tests are failing:

TerminalAppLocalTests::TabTests::TryInitializePage [Failed]
TerminalAppLocalTests::TabTests::TryDuplicateBadTab [Failed]
TerminalAppLocalTests::TabTests::TryDuplicateBadPane [Failed]
TerminalAppLocalTests::TabTests::TryZoomPane [Failed]
TerminalAppLocalTests::TabTests::MoveFocusFromZoomedPane [Failed]
TerminalAppLocalTests::TabTests::CloseZoomedPane [Failed]
TerminalAppLocalTests::TabTests::SwapPanes [Failed]
TerminalAppLocalTests::TabTests::NextMRUTab [Failed]
TerminalAppLocalTests::TabTests::VerifyCommandPaletteTabSwitcherOrder [Failed]
TerminalAppLocalTests::TabTests::TestWindowRenameSuccessful [Failed]
TerminalAppLocalTests::TabTests::TestWindowRenameFailure [Failed]
TerminalAppLocalTests::TabTests::TestPreviewCommitScheme [Failed]
TerminalAppLocalTests::TabTests::TestPreviewDismissScheme [Failed]
TerminalAppLocalTests::TabTests::TestPreviewSchemeWhilePreviewing [Failed]
TerminalAppLocalTests::TabTests::TestClampSwitchToTab [Failed]
SettingsModelLocalTests::SerializationTests::CascadiaSettings [Failed]

[zadjii-msft]

If I had to blind guess, I'm guessing this is from us removing the XAML Toolkit application but not from the tests. Just a guess.

[zadjii-msft]

... How exactly are they failing for you? I've got a fix for the SerializationTests::CascadiaSettings test ready, but I can't get the others to fail, other than in one-off edge cases. Those are always some sort of closing race condition in accessing the Control's Dispatcher, so I'm not too worried about those (of course the test app lifetime is gonna be even worse than the main app's).

[j4james]

I can't get the others to fail, other than in one-off edge cases.

OK. Maybe it's just me then. They failed for me when doing a full runut.cmd run, but I also confirmed that each of them were failing individually by testing them one by one with /name.

Here's the full output from one test case:

Test Authoring and Execution Framework v10.60k for x64
TAEF: Backing up custom default AppXManifest... Copying C:\Users\James\CPP\terminal\bin\x64\Release\TestHostApp\AppXManifest.xml to C:\Users\James\AppData\Local\Temp\Tfm-20456-0\AppXManifest.xml
TAEF: Deploying custom AppXManifest... Copying C:\Users\James\CPP\terminal\bin\x64\Release\TestHostApp\TestHostAppXManifest.xml to C:\Users\James\CPP\terminal\bin\x64\Release\TestHostApp\AppXManifest.xml

StartGroup: TerminalAppLocalTests::TabTests::TryDuplicateBadTab
Verify: IsNotNull(settings0)
Verify: IsNotNull(settings1)
Construct the TerminalPage
Verify: SUCCEEDED(result)
Verify: IsNotNull(page)
Verify: IsNotNull(page->_settings)
Create() the TerminalPage
Verify: IsNotNull(page)
Verify: IsNotNull(page->_settings)
Create()'d the page successfully
Added a single newTab action
Verify: SUCCEEDED(result)
Wait for the page to finish initializing...
Verify: SUCCEEDED(waitForInitEvent.Wait())
...Done
Ensure we set the first tab as the selected one.
Verify: SUCCEEDED(result)
Verify: AreEqual(1u, page->_tabs.Size())
Verify: SUCCEEDED(result)
Duplicate the first tab
Error: Verify: AreEqual(2u, page->_tabs.Size()) - Values (2, 0) [File: C:\Users\James\CPP\terminal\src\cascadia\LocalTests_TerminalApp\TabTests.cpp, Function: TerminalAppLocalTests::TabTests::TryDuplicateBadTab::<lambda_2>::operator (), Line: 413]
Error: Verify: SUCCEEDED(result) - Value (0x80004005) [File: C:\Users\James\CPP\terminal\src\cascadia\LocalTests_TerminalApp\TabTests.cpp, Function: TerminalAppLocalTests::TabTests::TryDuplicateBadTab, Line: 415]
EndGroup: TerminalAppLocalTests::TabTests::TryDuplicateBadTab [Failed]
TAEF: Restoring cached AppXManifest... Copying C:\Users\James\AppData\Local\Temp\Tfm-20456-0\AppXManifest.xml to C:\Users\James\CPP\terminal\bin\x64\Release\TestHostApp\AppXManifest.xml

From what I can recall, they were all failing with an 0x80004005 error similar to that, but I wasn't paying that much attention. If you can't reproduce it, I'll try and get some more info when I have chance. Maybe another Windows 10 only thing?

[j4james]

I realised after looking at this again that the 0x80004005 error is irrelevant - it's the error before that matters. I still have no clue what's actually going wrong, but I am now fairly convinced it's timing sensitive, and that's possibly why you're not seeing it.

If I insert a Sleep(1000) before this part of the code, I can get it to fail even earlier.

terminal/src/cascadia/LocalTests_TerminalApp/TabTests.cpp

Lines 291 to 299 in 8f08bb0

	result = RunOnUIThread([&page]() {
	// In the real app, this isn't a problem, but doesn't happen
	// reliably in the unit tests.
	Log::Comment(L"Ensure we set the first tab as the selected one.");
	auto tab = page->_tabs.GetAt(0);
	auto tabImpl = page->_GetTerminalTabImpl(tab);
	page->_tabView.SelectedItem(tabImpl->TabViewItem());
	page->_UpdatedSelectedTab(tab);
	});

It looks to me like the tab is getting removed after a certain period of time, so with the additional delay there's no tab left when the _tabs.GetAt(0) call is made, and thus it crashes.

If I instead move the Sleep after the _initializeTerminalPage call, it can then get as far as this _tabs.Size() test before discovering the tab is gone.

terminal/src/cascadia/LocalTests_TerminalApp/TabTests.cpp

Lines 403 to 407 in 8f08bb0

	_initializeTerminalPage(page, settings0);
	auto result = RunOnUIThread([&page]() {
	VERIFY_ARE_EQUAL(1u, page->_tabs.Size());
	});

Without any delays it can get a bit further, but eventually it reaches a point where it's trying to access a tab after is has been removed.

However, if your computer is fast enough, I guess this may never be a problem for you. So maybe it doesn't matter. As long as it's not an indication of an actual bug somewhere.

[zadjii-msft]

Huh. That's a good find. That's far too annoying to call that intermittent. We should fix that so it's deterministic.