Additional test stabilization (#935): Drain Queue Before Verifying Results in AsyncBlockTests (#940)

jhugard · web-flow · commit e0be0f0494b4 · 2026-02-20T14:29:09.000-08:00
* fix 935: drain queue before verifying opcodes in all verification tests

Apply queue drain timing fix to tests that verify async opcodes.
These tests were checking opcodes immediately after async completion
without ensuring all cleanup work had been recorded to the opcode log,
causing intermittent test failures.

* Refine cdb test soak script

Refactor cdb test script to capture stacks independently, as well as
output log, stacks, and dmp for all abnormal exits (including Ctrl+C).

* Fix AsyncBlockTests: drain queue before verifying in al tests

Apply consistent queue drain pattern to 8 AsyncBlockTests before final queue
verification to eliminate timing races where cleanup work completes asynchronously
after XAsyncGetStatus() returns.

Root Cause:
  The async framework's Cleanup operation is initiated by the provider but
  completed asynchronously through the task queue. Tests checking queue state
  or opcode snapshots immediately after XAsyncGetStatus() could race with the
  pending Cleanup work, resulting in intermittent failures (heisenbug-like
  behavior with "8 vs 9 opcodes" or "queue not empty" errors).

Solution:
  All queue verification now preceded by explicit drain loop:
    - Checks both Completion and Work ports
    - 10ms sleep granularity, 2000ms timeout
    - Ensures all async cleanup completes before verification
diff --git a/Tests/UnitTests/Tests/AsyncBlockTests.cpp b/Tests/UnitTests/Tests/AsyncBlockTests.cpp
@@ -429,15 +429,15 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
         ops.push_back(XAsyncOp::GetResult);
         ops.push_back(XAsyncOp::Cleanup);
 
-        VerifyOps(data.Ref->GetOpCodes(), ops);
-
+        // Drain the queue before verifying opcodes to ensure cleanup has been recorded
         UINT64 drainTicks = GetTickCount64();
         while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
             && GetTickCount64() - drainTicks < 2000)
         {
             Sleep(10);
         }
 
+        VerifyOps(data.Ref->GetOpCodes(), ops);
         VERIFY_QUEUE_EMPTY(queue);
     }
 
@@ -480,6 +480,14 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
 
         VERIFY_ARE_EQUAL(count, completionCount);
 
+        // Drain the queue before verifying it's empty to ensure all cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
+
         // Note: FactorialCallData array elements were cleaned up by FactorialResult.
         VERIFY_QUEUE_EMPTY(queue);
     }
@@ -527,14 +535,15 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
         ops.push_back(XAsyncOp::GetResult);
         ops.push_back(XAsyncOp::Cleanup);
 
-        VerifyOps(data.Ref->GetOpCodes(), ops);
-
+        // Drain the queue before verifying opcodes to ensure cleanup has been recorded
         UINT64 drainTicks = GetTickCount64();
         while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
             && GetTickCount64() - drainTicks < 2000)
         {
             Sleep(10);
         }
+
+        VerifyOps(data.Ref->GetOpCodes(), ops);
         VERIFY_QUEUE_EMPTY(queue);
     }
 
@@ -605,9 +614,16 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
 
         XAsyncCancel(&async);
         VERIFY_ARE_EQUAL(XAsyncGetStatus(&async, true), E_ABORT);
-        Sleep(500);
         VERIFY_ARE_EQUAL(E_ABORT, hrCallback);
 
+        // Drain the queue before verifying opcodes to ensure cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
+
         auto opCodes = data.Ref->GetOpCodes();
         VerifyHasOp(opCodes, XAsyncOp::Cancel);
         VerifyHasOp(opCodes, XAsyncOp::Cleanup);
@@ -640,7 +656,14 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
         XAsyncCancel(&async);
 
         VERIFY_ARE_EQUAL(XAsyncGetStatus(&async, true), E_ABORT);
-        XTaskQueueDispatch(queue, XTaskQueuePort::Completion, 700);
+        
+        // Drain the queue before verifying opcodes to ensure cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
 
         auto opCodes = data.Ref->GetOpCodes();
         VerifyHasOp(opCodes, XAsyncOp::Cancel);
@@ -674,7 +697,14 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
         XAsyncCancel(&async);
 
         VERIFY_ARE_EQUAL(XAsyncGetStatus(&async, true), E_ABORT);
-        Sleep(500);
+        
+        // Drain the queue before verifying opcodes to ensure cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
 
         auto opCodes = data.Ref->GetOpCodes();
         VerifyHasOp(opCodes, XAsyncOp::Cancel);
@@ -701,7 +731,14 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
         VERIFY_SUCCEEDED(XAsyncRun(&async, WorkThunk::Callback));
         
         result = XAsyncGetStatus(&async, true);
-        Sleep(500);
+        
+        // Drain the queue before verifying it's empty to ensure cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
 
         VERIFY_ARE_EQUAL(result, expected);
         VERIFY_QUEUE_EMPTY(queue);
@@ -815,7 +852,14 @@ DEFINE_TEST_CLASS(AsyncBlockTests)
 
         VERIFY_SUCCEEDED(FactorialAllocateAsync(5, &async));
         VERIFY_SUCCEEDED(XAsyncGetStatus(&async, true));
-        Sleep(500);
+        
+        // Drain the queue before verifying it's empty to ensure cleanup has been recorded
+        UINT64 drainTicks = GetTickCount64();
+        while ((!XTaskQueueIsEmpty(queue, XTaskQueuePort::Completion) || !XTaskQueueIsEmpty(queue, XTaskQueuePort::Work))
+            && GetTickCount64() - drainTicks < 2000)
+        {
+            Sleep(10);
+        }
 
         VERIFY_ARE_EQUAL(result, (DWORD)120);
         VERIFY_QUEUE_EMPTY(queue);
diff --git a/Tests/test_under_cdb.ps1 b/Tests/test_under_cdb.ps1
@@ -90,59 +90,50 @@ while ($true) {
 	if (Test-Path $dumpPath) { Remove-Item $dumpPath -Force -ErrorAction SilentlyContinue }
 
 	$dumpPathCdb = $dumpPath -replace '\\','/'
-	$dumpOnBreakpoint = 'sxd ibp'
-	$dumpSymbols = @(
-		'TE_Common!WEX::TestExecution::Verify::VerificationFailed<tagVARIANT,tagVARIANT,WEX::TestExecution::Verify::VerifyMessageFunctor>',
-		'TE_Common!WEX::TestExecution::Verify::VerificationFailed<tagVARIANT,tagVARIANT,WEX::TestExecution::Private::VerifyMessageFunctor>',
-		'TE_Common!WEX::TestExecution::ComVerify::AreEqual',
-		'libHttpClient_UnitTest_TAEF!WEX::TestExecution::Private::MacroVerify::VerificationFailed',
-		'libHttpClient_UnitTest_TAEF!WEX::TestExecution::Private::MacroVerify::AreEqualImpl<unsigned int>',
-		'libHttpClient_UnitTest_TAEF!WEX::TestExecution::Private::MacroVerify::IsTrueImpl<char>',
-		'ucrtbased!abort',
-		'ucrtbase!abort',
-		'ucrtbased!issue_debug_notification',
-		'ucrtbase!issue_debug_notification',
-		'vcruntime140d!__fastfail',
-		'vcruntime140_1d!__fastfail',
-		'vcruntime140d!_invoke_watson',
-		'vcruntime140_1d!_invoke_watson',
-		'ucrtbased!_CrtDbgReportW',
-		'ucrtbased!_raiseabort',
-		'ucrtbase!_raiseabort'
+	$stackTraceFile = Join-Path $LogDir ("stack_{0:D6}_{1}_{2}.txt" -f $iteration, $stamp, $nonce)
+	$stackPathCdb = $stackTraceFile -replace '\\','/'
+
+	# Helper function to generate diagnostic commands (log stacks, dump, exit)
+	function Get-DiagnosticCommand {
+		param(
+			[string]$StackFile,
+			[string]$DumpFile,
+			[switch]$IncludeAnalyze
+		)
+		$analyze = if ($IncludeAnalyze) { '!analyze -v; ' } else { '' }
+		return ".logopen $StackFile; ${analyze}~*k; .logclose; .dump /ma /o $DumpFile; q"
+	}
+
+	$diagCmd = Get-DiagnosticCommand -StackFile $stackPathCdb -DumpFile $dumpPathCdb -IncludeAnalyze
+	$diagCmdNoAnalyze = Get-DiagnosticCommand -StackFile $stackPathCdb -DumpFile $dumpPathCdb
+
+	# Ctrl+C handler: capture all thread stacks and dump before quitting
+	$ctrlCHandler = 'sxe -c "' + $diagCmd + '" 0x40010005'
+	# Access violation handler: capture stacks and dump
+	$avHandler = 'sxe -c "' + $diagCmd + '" av'
+	# Stack overflow handler: capture stacks and dump
+	$stackOverflowHandler = 'sxe -c "' + $diagCmd + '" 0xc0000409'
+
+	# Common debugger setup
+	$cmdLines = @(
+		'.childdbg 1'
+		'sxd ibp'
+		'.logopen ' + $logPath
+		('bp ucrtbased!abort "' + $diagCmd + '"')
+		('bp ucrtbase!abort "' + $diagCmd + '"')
+		('bp vcruntime140d!_invoke_watson "' + $diagCmd + '"')
+		$stackOverflowHandler
+		$avHandler
+		'sxd c0000374'
+		$ctrlCHandler
+		'g'
 	)
-	$dumpBreakpoints = $dumpSymbols | ForEach-Object { New-DumpOnSymbol -Symbol $_ -DumpPath $dumpPathCdb }
 
+	# Append mode-specific exit behavior
 	if ($ManualDebug) {
-		$cmdLines = @(
-			'.childdbg 1',
-			$dumpOnBreakpoint
-		) + $dumpBreakpoints + @(
-			'sxd eh',
-			'sxi 0xe06d7363',
-			'sxe 0x40000015',
-			'sxe 0xc0000409',
-			'sxe 0xc000013a',
-			'sxe av',
-			'sxe c0000374',
-			'g',
-			'g'
-		)
+		$cmdLines += 'g'
 	} else {
-		$cmdLines = @(
-			'.childdbg 1',
-			$dumpOnBreakpoint
-		) + $dumpBreakpoints + @(
-			'sxd eh',
-			'sxi 0xe06d7363',
-			('sxe -c "!analyze -v; ~*k; .dump /ma /o ' + $dumpPathCdb + '; .kill; q" 0xc000013a'),
-			('sxe -c "!analyze -v; ~*k; .dump /ma /o ' + $dumpPathCdb + '; .kill; q" 0x40000015'),
-			('sxe -c "!analyze -v; ~*k; .dump /ma /o ' + $dumpPathCdb + '; .kill; q" 0xc0000409'),
-			('sxd -c "!analyze -v; ~*k; .dump /ma /o ' + $dumpPathCdb + '; .kill; q" av'),
-			('sxd -c "!analyze -v; ~*k; .dump /ma /o ' + $dumpPathCdb + '; .kill; q" c0000374'),
-			'g',
-			'g', # resume on TE's initial breakpoint
-			'q'
-		)
+		$cmdLines += 'q'
 	}
 	$cmdLines | Set-Content -Path $cmdFile -Encoding ASCII
 
@@ -152,6 +143,7 @@ while ($true) {
     if (Test-Path -Path $dumpPath -PathType Leaf ) {
 		Write-Host "Crash dump detected; stopping" -ForegroundColor Red
 		Write-Host "Log: $logPath"
+		Write-Host "Stack trace: $stackTraceFile"
 		Write-Host "Dump: $dumpPath"
 		break
 
@@ -160,13 +152,13 @@ while ($true) {
 	if ($exitCode -ne 0) {
 		Write-Host "Non-zero exit code: $exitCode" -ForegroundColor Red
 		Write-Host "Log: $logPath"
+		Write-Host "Stack trace: $stackTraceFile"
 		Write-Host "Dump: $dumpPath"
 		break
 	}
 
-	# Successful run: clean up log/dump/cmd to avoid accumulation
+	# Successful run: clean up log/cmd to avoid accumulation (keep dumps/stacks for retention)
 	if (Test-Path $logPath) { Remove-Item $logPath -Force -ErrorAction SilentlyContinue }
-	if (Test-Path $dumpPath) { Remove-Item $dumpPath -Force -ErrorAction SilentlyContinue }
 	if (Test-Path $cmdFile) { Remove-Item $cmdFile -Force -ErrorAction SilentlyContinue }
 }
 
