System.Data.OleDb.Test - timeout and hangs

[karelz]

  Discovering: System.Data.OleDb.Tests (app domain = on [no shadow copy], method display = ClassAndMethod, method display options = None)
  Discovered:  System.Data.OleDb.Tests (found 50 of 85 test cases)
  Starting:    System.Data.OleDb.Tests (parallel test collections = on, max threads = 2)
['System.Data.OleDb.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

Roughly 1 failure per day, with 4 rolling runs affected in last 3 weeks. It is blocking CI, we should investigate it ASAP.

{ "ErrorPattern":".*'System.Data.OleDb.Tests' END OF WORK ITEM LOG: Command timed out, and was killed.*" } 

Report

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	0

Known Issue Error Message

Fill the error message using known issues guidance.

{
  "ErrorMessage": "",
  "BuildRetry": false
}

[ghost]

Tagging subscribers to this area: @roji, @ajcvickers
See info in area-owners.md if you want to be subscribed.

Issue Details

---

The test suite fails

Failures in last 120 days

Day	Run	Details
8/23	Rolling run 1960858	Helix timeout
8/22	Rolling run 1959521	Helix timeout
8/22	PR 1959387	Helix timeout
8/20	PR 1955186	Helix timeout
8/19	Rolling run 1954782	Helix timeout
8/18	PR 1952610	Helix timeout
8/18	PR 1952074	Long running tests - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_NullCommandText_Throws and System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
8/18	PR 1951129	Helix timeout
8/17	PR 1950076	Helix timeout
8/16	PR 1946316	Tests passed - Console log - likely infra issue
8/16	Rolling run 1946264	Helix timeout
8/15	PR 1945616	Helix timeout
8/15	PR 1944502	Long running test - System.Data.OleDb.Tests.OleDbConnectionTests.ServerVersionTest
8/12	PR 1941350	Assertion failed at System.String.Substring(Int32 startIndex, Int32 length) in /_/src/libraries/System.Private.CoreLib/src/System/String.Manipulation.cs:line 1836 -- likely specific to the PR
8/11	2x PR 1938154	Assert: ARRAY_SIZE(pCols) >= pTable->m_cCols at coreclr\md\runtime\metamodel.cpp Line: 736 -- likely specific to the PR
8/11	PR 1937102	Helix timeout
8/10	PR 1935667	Long running test - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
8/10	PR 1934364	Long running test - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
8/8	PR 1930946	Helix timeout
8/8	PR 1930321	Long running test - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
8/5	PR 1925814	Helix timeout
8/4	PR 1923196	Long running test - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
8/3	PR 1920208	Long running test - System.Data.OleDb.Tests.OleDbCommandBuilderTests.DeriveParameters_InvalidCommandType_Throws
?-8/1		Console logs not available

Roughly 1 failure per day, with 4 rolling runs affected in last 3 weeks. It is blocking CI, we should investigate it ASAP.

Author:	karelz
Assignees:	-
Labels:	blocking-clean-ci, area-System.Data.OleDB
Milestone:	-

[ajcvickers]

@jkotas @roji Does anything need doing here?

[jkotas]

I do not see any hits in last week, so there is a good chance that this is fixed.

[karelz]

I still see hits on some PRs, some of them created 1-2 days ago. Reopening.

[jkotas]

Stack trace of the crash (the hangs seems to be caused by crash reporting taking too long, so same root cause):

ntdll!ZwWaitForMultipleObjects+0xa [d:\blue.obj.amd64fre\minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 894] 
ntdll!RtlReportExceptionEx+0x452 [d:\blue\minkernel\ntdll\wer.c @ 982] 
ntdll!RtlReportException+0xbc [d:\blue\minkernel\ntdll\wer.c @ 1164] 
comsvcs!ReportException+0x52 [d:\blue\com\complus\src\shared\util\svcerr.cpp @ 1704] 
comsvcs!UserCodeExceptionFilter+0x33 [d:\blue\com\complus\src\shared\util\svcerr.cpp @ 1724] 
comsvcs!ComSvcsExceptionFilter+0x33 [d:\blue\com\complus\src\comsvcs\comsvcs\comsvcs.cpp @ 734] 
comsvcs!`CHolder::SafeDispenserDriver::DestroyResource'::`1'::filt$0+0x1d [d:\blue\com\complus\src\comsvcs\dispman\cholder.cpp @ 216] 
ntdll!__C_specific_handler+0x96 [d:\blue\minkernel\crts\crtw32\misc\amd64\chandler.c @ 194] 
ntdll!RtlpExecuteHandlerForException+0xd [d:\blue\minkernel\ntos\rtl\amd64\xcptmisc.asm @ 131] 
ntdll!RtlDispatchException+0x197 [d:\blue\minkernel\ntos\rtl\amd64\exdsptch.c @ 535] 
ntdll!KiUserExceptionDispatch+0x3a [d:\blue\minkernel\ntos\rtl\amd64\trampoln.asm @ 715] 
ACECORE!JetTerm+0x50 [n:\src\ace\jet4\src\initterm.c @ 1062] 
ACEOLEDB!TerminateJetInstance+0x23 [n:\src\ace\jolt\src\classfac.cpp @ 166] 
ACEOLEDB!MsoHelper::TerminateJet+0x6b [n:\src\ace\jolt\src\classfac.cpp @ 236] 
ACEOLEDB!CDataSource::UtilUninitialize+0xa4 [n:\src\ace\jolt\src\dso.cpp @ 2376] 
ACEOLEDB!CDataSource::~CDataSource+0x37 [n:\src\ace\jolt\src\dso.cpp @ 114] 
ACEOLEDB!CDataSource::`scalar deleting destructor'+0x14
ACEOLEDB!CDataSource::Release+0x80 [n:\src\ace\jolt\src\dso.cpp @ 723] 
oledb32!CAcm::FinalRelease+0x55 [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\cacm.cpp @ 518] 
oledb32!CDCM::FinalRelease+0x19 [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\dcm.cpp @ 93] 
oledb32!ATL::CComPolyObject<CDCM>::FinalRelease+0x1d [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 963] 
oledb32!ATL::CComPolyObject<CDCM>::~CComPolyObject<CDCM>+0x41 [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 969] 
oledb32!ATL::CComPolyObject<CDCM>::Release+0x37 [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 980] 
oledb32!CDCMCreator::DestroyResource+0x2a [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\dcmcreator.cpp @ 509] 
comsvcs!CHolder::SafeDispenserDriver::DestroyResource+0x3a [d:\blue\com\complus\src\comsvcs\dispman\cholder.cpp @ 201] 
comsvcs!CHolder::ProcessDestroyList+0x78 [d:\blue\com\complus\src\comsvcs\dispman\cholder.cpp @ 1089] 
comsvcs!CHolder::FreeResource+0x99 [d:\blue\com\complus\src\comsvcs\dispman\cholder.cpp @ 627] 
oledb32!CDCMCreator::ReleaseResource+0x60 [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\dcmcreator.cpp @ 373] 
oledb32!CDPO::ReturnDCMToPool+0x4042b [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\dpo.cpp @ 595] 
oledb32!CDPO::FinalRelease+0x13 [d:\9147\enduser\databaseaccess\src\mdac\oledb\src\dpo.cpp @ 384] 
oledb32!ATL::CComPolyObject<CDPO>::FinalRelease+0x13 [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 963] 
oledb32!ATL::CComPolyObject<CDPO>::{dtor}+0x29 [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 969] 
oledb32!ATL::CComPolyObject<CDPO>::Release+0x64 [d:\9147.public.fre\sdk\inc\atl21\atlcom.h @ 980] 
System_Private_CoreLib!System.Runtime.InteropServices.Marshal.Release(IntPtr) + 165
System.Private.CoreLib.dll!System.Runtime.InteropServices.Marshal.Release(IntPtr) + 165
System.Data.OleDb.dll!System.Data.ProviderBase.WrappedIUnknown.ReleaseHandle() + 90
System.Private.CoreLib.dll!System.Runtime.InteropServices.SafeHandle.InternalRelease(Boolean) + 143
System.Private.CoreLib.dll!System.Runtime.InteropServices.SafeHandle.Dispose(Boolean) + 32
System.Private.CoreLib.dll!System.Runtime.InteropServices.SafeHandle.Dispose() + 37
System.Data.OleDb.dll!System.Data.OleDb.OleDbConnectionInternal.Dispose() + 174
System.Data.OleDb.dll!System.Data.ProviderBase.DbConnectionInternal.CloseConnection(System.Data.Common.DbConnection, System.Data.ProviderBase.DbConnectionFactory) + 590
System.Data.OleDb.dll!System.Data.OleDb.OleDbConnection.Close() + 103
System.Data.OleDb.Tests.dll!System.Data.OleDb.Tests.OleDbTestBase.Dispose(Boolean) + 250
TestUtilities.dll!System.IO.FileCleanupTestBase.Dispose() + 53
xunit.execution.dotnet.dll!Xunit.Sdk.ExecutionTimer.Aggregate(System.Action) + 53 [/_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs @ 31]
xunit.execution.dotnet.dll!ReflectionAbstractionExtensions.DisposeTestClass(Xunit.Abstractions.ITest, System.Object, Xunit.Sdk.IMessageBus, Xunit.Sdk.ExecutionTimer, System.Threading.CancellationTokenSource) + 244 [/_/src/xunit.execution/Extensions/ReflectionAbstractionExtensions.cs @ 79]
xunit.execution.dotnet.dll!Xunit.Sdk.TestInvoker`1+c__DisplayClass47_0[[System.__Canon, System.Private.CoreLib]].b__1() + 149 [/_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs @ 216]
xunit.core.dll!Xunit.Sdk.ExceptionAggregator.Run(System.Action) + 51 [/_/src/xunit.core/Sdk/ExceptionAggregator.cs @ 73]

[roji]

Note #76054 which could be related: after performing a query via the OleDB ACE driver, the process no longer exits properly. I've verified that switching to the SQL Server OleDB driver makes the problem go away, so presumably this would be an issue in the ACE driver itself. This could also be the root cause for the problem happening above, so switching to a different OleDB driver in the tests could be the "fix" here (though ideally, the ACE driver would be fixed...).

/cc @ajcvickers

[roji]

@karelz we have a report that installing a recent update to the ACE driver may make this go away (KB5002243, see #76054 (comment)). Is it possible to make sure this KB is installed on our CI images?

[carlossanlop]

@roji this is also happening in the release/6.0 branch quite frequently, but it seems the automated arcade error message detection doesn't work in that branch.

So if there is a fix available, please backport it to 6.0.

Here is an example:

• PR: [release/6.0][Android] Backport fix NetworkInterface.GetAllNetworkInterfaces #77260
• Queue: Libraries Test Run release coreclr windows x64 Debug
• Job: https://dev.azure.com/dnceng-public/public/_build/results?buildId=71547&view=logs&j=55b384d0-d6b0-5894-fd8a-d754d713246e&t=8dcacd81-cb5e-5ac9-93e5-c3f19b19e19b&l=949
• Log file: https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-77260-merge-32d91221ef4140938e/System.Data.OleDb.Tests/1/console.ab829b1e.log?helixlogtype=result

Console log: 'System.Data.OleDb.Tests' from job 32d91221-ef41-4093-8eb2-a0830865a9ca workitem 29b3eca1-6f22-4419-aeff-1e2cb18e2638 (windows.11.amd64.client.open.svc) executed on machine a000JWD running Windows-10-10.0.22000-SP0

C:\h\w\9DE008DB\w\B30409A1\e>taskkill.exe /f /im corerun.exe 
ERROR: The process "corerun.exe" not found.

C:\h\w\9DE008DB\w\B30409A1\e>call RunTests.cmd --runtime-path C:\h\w\9DE008DB\p 
----- start Thu 11/03/2022  2:45:57.45 ===============  To repro directly: ===================================================== 
pushd C:\h\w\9DE008DB\w\B30409A1\e\
"C:\h\w\9DE008DB\p\dotnet.exe" exec --runtimeconfig System.Data.OleDb.Tests.runtimeconfig.json --depsfile System.Data.OleDb.Tests.deps.json xunit.console.dll System.Data.OleDb.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing 
popd
===========================================================================================================

C:\h\w\9DE008DB\w\B30409A1\e>"C:\h\w\9DE008DB\p\dotnet.exe" exec --runtimeconfig System.Data.OleDb.Tests.runtimeconfig.json --depsfile System.Data.OleDb.Tests.deps.json xunit.console.dll System.Data.OleDb.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing  
  Discovering: System.Data.OleDb.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Data.OleDb.Tests (found 50 of 85 test cases)
  Starting:    System.Data.OleDb.Tests (parallel test collections = on, max threads = 2)
['System.Data.OleDb.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

[carlossanlop]

Here's another hit in a release/6.0 PR: #77283

[roji]

@carlossanlop OK, thanks for flagging that. Is there anyone who can help with the suggestion in #74488 (comment)? It's possible that some Windows updates on the CI machines would make this go away.

[jkotas]

The place to ask about this is https://teams.microsoft.com/l/team/19%3aa88bb61ffc1a4392ad38ebbc526c86f8%40thread.skype/conversations?groupId=4d73664c-9f2f-450d-82a5-c2f02756606d&tenantId=72f988bf-86f1-41af-91ab-2d7cd011db47 Teams Channel.

[steveisok]

Since this is a known build error, I'm going to remove the blocking-clean-ci label.