Add partial packet detection and fixup

Split out from https://github.com/dotnet/SqlClient/pull/2608 per discussion detailed in https://github.com/dotnet/SqlClient/pull/2608#issuecomment-2239803005
Adds packet multiplexer and covering tests.

I've added comments to the Packet class as requested. The CI was green apart from some ubuntu legs which timed out, many other ubuntu legs succeeded so I don't see any direct inference on from that.
Ready for review @David-Engel @saurabh500 @cheenamalhotra

@Wraith2 We are reviewing this and hope to get faster traction towards EOW.
  The results, if any, should be discarded.
      at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlE

This test should be looked at carefully.
It failed on Ubuntu with .NET 6 and 8 , and also hung up on Windows when ran with Managed SNI, link to logs.
In this use case, multiple parallel async read operations are being performed, which means connection isolation should be intact while cancellation occurs in between, but it doesn't seem to be happening.

Isn't this the set of tests that @David-Engel pointed out in https://github.com/dotnet/SqlClient/pull/2608#issuecomment-2215278475 ? If so we discussed it at length on the teams call. I don't believe that those tests are reliable.
Setup a breakpoint or Debug.WriteLine where an exception is added to the state object and run the test. You should find that an exception is always added to the state object but that the test will usually succeed. That should not be possible, an exception if added should be thrown. The test is missing failures and if that's the case then the test is unreliable.

When you work past the terrible code in SNITCPHandle and make the test run for long enough it settles into a steady state where it can't reach the end. There is no indication why yet.
00:05:45.3696502 True Started:97 Done:88 InFlight:9 RowsRead:241216 ResultRead:3769 PoisonedEnded:88 nonPoisonedExceptions:0 PoisonedCleanupExceptions:0 Count:0 Found:0
00:05:50.3638134 True Started:97 Done:88 InFlight:9 RowsRead:241216 ResultRead:3769 PoisonedEnded:88 nonPoisonedExceptions:0 PoisonedCleanupExceptions:0 Count:0 Found:0

those 9 in flight items just don't seem to complete but i don't know why.
This is going to need your help from MS side to identify what's going on here.

After a few more hours investigation I know what the problem is but I have no clue what change has caused it.
In SqlDataReader when an async method is called we use a context object to contain some state and pass that context object to all the async methods that are used to implement the async read machinery. Part of this state is the TaskCompletionSource.
When running the test CancelAsyncConnections many connections are opened and then SqlCommand.Cancel is called after a brief timed wait. If the timing of the cancel operation is exact then an async operation can be in progress and between packets at the time when the cancellation is executed.
This causes the thread awaiting the async operation to wait indefinitely for a task that will never be completed. This is  what causes the stuck threads. The threads as stuck so the test can never complete and it then times out.
What I don't understand is how cancel is supposed to work. I'm unable to run the tests in native sni mode because the native sni can't be initialized (can't find the sni dll). So I can't compare the managed to unmanaged implementations here. I don't believe that I have made any change that should affect cancellation. I have verified that there are no partial packets in the state objects when the async tasks get stuck.
I don't understand how async cancellation is supposed to work at all.

Can someone with CI access rerun the failed legs? the failures are random or CI resources not being available as far as i can tell.

The current failures are interesting. They're in the test that was failing before but they new ones are only detected because i made the test more accurate.
  [xUnit.net 00:06:40.39]     Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections [FAIL]
  [xUnit.net 00:06:40.39]       Assert.Empty() Failure: Collection was not empty
  [xUnit.net 00:06:40.39]       Collection: ["Microsoft.Data.SqlClient.SqlException (0x80131904)"···]
  [xUnit.net 00:06:40.39]       Stack Trace:
  [xUnit.net 00:06:40.39]         /_/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncCancelledConnectionsTest.cs(71,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.RunCancelAsyncConnections(SqlConnectionStringBuilder connectionStringBuilder)
  [xUnit.net 00:06:40.39]         /_/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncCancelledConnectionsTest.cs(32,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections()
  [xUnit.net 00:06:40.39]            at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
  [xUnit.net 00:06:40.39]            at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
  [xUnit.net 00:06:40.39]       Output:
  [xUnit.net 00:06:40.39]         00:00:05.4318805 True Started:21 Done:0 InFlight:21 RowsRead:117 ResultRead:9 PoisonedEnded:4 nonPoisonedExceptions:2 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         00:00:10.4374767 True Started:25 Done:0 InFlight:25 RowsRead:1469 ResultRead:113 PoisonedEnded:11 nonPoisonedExceptions:9 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         00:00:15.4529038 True Started:31 Done:1 InFlight:30 RowsRead:4732 ResultRead:364 PoisonedEnded:14 nonPoisonedExceptions:13 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         00:00:20.4568918 True Started:67 Done:12 InFlight:55 RowsRead:7852 ResultRead:604 PoisonedEnded:28 nonPoisonedExceptions:21 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         00:00:24.9990795 True Started:91 Done:32 InFlight:59 RowsRead:19955 ResultRead:1535 PoisonedEnded:43 nonPoisonedExceptions:35 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         00:00:28.1341854 True Started:100 Done:100 InFlight:0 RowsRead:52273 ResultRead:4021 PoisonedEnded:100 nonPoisonedExceptions:44 PoisonedCleanupExceptions:0 Count:1 Found:0
  [xUnit.net 00:06:40.39]         Microsoft.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.  The results, if any, should be discarded.
  [xUnit.net 00:06:40.39]            at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlE
    Failed Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections [28 s]
EXEC : error Message:  [/mnt/vss/_work/1/s/build.proj]
     Assert.Empty() Failure: Collection was not empty

The previous version of the test accepted any exception when it was expecting a cancellation exception. It was passing on netfx with my previous changes because timeout exceptions were being thrown. I judged that accepting a timeout when we were supposed to be testing whether cancellation had occurred was not correct.
If we retained the previous version of the test then everything would have passed cleanly. In the current situation since the test completed correctly without hanging the result is equivalent to what we would have experienced in all test runs in the past, all started threads that we expected to be cancelled exited with an exception.

@Wraith2 You might be banging your head against an unrelated issue in the driver. IIRC, the test was only introduced to ensure we don't regress "The MARS TDS header contained errors." issue. (The test code came from the repro.)
If you isolate your test changes and run them against main code, does it still fail? Yes, the correct exception is probably "Operation cancelled by user." where the exception is being caught. But if it's unrelated to your other changes, I would leave that part of the test as it was and file a new issue with repro code. As it is, it's unclear if and how this behavior is impacting users and I wouldn't hold up your perf improvements for it.

There was definitely a real problem. The results differed between main and my branch. I've solved that issue now and the current state is that we're seeing a real failure because I've made the test more sensitive. I think it's probably safe to lower the sensitivity of the test again now because the new test that I've added covers the specific scenario in the multiplexer that I had missed and everything else is pass. I'll try that and see how the CI likes it.
I think the current state on this branch is that it is as stable as live. We need to have confidence that this set of changes is correct before we can merge it. It's high risk and high complexity code. Even understanding it very deeply it has taken me a week to actively debug a very important behaviour change that I missed.

The failing test is EventCounter_ReclaimedConnectionsCounter_Functional. It's doing something with GC specific to net6. It's failing sporadically on net6 managed sni runs but not deterministically. I can't make it fail locally to trace what might be happening.

Any thoughts?

I'm not seeing the failures you mentioned in EventCounter_ReclaimedConnectionsCounter_Functional. I mainly see fairly consistent failures of CancelAsyncConnections on Linux. It seems to pass on Windows managed SNI, so there might be something that is Linux/Ubuntu network specific. Can you run/debug the test against a local WSL or Docker instance?

If i click through the failure i get to this page https://sqlclientdrivers.visualstudio.com/public/_build/results?buildId=95784&view=ms.vss-test-web.build-test-results-tab

The cancel tests are passing now, those failed in the previous runs but not the current ones.

I think there is something wrong with the Tests tab. I don't usually reference it. I scroll down the summary tab to see what jobs had failures:

Then drill into the job and the task that failed to see the log:

I chatted with @saurabh500 and I just want to add that this is definitely something we all want to see get merged. It'll just take someone finding time (could take a few days dedicated time) to get their head wrapped around the new code and be able to help repro/debug to find the issue.

I'm happy to make myself available to talk through the code with anyone that needs it.

@Wraith2  and @David-Engel  I was looking at the lifecycle of the snapshots and something that stood out in NetCore vs NetFx is that SqlDataReader for NetCore is storing the cached snapshot with the SqlInternalConnectionTds which is a shared resource among all the SqlDataReader(s) running on a MARS connection.
private void PrepareAsyncInvocation(bool useSnapshot)
{
    // if there is already a snapshot, then the previous async command
    // completed with exception or cancellation.  We need to continue
    // with the old snapshot.
    if (useSnapshot)
    {
        Debug.Assert(!_stateObj._asyncReadWithoutSnapshot, "Can't prepare async invocation with snapshot if doing async without snapshots");

        if (_snapshot == null)
        {
            if (_connection?.InnerConnection is SqlInternalConnection sqlInternalConnection)
            {
                _snapshot = Interlocked.Exchange(ref sqlInternalConnection.CachedDataReaderSnapshot, null) ?? new Snapshot();
            }
            else
            {
                _snapshot = new Snapshot();
            }

This means that we are saving the reader snapshot on the shared resource, which can be overwritten by any other reader.
Also a reader can receive another reader's snapshot.
@Wraith2 have you had a chance to pursue this line of investigation for hanging test?
I wonder if the timing is causing the wrong cached snapshot to be provided to a SqlDataReader, causing data corruption and likely causing a hang.

SqlInternalConnection.cs

#if NET6_0_OR_GREATER
        internal SqlCommand.ExecuteReaderAsyncCallContext CachedCommandExecuteReaderAsyncContext;
        internal SqlCommand.ExecuteNonQueryAsyncCallContext CachedCommandExecuteNonQueryAsyncContext;
        internal SqlCommand.ExecuteXmlReaderAsyncCallContext CachedCommandExecuteXmlReaderAsyncContext;

        internal SqlDataReader.Snapshot CachedDataReaderSnapshot;
        internal SqlDataReader.IsDBNullAsyncCallContext CachedDataReaderIsDBNullContext;
        internal SqlDataReader.ReadAsyncCallContext CachedDataReaderReadAsyncContext;
#endif

@Wraith2  I see that you had made the changes in the first place. Can you try another PR where you remove the storage of these contexts and snapshots on SqlInternalConnection and with the multiplexing change, try to see if this solves the problem.

The snapshot caching has been present for a long time now and it's cleared and never moves between owners. The snapshot lifetime is dealt with by the async prepare and related functions which are highly conserved between both versions of the driver.
The cached async context objects are kept on the internal connection because that's the long-lived objects that is kept in the pool. Their ownership is opportunistic so if one is present on the internal connection it is always safe to use (see the Clear method on the base object for lifetime management) and if one isn't present then a new one is created. We could remove those caches for a small memory cost on repeated async operations but there's been no indication that they're in any way involved in a problem.

I see. So its necessarily an object for anyone to grab/reset and then reuse? Is this correct ?

The async contexts, yes. All of them should be used through interlocks.

@Wraith2  Have you looked at this failure ?
[xUnit.net 00:05:24.42]       Microsoft.Data.SqlClient.SqlException : Transaction (Process ID 138) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
  [xUnit.net 00:05:24.42]     Microsoft.Data.SqlClient.ManualTesting.Tests.BatchTests.MixedBatchSupported [FAIL]
  [xUnit.net 00:05:24.42]       Stack Trace:
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlConnection.cs(2132,0): at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlInternalConnection.cs(773,0): at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(1436,0): at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, SqlCommand command, Boolean callerHasConnectionLock, Boolean asyncClose)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(2699,0): at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs(5298,0): at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs(5168,0): at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean isAsync, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs(4845,0): at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String method)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs(1701,0): at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry, String methodName)
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs(1221,0): at Microsoft.Data.SqlClient.SqlCommand.ExecuteNonQuery()
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlBatch.cs(92,0): at Microsoft.Data.SqlClient.SqlBatch.ExecuteNonQuery()
  [xUnit.net 00:05:24.42]         /_/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Batch/BatchTests.cs(117,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.BatchTests.MixedBatchSupported()
  [xUnit.net 00:05:24.42]            at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
  [xUnit.net 00:05:24.42]            at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

I did, it doesn't repro locally.
On the topic of reproducing problems. I've build an ubuntu 22.04 vm and installed rider to allow me to build this project. The tests require runtime version 2.1 for some reason and that isn't available (and hasn't been for a long time) on any supported ubuntu build. How are you running development environments on linux to investigate things? Is there some magic way to get netcore2.1 onto ubuntu that i can't find?

I personally use the Ubuntu distribution with the .Net runtime and mostly use command line to launch the tests, and leverage console logs and traces.
In case I need to attach a debugger I use VS on windows with ssh remote debugging.

I'm trying the linux thing again. The buildguide should be up to date but it's not helping. For example, the commands list just running msbuild but that's not available, the only option is to use dotnet msbuild which I can do but it doesn't reflect well on the accuracy. The build doesn't work because it can't find powershell. I have powershell installed but the executable is just called pwsh.
Have you had any luck getting a linux system build and working? has anyone else?

wraith@UbuntuDev2204:~/RiderProjects/SqlClient$ dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections"
Build started 13/09/2024 22:11:16.
Test run for /home/wraith/RiderProjects/SqlClient/artifacts/Project/bin/Unix/Release.AnyCPU.ManualTests/netcoreapp2.1/ManualTests.dll (.NETCoreApp,Version=v2.1)
Microsoft (R) Test Execution Command Line Tool Version 17.3.3 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

Passed!  - Failed:     0, Passed:     1, Skipped:     0, Total:     1, Duration: < 1 ms - /home/wraith/RiderProjects/SqlClient/artifacts/Project/bin/Unix/Release.AnyCPU.ManualTests/netcoreapp2.1/ManualTests.dll (netcoreapp2.1)

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:41.22

You can find the command from the CI logs (e.g. link to log) actually, in this case the command run on Unix agents is:
dotnet msbuild -t:BuildAll -p:TestEnabled=true -p:GenerateDocumentationFile=false -p:configuration=Release
I only needed to install dotnet SDKs (8.0 and 6.0) and PowerShell on Ubuntu 22 in order to run this command successfully.

Install PowerShell on Ubuntu 22
Install .NET SDK 8
Install .NET SDK 6.0

Further steps to build and run steps are also available in logs likewise.
Note: These steps don't apply to WSL.

Getting those items installed on the right version of Ubuntu didn't prove to be simple. It would also have been good to know that it has to be done on Ubuntu 2204 not 2404 because of package availability. Even with those things installed the test does not fail on my machine, as you can see from https://github.com/dotnet/SqlClient/pull/2714#issuecomment-2350234043 , and i cannot use remote debug over ssh to try and step through i can only run locally.
So all in all a month mostly wasted.

@Wraith2
I finally got the error to repro. Haven't debugged anything, yet. But here's my setup:
Installed Ubuntu 22.04 under WSL (install Ubuntu 22.04 from Microsoft Store).
Install PowerShell on Ubuntu: https://learn.microsoft.com/en-us/powershell/scripting/install/install-ubuntu?view=powershell-7.4#installation-via-package-repository-the-package-repository
Set MS packages repo preferred over Ubuntu's to avoid .NET errors wrt package conflicts. Create /etc/apt/99microsoft-dotnet.pref
Package: dotnet* aspnet* netstandard*
Pin: origin "archive.ubuntu.com"
Pin-Priority: -10

Package: dotnet* aspnet* netstandard*
Pin: origin "security.ubuntu.com"
Pin-Priority: -10

sudo apt update

Install .NET 6.0 and 8.0 SDKs:
sudo apt-get install dotnet-sdk-6.0 dotnet-sdk-8.0

Clone SqlClient and checkout branch:
git clone https://github.com/Wraith2/SqlClient
cd SqlClient
git checkout operation-status-part2

Define src/Microsoft.Data.SqlClient/tests/tools/Microsoft.Data.SqlClient.TestUtilities/config.json I pointed it at the IP that resolved to SQL Server on my machine outside of WSL, which already had Northwind created. Use nslookup <host machine name> for a list of potential IP addresses this might be in your Ubuntu instance.
{
    "TCPConnectionString": "Data Source=tcp:<IP_ADDRESS>;Database=Northwind;user id=sa;password=*****;Encrypt=f
alse;",
    "NPConnectionString": "Data Source=np:<IP_ADDRESS>;Database=Northwind;user id=sa;password=*****;Encrypt=fal
se;",
    "TCPConnectionStringHGSVBS": "",
    "TCPConnectionStringNoneVBS": "",
    "TCPConnectionStringAASSGX": "",
    "EnclaveEnabled": false,
    "TracingEnabled": false,
    "AADAuthorityURL": "",
    "AADPasswordConnectionString": "",
    "AADServicePrincipalId": "",
    "AADServicePrincipalSecret": "",
    "AzureKeyVaultURL": "",
    "AzureKeyVaultTenantId": "",
    "SupportsIntegratedSecurity": false,
    "LocalDbAppName": "",
    "LocalDbSharedInstanceName": "",
    "SupportsFileStream": false,
    "FileStreamDirectory": "",
    "UseManagedSNIOnWindows": false,
    "DNSCachingConnString": "",
    "DNSCachingServerCR": "",
    "DNSCachingServerTR": "",
    "IsDNSCachingSupportedCR": false,
    "IsDNSCachingSupportedTR": false,
    "IsAzureSynapse": false,
    "EnclaveAzureDatabaseConnString": "",
    "ManagedIdentitySupported": false,
    "UserManagedIdentityClientId": "",
    "PowerShellPath": "",
    "AliasName": ""
}

Restore NuGets:
cd src/Microsoft.Data.SqlClient/tests/ManualTests/
# or it might have been cd src/Microsoft.Data.SqlClient/tests/tools/Microsoft.Data.SqlClient.ExtUtilities/
# restoring one of these gets you past the failed to download package error from the feed on the root restore
dotnet restore
cd ~SqlClient
dotnet restore

Build
cd ~SqlClient
dotnet msbuild build.proj -t:BuildTestsNetCore -p:TF=net8.0 -p:TestSet=1 -p:ReferenceType=Project -p:OSGroup=Unix -p:platform=AnyCPU -p:Configuration=Release
dotnet msbuild build.proj -t:RunFunctionalTests -p:TF=net8.0 -p:TestSet=1 -p:ReferenceType=Project -p:platform=AnyCPU -p:Configuration=Release
dotnet msbuild build.proj -t:RunManualTests -p:TF=net8.0 -p:TestSet=1 -p:ReferenceType=Project -p:platform=AnyCPU -p:Configuration=Release
# Test fails in the above run
# Subsequent runs of just the one test fail for me, too
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections"

Hopefully I didn't miss any steps. I am leaving out a bunch of commands that failed to resolve the various issues I encountered just to get tests to run. My hope is this will get you to a point where you can actually debug the issue.

That works flawlessly up until the build part.
wraith@Ubuntu:~/SqlClient$ dotnet msbuild
MSBuild version 17.11.4+37eb419ad for .NET
  Determining projects to restore...
  All projects are up-to-date for restore.
  Determining projects to restore...
  All projects are up-to-date for restore.
  Determining projects to restore...
  All projects are up-to-date for restore.
    Determining projects to restore...
    All projects are up-to-date for restore.
    Microsoft.Cci.Extensions -> /home/wraith/SqlClient/tools/GenAPI/Microsoft.Cci.Extensions/bin/Release/netstandard2.0/Microsoft.Cci.Extensions.dll
    Microsoft.DotNet.GenAPI -> /home/wraith/SqlClient/tools/GenAPI/Microsoft.DotNet.GenAPI/bin/Release/net6.0/Microsoft.DotNet.GenAPI.dll
    Microsoft.DotNet.GenAPI -> /home/wraith/SqlClient/tools/GenAPI/Microsoft.DotNet.GenAPI/bin/Release/net8.0/Microsoft.DotNet.GenAPI.dll
    Microsoft.DotNet.GenAPI -> /home/wraith/SqlClient/tools/GenAPI/Microsoft.DotNet.GenAPI/bin/Release/net472/Microsoft.DotNet.GenAPI.exe

  Build succeeded.
      0 Warning(s)
      0 Error(s)

  Time Elapsed 00:00:01.13
  Microsoft.SqlServer.Server -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug.AnyCPU/Microsoft.SqlServer.Server/netstandard2.0/Microsoft.SqlServer.Server.dll
  Microsoft.SqlServer.Server -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug.AnyCPU/Microsoft.SqlServer.Server/net46/Microsoft.SqlServer.Server.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug/Microsoft.Data.SqlClient/ref/net6.0/Microsoft.Data.SqlClient.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug/Microsoft.Data.SqlClient/ref/net8.0/Microsoft.Data.SqlClient.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug.AnyCPU/Microsoft.Data.SqlClient/netcore/net8.0/Microsoft.Data.SqlClient.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/Unix/Debug.AnyCPU/Microsoft.Data.SqlClient/netcore/net6.0/Microsoft.Data.SqlClient.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/AnyOS/Debug/Microsoft.Data.SqlClient/ref/net6.0/Microsoft.Data.SqlClient.dll
  Microsoft.Data.SqlClient -> /home/wraith/SqlClient/artifacts/Project/bin/AnyOS/Debug/Microsoft.Data.SqlClient/ref/net8.0/Microsoft.Data.SqlClient.dll
  /usr/bin/sh: 2: /tmp/MSBuildTempwraith/tmp6c4f199d3704486ab7f21105cfc06597.exec.cmd:  /home/wraith/SqlClient/src/../artifacts/Project/tools/net8.0\Microsoft.DotNet.GenAPI.dll: not found
/home/wraith/SqlClient/tools/targets/NotSupported.targets(48,5): error MSB3073: The command " " /home/wraith/SqlClient/src/../artifacts/Project/tools/net8.0\Microsoft.DotNet.GenAPI.dll" "/home/wraith/SqlClient/artifacts/Project/bin/AnyOS/Debug/Microsoft.Data.SqlClient/ref/net8.0/Microsoft.Data.SqlClient.dll" -l:"/home/wraith/.nuget/packages/azure.core/1.38.0/lib/net6.0/;/home/wraith/.nuget/packages/azure.identity/1.11.4/lib/netstandard2.0/;/home/wraith/.nuget/packages/microsoft.bcl.asyncinterfaces/1.1.1/ref/netstandard2.1/;/usr/share/dotnet/packs/Microsoft.NETCore.App.Ref/8.0.8/ref/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.caching.abstractions/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.caching.memory/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.dependencyinjection.abstractions/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.logging.abstractions/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.options/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.extensions.primitives/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identity.client/4.61.3/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identity.client.extensions.msal/4.61.3/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.abstractions/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.jsonwebtokens/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.logging/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.protocols/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.protocols.openidconnect/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.tokens/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/microsoft.sqlserver.server/1.0.0/lib/netstandard2.0/;/home/wraith/.nuget/packages/system.clientmodel/1.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.configuration.configurationmanager/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/system.diagnostics.eventlog/8.0.0/lib/net8.0/;/home/wraith/.nuget/packages/system.identitymodel.tokens.jwt/7.5.0/lib/net8.0/;/home/wraith/.nuget/packages/system.memory.data/1.0.2/lib/netstandard2.0/;/home/wraith/.nuget/packages/system.security.cryptography.protecteddata/8.0.0/lib/net8.0/" -o:"/home/wraith/SqlClient/src/../artifacts/Project/obj/Debug.AnyCPU/Microsoft.Data.SqlClient/netcore//net8.0/Microsoft.Data.SqlClient.notsupported.cs" -t:"Microsoft.Data.SqlClient is not supported on this platform."" exited with code 127. [/home/wraith/SqlClient/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj::TargetFramework=net8.0]
  /usr/bin/sh: 2: /tmp/MSBuildTempwraith/tmp6cd4c5148eef4de6983e6d1ce31ff54f.exec.cmd:  /home/wraith/SqlClient/src/../artifacts/Project/tools/net6.0\Microsoft.DotNet.GenAPI.dll: not found
/home/wraith/SqlClient/tools/targets/NotSupported.targets(48,5): error MSB3073: The command " " /home/wraith/SqlClient/src/../artifacts/Project/tools/net6.0\Microsoft.DotNet.GenAPI.dll" "/home/wraith/SqlClient/artifacts/Project/bin/AnyOS/Debug/Microsoft.Data.SqlClient/ref/net6.0/Microsoft.Data.SqlClient.dll" -l:"/home/wraith/.nuget/packages/azure.core/1.38.0/lib/net6.0/;/home/wraith/.nuget/packages/azure.identity/1.11.4/lib/netstandard2.0/;/home/wraith/.nuget/packages/microsoft.bcl.asyncinterfaces/1.1.1/ref/netstandard2.1/;/home/wraith/.nuget/packages/microsoft.netcore.app.ref/6.0.33/ref/net6.0/;/home/wraith/.nuget/packages/microsoft.extensions.caching.abstractions/6.0.0/lib/netstandard2.0/;/home/wraith/.nuget/packages/microsoft.extensions.caching.memory/6.0.1/lib/netstandard2.0/;/home/wraith/.nuget/packages/microsoft.extensions.dependencyinjection.abstractions/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.extensions.logging.abstractions/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.extensions.options/6.0.0/lib/netstandard2.1/;/home/wraith/.nuget/packages/microsoft.extensions.primitives/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identity.client/4.61.3/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identity.client.extensions.msal/4.61.3/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.abstractions/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.jsonwebtokens/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.logging/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.protocols/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.protocols.openidconnect/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.identitymodel.tokens/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/microsoft.sqlserver.server/1.0.0/lib/netstandard2.0/;/home/wraith/.nuget/packages/microsoft.win32.systemevents/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.clientmodel/1.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.configuration.configurationmanager/6.0.1/lib/net6.0/;/home/wraith/.nuget/packages/system.drawing.common/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.identitymodel.tokens.jwt/7.5.0/lib/net6.0/;/home/wraith/.nuget/packages/system.memory.data/1.0.2/lib/netstandard2.0/;/home/wraith/.nuget/packages/system.security.cryptography.protecteddata/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.security.permissions/6.0.0/lib/net6.0/;/home/wraith/.nuget/packages/system.windows.extensions/6.0.0/lib/net6.0/" -o:"/home/wraith/SqlClient/src/../artifacts/Project/obj/Debug.AnyCPU/Microsoft.Data.SqlClient/netcore//net6.0/Microsoft.Data.SqlClient.notsupported.cs" -t:"Microsoft.Data.SqlClient is not supported on this platform."" exited with code 127. [/home/wraith/SqlClient/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj::TargetFramework=net6.0]
wraith@Ubuntu:~/SqlClient$

I think I missed this as the first build command in my instructions:
dotnet msbuild -t:BuildAll -p:TestEnabled=true -p:GenerateDocumentationFile=false -p:configuration=Release

As far as I can see now there is only one failure:
2024-10-02T02:15:37.6634123Z     Failed Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [426 ms]
2024-10-02T02:15:37.6654484Z EXEC : error Message:  [/mnt/vss/_work/1/s/build.proj]
2024-10-02T02:15:37.6656848Z      Assert.Throws() Failure: Exception type was not an exact match
2024-10-02T02:15:37.6657452Z   Expected: typeof(System.Threading.Tasks.TaskCanceledException)
2024-10-02T02:15:37.6657932Z   Actual:   typeof(System.InvalidOperationException)
2024-10-02T02:15:37.6658699Z   ---- System.InvalidOperationException : Internal connection fatal error.
2024-10-02T02:15:37.6659128Z     Stack Trace:
2024-10-02T02:15:37.6659776Z        at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync() in /_/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 35

On a single run. The error message isn't related to what i'm doing so the failure could be real and transient. Can anyone see any errors I'm missing in the current CI run? Can someone re-run that leg and see if it repeats?

@Wraith2 there are 2 issues:

Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections test is stuck on .NET 6 + Ubuntu 20. I located that test by comparing Set 1 of test results with the terminated job.
Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync failed on .NET 8 + Ubuntu 20.
Expected: typeof(System.Threading.Tasks.TaskCanceledException)
Actual:   typeof(System.InvalidOperationException)
I can rerun the tests to see if they pass this time, but you can use both tests for investigation.

Using the same setup I used before except building and testing for TestSet 2:
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync"
dotnet msbuild build.proj -t:RunFunctionalTests -p:TF=net8.0 -p:TestSet=2 -p:ReferenceType=Project -p:platform=AnyCPU -p:Configuration=Release
dotnet msbuild build.proj -t:RunManualTests -p:TF=net8.0 -p:TestSet=2 -p:ReferenceType=Project -p:platform=AnyCPU -p:Configuration=Release

My initial run of manual tests passed. So I started running the single test repeatedly:
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync"

My seventh run of DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync failed. More runs (not automated) resulted in what was about 10% of them failing. That test doesn't show up as failing regularly in the CI, so it's a bit suspicious.

@Wraith2 there are 2 issues:

Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections test is stuck on .NET 6 + Ubuntu 20. I located that test by comparing Set 1 of test results with the terminated job.
Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync failed on .NET 8 + Ubuntu 20.
Expected: typeof(System.Threading.Tasks.TaskCanceledException)
Actual:   typeof(System.InvalidOperationException)
I can rerun the tests to see if they pass this time, but you can use both tests for investigation.

I did see the cancelled run later after i'd posted. It's a bit odd. I can add in some extra code to timeout the parallel wait after 10 seconds and print information about what is still being waited for.
Not sure on the cancellation token. I'll have to look into it. Have you guys picked up any ideas while you've been investigating? any thoughts on the code or functionality?

I can't replicate the Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync issue. What sql server connection are you using. Local network-local or azure?
Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync(runNo: 56248) [3 ms]
[xUnit.net 00:06:02.05]   Finished:    ManualTests
  Passed

Test Run Successful.
Total tests: 100000
     Passed: 100000
 Total time: 6.0426 Minutes

I can't replicate the Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync issue. What sql server connection are you using. Local network-local or azure?

Same setup as before. MDS is running under Ubuntu 22.04 WSL and connecting to SQL 2022 installed locally under Windows.
I just ran it again (this command):
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync"

and it failed the second time.

Exactly the same setup. I even tried both release and debug modes to see if any assertions fired. Nothing. I think 100,000 passing iterations means it isn't going to replicate. I also can't get the previous test we were looking at to stall even though I have seen it do that before the latest commit.

FWIW I managed to replicate the failure CancellationTokenIsRespected_ReadAsync after 141 iterations on my system.
An issue I ran into with replicating it is that I had to remove -p:TestSet=1 from the BuildTestsNetCore command, otherwise it didn't find that test. So this is the command list:
dotnet msbuild -t:BuildAll -p:TestEnabled=true -p:GenerateDocumentationFile=false -p:configuration=Release
dotnet msbuild build.proj -t:BuildTestsNetCore -p:TF=net8.0 -p:ReferenceType=Project -p:OSGroup=Unix -p:platform=AnyCPU -p:Configuration=Release
# Then run the following line until failure
dotnet test "src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync"

Full output of failed test
Build started 10/13/2024 22:29:46.
Test run for /home/oron/SqlClient/artifacts/Project/bin/Unix/Release.AnyCPU.ManualTests/net8.0/ManualTests.dll (.NETCoreApp,Version=v8.0)
VSTest version 17.11.1 (x64)

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.5.5+28b46ff510 (64-bit .NET 8.0.10)
[xUnit.net 00:00:00.08]   Discovering: ManualTests (method display = ClassAndMethod, method display options = None)
[xUnit.net 00:00:00.50] ManualTests: Non-serializable data ('System.Object[]') found for 'Microsoft.Data.SqlClient.ManualTesting.Tests.CertificateTestWithTdsServer.BeginWindowsConnectionTest'; falling back to single test case.
[xUnit.net 00:00:00.50] ManualTests: Non-serializable data ('System.Object[]') found for 'Microsoft.Data.SqlClient.ManualTesting.Tests.CertificateTestWithTdsServer.BeginLinuxConnectionTest'; falling back to single test case.
[xUnit.net 00:00:00.64]   Discovered:  ManualTests (found 888 test cases)
[xUnit.net 00:00:00.64]   Starting:    ManualTests (parallel test collections = on [24 threads], stop on fail = off)
[xUnit.net 00:00:00.71]     Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [FAIL]
[xUnit.net 00:00:00.71]       Assert.Throws() Failure: Exception type was not an exact match
[xUnit.net 00:00:00.71]       Expected: typeof(System.Threading.Tasks.TaskCanceledException)
[xUnit.net 00:00:00.71]       Actual:   typeof(System.InvalidOperationException)
[xUnit.net 00:00:00.71]       ---- System.InvalidOperationException : Internal connection fatal error.
[xUnit.net 00:00:00.71]       Stack Trace:
[xUnit.net 00:00:00.71]         /home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(35,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync()
[xUnit.net 00:00:00.71]         --- End of stack trace from previous location ---
[xUnit.net 00:00:00.71]         ----- Inner Stack Trace -----
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(2068,0): at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(1951,0): at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(8100,0): at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj)
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(365,0): at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj)
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs(179,0): at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention()
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs(746,0): at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession()
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(1060,0): at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader)
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(933,0): at Microsoft.Data.SqlClient.SqlDataReader.Close()
[xUnit.net 00:00:00.71]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(848,0): at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing)
[xUnit.net 00:00:00.71]         /home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(44,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_0.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext()
[xUnit.net 00:00:00.71]         --- End of stack trace from previous location ---
[xUnit.net 00:00:00.72]   Finished:    ManualTests
  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [26 ms]
  Error Message:
   Assert.Throws() Failure: Exception type was not an exact match
Expected: typeof(System.Threading.Tasks.TaskCanceledException)
Actual:   typeof(System.InvalidOperationException)
---- System.InvalidOperationException : Internal connection fatal error.
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync() in /home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 35
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 2068
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 1951
   at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 8100
   at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 365
   at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs:line 179
   at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession() in /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs:line 746
   at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 1060
   at Microsoft.Data.SqlClient.SqlDataReader.Close() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 933
   at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 848
   at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_0.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext() in /home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 44
--- End of stack trace from previous location ---

Test Run Failed.
Total tests: 1
     Failed: 1
 Total time: 1.1320 Seconds
     1>Project "/home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" on node 1 (VSTest target(s)).
     1>Project "/home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (1) is building "/home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (1:2) on node 1 (VSTest target(s)).
     1>_VSTestConsole:
         MSB4181: The "VSTestTask" task returned false but did not log an error.
     1>Done Building Project "/home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (VSTest target(s)) -- FAILED.
     1>DispatchToInnerBuildsWithVSTestTarget:
         Build continuing because "ContinueOnError" on the task "MSBuild" is set to "ErrorAndContinue".
     1>Done Building Project "/home/oron/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (VSTest target(s)) -- FAILED.

Build FAILED.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:01.63

Could that behaviour be triggered if the SQL Server is distant or under load? We cancel the CancellationToken in the first iteration of the SqlDataReader.ReadAsync loop and this sends an Attention packet to the SQL Server, but the SQL Server might coincidentally not acknowledge the packet until Dispose is about to run (or already running.)
Alternatively, the DONE token containing the acknowledgement might be straddling packets. I could imagine this happening if the SQL Server is able to queue a few hundred rows into the TDS stream before the client cancels - so in this case, it'd probably be a result of network latency.
Incidentally, the InvalidOperationException is the result of TdsParser encountering an invalid token value.

From my (not so scientific) testing, running a CPU stress test at the same time increases the likelyhood of an error. Especially with tests that use a lot of RAM. Still does not reproduce every time though, with the right test it can average <10 iterations (IntelBurnTest at maximum level, Prime95 sometimes, MemTestPro at near 100% usage).
This is with SQL Server and the test running on the same system according to David-Engel WSL2 setup. Maybe worth testing on a separate/distant machine. I'm still not convinced this isn't dependent on hardware or some other obscure factor.

On 14/10/2024 07:49 IDT Edward Neal @.***> wrote:
Could that behaviour be triggered if the SQL Server is distant or under load? We cancel the CancellationToken in the first iteration of the SqlDataReader.ReadAsync loop and this sends an Attention packet to the SQL Server, but the SQL Server might coincidentally not acknowledge the packet until Dispose is about to run (or already running.)
Alternatively, the DONE token containing the acknowledgement might be straddling packets. I could imagine this happening if the SQL Server is able to queue a few hundred rows into the TDS stream before the client cancels - so in this case, it'd probably be a result of network latency.
Incidentally, the InvalidOperationException is the result of TdsParser encountering an invalid token value.
—
Reply to this email directly, view it on GitHub https://github.com/dotnet/SqlClient/pull/2714#issuecomment-2409939451, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABHFFDBX2QMDPX4CKH4CI7DZ3NENXAVCNFSM6AAAAABLNIFAIKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDIMBZHEZTSNBVGE.
You are receiving this because you commented.Message ID: @.***>

Could that behaviour be triggered if the SQL Server is distant or under load? We cancel the CancellationToken in the first iteration of the SqlDataReader.ReadAsync loop and this sends an Attention packet to the SQL Server, but the SQL Server might coincidentally not acknowledge the packet until Dispose is about to run (or already running.)

It  seems likely. I'm fairly sure that this is some sort of timing issue because it's happening easily on CI (low resources), fairly easily on other people's machines (assuming David is on a laptop). And not to me on an old but still reasonably fast machine with many cores. Cpu loading with a stress test causing the frequency of error to increase agrees with that general idea.

Alternatively, the DONE token containing the acknowledgement might be straddling packets.

This can't happen. It couldn't happen before my changes because there was packet header reconstruction. It can't happen now because there's still packet header reconstruction and is no full packet reconstruction. The done variations are all in the status flag of the packet header.

Incidentally, the InvalidOperationException is the result of TdsParser encountering an invalid token value.

Yes. and there are only 2 places in the runloop that it can be raised as an invalid operation due to this getting queued to the error set and then thrown later. The crucial thing I need to know is why. Catching this at the point of failure isn't enough because I need to understand what prior decision caused it to reach the invalid state. It seems likely to me that this is a similar issue to the one I've already fixed in src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.Multiplexer.cs where I needed to change the packet handling so that even though a snapshot was present the packet containing the done token (result of cancel ack from server) was added to the snapshot and left in the current packet buffer because something required that behaviour.
Until I can deterministically reproduce the problem I can't debug it properly because I have to know that it's going to error and follow the handling of all the packets to understand the decision path.

It's a bit ambiguous whether it's down to high CPU usage impacting SqlClient, high CPU usage leading to latency between the SQL Server instance and SqlClient, or both. I think it's a little more likely to be the latter; if that's the case, we might be able to make the failure case more likely by testing with a distant Azure SQL instance. I'll try this within the next few days.
Would the TDSServer project help to make this deterministic? This has a hook for TDS Attention responses, and if there were a few debug hooks inside TdsParser, it could be synchronised with the TDSServerParser's response handling.
Looking a bit more broadly, could we have the trace logs from a few failed test runs?

It seems to be more correlated with host cpu speed than latency. On a slow cpu I can repro the CancelAsyncConnections hang with a remote sql server, on a fast one I can't. Of course this makes trying to track it down miserable.

Could someone with access restart the CI legs please. All linux legs failed so assume infra problem.
Could anyone who has managed to repro the problem please try again with the latest commit and let me know if it still fails. I could repro without it, and with it I can't anymore (again).

We're noticing issues with Linux job agents as they're currently not provisioned for running CI jobs. We're working on it and will rerun pipelines when this is resolved.

Ok, can you try it locally?

I'm rerunning locally. Figures WSL would break on me right when I need it... (couldn't launch Ubuntu earlier - finally fixed it)

I pulled the latest and reran my scenario. It looks like the latest fix addressed the source of the error. 🚀
However, I put the single test in a loop and ran it 100 times.
dotnet msbuild -t:BuildAll -p:TestEnabled=true -p:GenerateDocumentationFile=false -p:configuration=Release
dotnet msbuild build.proj -t:BuildTestsNetCore -p:TF=net8.0 -p:ReferenceType=Project -p:OSGroup=Unix -p:platform=AnyCPU -p:Configuration=Release

for i in {1..100}; do
    echo Run: $i
    dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.AsyncCancelledConnectionsTest.CancelAsyncConnections"
    if [ $? -ne 0 ]; then
        echo "Error encountered. Exiting loop."
        break
    fi
done

First two times, it hung somewhere around iteration 20-30 (I didn't have it printing iteration # at the time). It might have just been a fluke as the third run ran all the way through 100. I'm running it some more to see if it hangs again.

So at least it's better. Can you try CancellationTokenIsRespected_ReadAsync as well?

I was only running TestSet=1 before. That one fails pretty consistently:
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync"

Build started 10/17/2024 15:13:11.
Test run for /home/user1/Source/SqlClient-Wraith2/artifacts/Project/bin/Unix/Release.AnyCPU.ManualTests/net8.0/ManualTests.dll (.NETCoreApp,Version=v8.0)
VSTest version 17.11.0 (x64)

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.5.5+28b46ff510 (64-bit .NET 8.0.8)
[xUnit.net 00:00:00.07]   Discovering: ManualTests (method display = ClassAndMethod, method display options = None)
[xUnit.net 00:00:00.51] ManualTests: Non-serializable data ('System.Object[]') found for 'Microsoft.Data.SqlClient.ManualTesting.Tests.CertificateTestWithTdsServer.BeginWindowsConnectionTest'; falling back to single test case.
[xUnit.net 00:00:00.51] ManualTests: Non-serializable data ('System.Object[]') found for 'Microsoft.Data.SqlClient.ManualTesting.Tests.CertificateTestWithTdsServer.BeginLinuxConnectionTest'; falling back to single test case.
[xUnit.net 00:00:00.64]   Discovered:  ManualTests (found 888 test cases)
[xUnit.net 00:00:00.65]   Starting:    ManualTests (parallel test collections = on [8 threads], stop on fail = off)
[xUnit.net 00:00:00.72]     Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [FAIL]
[xUnit.net 00:00:00.72]       Assert.Throws() Failure: Exception type was not an exact match
[xUnit.net 00:00:00.72]       Expected: typeof(System.Threading.Tasks.TaskCanceledException)
[xUnit.net 00:00:00.72]       Actual:   typeof(System.InvalidOperationException)
[xUnit.net 00:00:00.72]       ---- System.InvalidOperationException : Internal connection fatal error.
[xUnit.net 00:00:00.72]       Stack Trace:
[xUnit.net 00:00:00.72]         /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(35,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync()
[xUnit.net 00:00:00.72]         --- End of stack trace from previous location ---
[xUnit.net 00:00:00.72]         ----- Inner Stack Trace -----
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(2068,0): at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(1951,0): at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(8100,0): at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj)
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(365,0): at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj)
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs(179,0): at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention()
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs(746,0): at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession()
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(1060,0): at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader)
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(933,0): at Microsoft.Data.SqlClient.SqlDataReader.Close()
[xUnit.net 00:00:00.72]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(848,0): at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing)
[xUnit.net 00:00:00.72]         /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(44,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_0.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext()
[xUnit.net 00:00:00.72]         --- End of stack trace from previous location ---
[xUnit.net 00:00:00.73]   Finished:    ManualTests
  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [27 ms]
  Error Message:
   Assert.Throws() Failure: Exception type was not an exact match
Expected: typeof(System.Threading.Tasks.TaskCanceledException)
Actual:   typeof(System.InvalidOperationException)
---- System.InvalidOperationException : Internal connection fatal error.
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync() in /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 35
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 2068
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 1951
   at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 8100
   at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 365
   at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs:line 179
   at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession() in /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs:line 746
   at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 1060
   at Microsoft.Data.SqlClient.SqlDataReader.Close() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 933
   at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 848
   at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_0.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext() in /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 44
--- End of stack trace from previous location ---

Test Run Failed.
Total tests: 1
     Failed: 1
 Total time: 1.1237 Seconds
     1>Project "/home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" on node 1 (VSTest target(s)).
     1>Project "/home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (1) is building "/home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (1:2) on node 1 (VSTest target(s)).
     1>_VSTestConsole:
         MSB4181: The "VSTestTask" task returned false but did not log an error.
     1>Done Building Project "/home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (VSTest target(s)) -- FAILED.
     1>DispatchToInnerBuildsWithVSTestTarget:
         Build continuing because "ContinueOnError" on the task "MSBuild" is set to "ErrorAndContinue".
     1>Done Building Project "/home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" (VSTest target(s)) -- FAILED.

Build FAILED.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:01.62

I'll have to run with all TestSets, too, to double validate.

I can't replicate any failure with CancellationTokenIsRespected_ReadAsync and bizzarely my ubuntu wsl has also decided that it's not able to run .net programs anymore, is that what happened to yours?

My WDL issue was something about network device permissions when trying to start ubuntu. A custom .wslconfig file resolved it.
I just finished all tests and got one error:
[xUnit.net 00:16:32.86]     Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth [FAIL]
  [xUnit.net 00:16:32.87]       Notification not received within the timeout period
  [xUnit.net 00:16:32.87]       Stack Trace:
  [xUnit.net 00:16:32.87]         /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/SqlNotificationTest/SqlNotificationTest.cs(177,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth()
  [xUnit.net 00:16:32.87]            at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
  [xUnit.net 00:16:32.87]            at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
    Failed Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth [5 s]
EXEC : error Message:  [/home/user1/Source/SqlClient-Wraith2/build.proj]
     Notification not received within the timeout period
    Stack Trace:
       at Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth() in /home/user1/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/SqlNotificationTest/SqlNotificationTest.cs:line 177
     at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
     at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

The other one fails ~1 in 4 runs.
for i in {1..100}; do     echo Run: $i;     dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync";     if [ $? -ne 0 ]; then         echo "Error encountered. Exiting loop.";         break;     fi; done

Unless I see repeated failures on the notifications issue I'm going to assume it's a random for now. There's no prior indication of notifications being affected and they don't use out of band packets as far as I know so it's unlikely to be related to this cancellation issue.
I ran your loop, no failures.
Can you try it in Debug mode and see if it still replicates? I was able to get the previous test to replicate in debug and that helped track it down, there are also assertions in the snapshot code to flag up invalid conditions and if those hit it'll be informative. If there is a snapshot involved (check the _snapshot) then you can look at the sequence numbers of the packets to see if they're sequential and make sure the same packet isn't being added multiple times which is the bug I just fixed.

I've uploaded a dotnet dump here
As far as I can tell _attentionSent is true, but _snapshottedState is 0, so I think attentionReceived is not set?
Unfortunately I'm not skilled enough to tell if the packets make sense or not :)
_firstPacket and _lastPacket (first 8 bytes) seem to be identical with 0x04 0x01 0x06 0x0F 0x00 0x45 0x01 0x00

first and last packets are two ends of a doubly linked list so the start and end being the same can mean that there is only one packet in the list, if that's the case then it looks like in that case we've entirely missed the attention packet because as you point out the snapshot state doesn't have attention received. So where did the packet go? did we get it and drop it somehow? or did it never arrive?
To understand the packets you can read small parts of the spec here https://learn.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/b46a581a-39de-4745-b076-ec4dbb7d13ec and it's the first 8 bytes which are defined in section <IP_ADDRESS>, it's a byte of Type (likely to be 4), a byte of Status, 2 bytes of Length, 2bytes of SPID (should be the same for all packets on a non-mars connection), 2 bytes of PacketID (should be sequential). So on a connection that has failed to receive attention we need to know if that attention packet arrived or not and I don't think we have a good way to do that so you might need to add some debug logging. If it arrived and the code lost it in the multiplexer then it's my fault and i need to understand how it happened. if it never arrived it's an sql server problem.

I did get an error for Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync just now (Debug build - a DebugAssert thrown):

[xUnit.net 00:00:33.83]     Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [FAIL]
[xUnit.net 00:00:33.83]       Assert.Throws() Failure: Exception type was not an exact match
[xUnit.net 00:00:33.83]       Expected: typeof(System.Threading.Tasks.TaskCanceledException)
[xUnit.net 00:00:33.83]       Actual:   typeof(Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException)
[xUnit.net 00:00:33.83]       ---- Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException : Method Debug.Fail failed with 'unexpected token; token = 00
[xUnit.net 00:00:33.83]       ', and was translated to Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException to avoid terminating the process hosting the test.
[xUnit.net 00:00:33.83]       Stack Trace:
[xUnit.net 00:00:33.83]         /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(35,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync()
[xUnit.net 00:00:33.83]         --- End of stack trace from previous location ---
[xUnit.net 00:00:33.83]         ----- Inner Stack Trace -----
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(2064,0): at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(1951,0): at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(8100,0): at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj)
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs(365,0): at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj)
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs(179,0): at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention()
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs(746,0): at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession()
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(1005,0): at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader)
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(933,0): at Microsoft.Data.SqlClient.SqlDataReader.Close()
[xUnit.net 00:00:33.83]         /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs(848,0): at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing)
[xUnit.net 00:00:33.83]         /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs(40,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_1.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext()
[xUnit.net 00:00:33.83]            at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[xUnit.net 00:00:33.83]            at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
[xUnit.net 00:00:33.83]            at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
[xUnit.net 00:00:33.83]            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
[xUnit.net 00:00:33.83]
[xUnit.net 00:00:33.84]   Finished:    ManualTests
[xUnit.net 00:00:33.84] Canceling due to test failure...
  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync [27 ms]
  Error Message:
   Assert.Throws() Failure: Exception type was not an exact match
Expected: typeof(System.Threading.Tasks.TaskCanceledException)
Actual:   typeof(Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException)
---- Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException : Method Debug.Fail failed with 'unexpected token; token = 00
', and was translated to Microsoft.VisualStudio.TestPlatform.TestHost.DebugAssertException to avoid terminating the process hosting the test.
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync() in /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 35
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 2064
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 1951
   at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 8100
   at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 365
   at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs:line 179
   at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession() in /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs:line 746
   at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 1005
   at Microsoft.Data.SqlClient.SqlDataReader.Close() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 933
   at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 848
   at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_1.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext() in /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 40
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)

That's a very useful piece of information. It shows that it's not failing in packet handling code but that there's something wrong with the packet data somehow. I've just pushed a change with some additional debugging code in. I've added md5 checksums in debug mode to each packet in the snapshot so we will know if something alters a packet. I've also added a state dump to the position in the code for IsValidToken() so the current buffer will be dumped in the assertion or failure exception (depending on debug or release). Can you pull and re-run both those failing tests to see if we get any new behaviour please?

I hope this is helpful....:)

[xUnit.net 00:00:36.09] Canceling due to test failure...

  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync() in /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 35
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 2066
   at Microsoft.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 1951
   at Microsoft.Data.SqlClient.TdsParser.ProcessAttention(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 8109
   at Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(TdsParserStateObject stateObj) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs:line 365
   at Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.netcore.cs:line 179
   at Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession() in /_/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs:line 747
   at Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(Boolean closeReader) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 1005
   at Microsoft.Data.SqlClient.SqlDataReader.Close() in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 933
   at Microsoft.Data.SqlClient.SqlDataReader.Dispose(Boolean disposing) in /_/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs:line 848
   at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.<>c__DisplayClass0_1.<<CancellationTokenIsRespected_ReadAsync>b__0>d.MoveNext() in /home/michelz/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 40
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)

Honestly the information is slightly baffling but I may be able to make something of it. The fill with FF is interesting, the only place I know of in the code that does that is mine in the multiplexer:
#if DEBUG
                        // for debugging purposes fill the removed data area with an easily
                        // recognisable pattern so we can see if it is misused
                        Span<byte> removed = dataBuffer.AsSpan(dataOffset + (dataLength - bytesConsumed), (dataOffset + bytesConsumed));
                        removed.Fill(0xFF);
#endif

This is where it is consuming a partial packet that was produced by a previous run through the loop.
So somehow we got a block of data from the network that is (guessing here) 7317 bytes long but it contained two packets so it's been split apart into two packets, the first was processed correctly and then when the library requested more data the partial packet was present so it attempted to use it. Weirdly the partial packet seems garbled. the header (first 8 bytes) reads: 04 01 00 40 00 33 05 00, 4 is the MT_TOKENS, 1 is ST_EOM, then 00 40 is a hex number for the packet length which should be 64 decimal. That 64 should be 8+data length, so we're expecting 56 bytes following it, one byte we've consumed but there are clearly too many left in the partial packet.
00 //1
unused buffer:
00 00 01 00 00 00 04 00 00  00 06 00 00 00 01 00 // 16+1
00 00 05 00 00 00 02 00 00  00 E4 0B 00 00 00 0D // 32 +1
00 00 00 00 FE 04 03 00 00  00 FD 02 00 C1 00 00 // 48+1
00 00 00 00 00 00 00 04 01  00 15 00 33 01 00 FD // 64 + 1
20 00 FD 00 00 00 00 00 00  00 00 00 // 12 , 76+1 == 73 ?

Given the mistakes that I know I make it's entirely possible that there is a silly calculation mistake somewhere in the partial packet code. My next step would be to put a breakpoint in MultiplexPackets anywhere that i start to construct a partial packet and another near the top where it looks to see if the partial packet is non-null to consume it. Run the test case you're getting this data from and when it breaks have a poke at the data in the dubugger and see if it makes sense. Those first 8 bytes of every packet are the crucial thing to look at, the packet contents themselves I don't understand and we shouldn't be looking at in this layer of the code.
I appreciate your help on this. It's been extremely difficult to replicate these problems because they seem to be timing related. I hope we can keep working through this until we can fix it.

Random observation, that FD near the end, that's the SQL_DONE token, that's probably supposed to be the end of the packet data but we can't use that fact in code it's only useful for debugging this. It may tell us how many bytes offset we are.

Just a small observation, the size 0x00 0x40 is big endian, so IMHO = 0x4000 = 16384… ?

That could be possible if you set the packet size in the connection string. Default packet size is 8K though which is one of the things that leads me to the assumption that the 7317 bytes read number is from two packets, it's near the upper limit but under it. Prodding at the data in the debugger should let you see the data buffer sizes and that's the definitive determining factor in packet size.

Honestly the information is slightly baffling but I may be able to make something of it. The fill with FF is interesting, the only place I know of in the code that does that is mine in the multiplexer:
#if DEBUG
                        // for debugging purposes fill the removed data area with an easily
                        // recognisable pattern so we can see if it is misused
                        Span<byte> removed = dataBuffer.AsSpan(dataOffset + (dataLength - bytesConsumed), (dataOffset + bytesConsumed));
                        removed.Fill(0xFF);
#endif

This is where it is consuming a partial packet that was produced by a previous run through the loop.
So somehow we got a block of data from the network that is (guessing here) 7317 bytes long but it contained two packets so it's been split apart into two packets, the first was processed correctly and then when the library requested more data the partial packet was present so it attempted to use it. Weirdly the partial packet seems garbled. the header (first 8 bytes) reads: 04 01 00 40 00 33 05 00, 4 is the MT_TOKENS, 1 is ST_EOM, then 00 40 is a hex number for the packet length which should be 64 decimal. That 64 should be 8+data length, so we're expecting 56 bytes following it, one byte we've consumed but there are clearly too many left in the partial packet.
00 //1
unused buffer:
00 00 01 00 00 00 04 00 00  00 06 00 00 00 01 00 // 16+1
00 00 05 00 00 00 02 00 00  00 E4 0B 00 00 00 0D // 32 +1
00 00 00 00 FE 04 03 00 00  00 FD 02 00 C1 00 00 // 48+1
00 00 00 00 00 00 00 04 01  00 15 00 33 01 00 FD // 64 + 1
20 00 FD 00 00 00 00 00 00  00 00 00 // 12 , 76+1 == 73 ?

It looks like a DONE packet is at end here, right?
FD = DONE_TOKEN
0020 = DONE_ATTN
00FD = CUR_CMD
00 00 00 00 00 00 00 00 = DoneRowCount
https://learn.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/3c06f110-98bd-4d5b-b836-b1ba66452cb7

Yes but the more I think about this the less I want to rely on the contents of the packet in any way. We've got a framing problem which means that the packet contents are unreliable, I should not have looked to make sense of the contents.

Yes but the more I think about this the less I want to rely on the contents of the packet in any way. We've got a framing problem which means that the packet contents are unreliable, I should not have looked to make sense of the contents.

If you want to reproduce this on a many-core machine, I was successful by adding this to the CancelAsyncConnections test:
 public void CancelAsyncConnections()
 {
     ThreadPool.SetMinThreads(2, 1);
     ThreadPool.SetMaxThreads(32767, 1000);
     [...]

which basically are the settings that are used by default on my ubuntu 2-core VM.
If you also increase the Sleep Interval for the TimeBomb to close to 3 seconds, I can get a lot of InFlight "hanging" tasks:
private async Task TimeBombAsync(SqlCommand command)
{
    await SleepAsync(2990, 3010);
    command.Cancel();
}

I hope that somehow helps further diagnosing this.

It's 2 different messages in this packet though:
04 01 00 40 00 33 05 00 00 00 00 01 00 00 00 04
00 00 00 06 00 00 00 01 00 00 00 05 00 00 00 02
00 00 00 E4 0B 00 00 00 0D 00 00 00 00 FE 04 03
00 00 00 FD 02 00 C1 00 00 00 00 00 00 00 00 00

04 = Tabular result
01 = End of Message
00 40 = 64 bytes
33 = SPID
05 = Packet ID
00 = Window
Then the I'm not sure about this:
00 00 00 04 00 00 00 06 00 00 00 01 00 00 00 05
00 00 00 02 00 00 00 E4 0B 00 00 00 0D 00 00 00
00 FE 04 03 00 00 00

But this here:
FD 02 00 C1 00 00 00 00 00 00 00 00 00
should be:
FD = DONE
02 00 = DONE_ERROR
C1 00 = CurCmd
00 00 00 00 00 00 00 00 = DoneRowCount
So this is an error message.
Then after that is the Attention Ack message:
04 01 00 15 00 33 01 00 FD 20 00 FD 00 00 00 00
00 00 00 00 00

04 = Tabular result
01 = End Of Message
00 15 = 21 bytes
33 = SPID
01 = Packet ID
00 = Window
FD = DONE
20 00 = DONE_ATTN
FD 00 = CurCmd
00 00 00 00 00 00 00 00 = DoneRowCount
So somehow we think we're trying to read the DONE_ATTN message, but we are at a DONE_ERROR message (with some other data that I'm not sure about)
I also did a packet capture of such an exchange, maybe it helps someone make more sense of it:
Wireshark_CancelledCancellationTokenIsRespected_ReadAsync.zip
And just for completeness, this is the call stack where it fails:
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(bool hold, out byte value) Line 1319	C#
	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior runBehavior, Microsoft.Data.SqlClient.SqlCommand cmdHandler, Microsoft.Data.SqlClient.SqlDataReader dataStream, Microsoft.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, Microsoft.Data.SqlClient.TdsParserStateObject stateObj, out bool dataReady) Line 2072	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.Run(Microsoft.Data.SqlClient.RunBehavior runBehavior, Microsoft.Data.SqlClient.SqlCommand cmdHandler, Microsoft.Data.SqlClient.SqlDataReader dataStream, Microsoft.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, Microsoft.Data.SqlClient.TdsParserStateObject stateObj) Line 1967	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.ProcessAttention(Microsoft.Data.SqlClient.TdsParserStateObject stateObj) Line 8163	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParser.ProcessPendingAck(Microsoft.Data.SqlClient.TdsParserStateObject stateObj) Line 382	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.ResetCancelAndProcessAttention() Line 179	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.TdsParserStateObject.CloseSession() Line 747	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlDataReader.TryCloseInternal(bool closeReader) Line 1062	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlDataReader.Close() Line 936	C#
 	Microsoft.Data.SqlClient.dll!Microsoft.Data.SqlClient.SqlDataReader.Dispose(bool disposing) Line 851	C#
 	ManualTests.dll!Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancelledCancellationTokenIsRespected_ReadAsync.AnonymousMethod__0() Line 87	C#

(Right after the TryReadByte, on  if (!IsValidTdsToken(token)) I've added some more stuff there)

I've been wondering if a TDS packet might be split between TCP packets, but the multiplexer seems to be holding up. I'm struggling to reproduce the failure, but a few points jump out from the packet capture.
The first point is that there's quite a delay between the Attention message from the client and the EOM response from the server. 300ms feels excessive for a server running on localhost, and a lot of data is being sent in the interim.
Would you mind adding logging of each TDS token received by TdsParser please - both valid and invalid?
With that in place, could you take another packet capture of the same failure, including everything with a filter of tcp.port == 1433. I'm interested in seeing both the raw TCP packets, and the TDS packets which Wireshark tries to decode them to. I can then compare the TDS tokens which TdsParser tries to process with the TDS tokens which pass along the wire, and see whether the problematic TDS packet is being split across multiple TCP packets.
Finally: does this occur less frequently if you modify SNITcpHandle.SetKeepAliveValues to also set socket.ReceiveBufferSize to 32768 or 65536?
I ask about ReceiveBufferSize because we use ReceiveAsync in a few places. If the thread pool is heavily contended (to the point where we can't issue the next read as often as we need because we're very rarely able to return from the last one) and the server is continuing to send large amounts of data, I can imagine a case where the socket's receive buffer fills up. I'm interested to see whether this full socket receive buffer is the situation which triggers the issue: it's supposed to trigger TCP flow control behaviour, which should be pretty much transparent. This flow control behaviour should appear in the packet capture.

ReCancelledCancellationTokenIsRespected_ReadAsync which I think is the less complicated of the two because it seems to be quite deterministic and involves fewer packets. My suspicion is that the situation we have is a bit like the one that the BetweenAsyncAttentionPacket test covers. That test was created and added to the PR when I found that the cancellation packet needed to remain in the _inBuff even if it was received during an async operation. This isn't something that the rest of the packet handling requires and is special behaviour that isn't clear at all from the code.
The things I want to know are

what data is received in packets (packet capture will give this, or dumping the received buffer)
what blocks of bytes are they received in (dumping received buffers)
what blocks does the code split them into (dumping buffers at multiplexer return?)
With that information it should be possible to generate a test case to plug into the testharness. The test harness is using the same implementation so it acts exactly as it should, it's just the assertions that we'd need at that point.

We could be seeing one bug or two (or more) but i'd really like to think it's just one since we're working around cancellation in both cases. It's really really frustrating not being able to repro the problem. I've tried on 4 machines now, various sql servers, thread limitations, cpu load etc.

An ssh session to a machine I can repro either issue on would be useful. My email is in my profile.

@Wraith2 please update your branch with main to kick off Ubuntu builds, thanks!

I've managed to dump the packets of the failure in CancelledCancellationTokenIsRespected_ReadAsync and have found that it's hitting the sanity check at the end of the multiplexer method. I've added a debug fail to make it clearer what's going on. I now have a local, but large, reproduction. I don't have a fix yet but it's 2am so I'll look at it tomorrow.

Are you interested in an SSH connection to a machine where you can reproduce this?

Realistically, it'll likely be the weekend before I'll have time (and it looks like Wraith2's a step ahead) but I'd appreciate the connection nonetheless, thanks. If you email github-at-jibberwock.com, I'll be able to pick it up.

The more people who can review the code the better it is for overall stability and confidence. So whether I'm ahead or not it would be helpful to have you do some investigation

/azp run

/azp run

I just rebased to fix the conflicts because they were causing visual studio to find all sorts of problems and underline them where the build wasn't seeing problems.
I haven't fixed the root issue. I think I've made the read cancel respected test hit the same problem as the other test does so the behaviour changes from quickly failing with an invalid operation to slowly timing out. I would like some validation from others on that though. the build on the machine MichelZ has kindly let me access is currently not working because of SqlJson not being found when building the tests which i've no worked out how to fix yet. Once i do there will be more debugging.

I haven't fixed the root issue. I think I've made the read cancel respected test hit the same problem as the other test does so the behaviour changes from quickly failing with an invalid operation to slowly timing out. I would like some validation from others on that though.

Are you looking for this?
[xUnit.net 00:00:31.26] Canceling due to test failure...
  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancelledCancellationTokenIsRespected_ReadAsync [30 s]
  Error Message:
   Cancellation did not trigger on time.
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.DataReaderCancellationTest.CancelledCancellationTokenIsRespected_ReadAsync() in /home/sqlclient/SqlClient/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/DataReaderTest/DataReaderCancellationTest.cs:line 81
--- End of stack trace from previous location ---

Yes. That's the one. That test used to fail quickly with an InvalidOperationException which was due to the safeguard being his. It now times out instead which i think is the same symptom as the other test. I'll keep looking into both.

Just adding more data. I still get intermittent failures in DataReaderCancellationTest.CancellationTokenIsRespected_ReadAsync. But I also get consistent failures for SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth
dotnet test "src\Microsoft.Data.SqlClient\tests\ManualTests\Microsoft.Data.SqlClient.ManualTesting.Tests.csproj" -p:TF=net8.0 -p:TargetnetcoreVersion=net8.0 -p:Platform="AnyCPU" -p:Configuration="Release" -p:TestTargetOS="Unixnetcoreapp" --no-build -v n --filter "FullyQualifiedName=Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth"

[xUnit.net 00:16:57.16]     Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth [FAIL]
[xUnit.net 00:16:57.16]       Notification not received within the timeout period
[xUnit.net 00:16:57.16]       Stack Trace:
[xUnit.net 00:16:57.17]         /home/dengel/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/SqlNotificationTest/SqlNotificationTest.cs(177,0): at Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth()
[xUnit.net 00:16:57.17]            at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
[xUnit.net 00:16:57.17]            at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
  Failed Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth [5 s]
  Error Message:
   Notification not received within the timeout period
  Stack Trace:
     at Microsoft.Data.SqlClient.ManualTesting.Tests.SqlNotificationTest.Test_SingleDependency_AllDefaults_SqlAuth() in /home/dengel/Source/SqlClient-Wraith2/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/SqlNotificationTest/SqlNotificationTest.cs:line 177
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)

Thanks. I'll give that one a look and see if it's a simpler replication than either of the two existing cases.

I've reproduced the problem on the instance @MichelZ provided, (thanks again for this!) and noticed some slightly unusual behaviour which (I think) points us towards TdsParser. In the packet capture I can reproducibly see cases where SQL Server acknowledges the Attention packet by sending two DONE tokens. Is that a scenario you'd expect the parser to handle?
I've attached the packet capture, but I've extracted as much useful information as I can see below. The behaviour I can see is:

Time since capture start (ms)
Packet
Notes

507374
SQL batch

507891 / 508039 / 508176 / 508286 / 508385
Response
Initially, one TCP packet corresponds to one TDS packet - no partial packets

507910 / 508046 / 508180 / 508290 / 508388
TCP ACK
Not a TDS packet - just a TCP level acknowledgement

508476 / 508565 / 508674 / 508753 / 508836
Response
Same TCP/TDS packet alignment

511164
TCP ACK
TCP level acknowledgement of 508836. Not unacceptable - just a behavioural change

716692
Response
We now see three complete TDS packets and one partial packet in a single TCP packet. It looks like the generation of result sets is continuing, but network traffic pauses for 200ms

716716
TCP ZeroWindow
Sent by SqlClient. The receive buffer is full, and is being processed

924659
TCP KeepAlive
Sent by SQL Server, to keep the TCP connection alive, trying to negotiate a new packet size

924674
TCP ZeroWindow
Sent by SqlClient

995483
Attention

998476
TCP window update

998483
Response
One TDS packet per TCP packet

998489
Response
Four complete TDS packets and one partial packet per TCP packet

998508 / 1000002
TCP ACK
Acknowledgement of 998483 and 998489. I won't mention acknowledgements after this point!

1000013 (onwards)
Response
Around 90 separate TCP packets, each containing four or more complete TDS packets and a partial packet

1002311
Response
Final TCP packet, containing six TDS packets. Details below

The final TCP packet is somewhat interesting. TDS packets 1-5 are the same as earlier - just standard Results, all 8000 bytes long. The final two packets are unusual though:
TDS packet 6 (TDS packet ID: 75)
04 01 00 40 00 33 4b 00 00 00 00 01 00 00 00 08
00 00 00 08 00 00 00 01 00 00 00 03 00 00 00 02
00 00 00 e4 0b 00 00 00 01 00 00 00 00 fe 04 03
00 00 00 fd 02 00 c1 00 00 00 00 00 00 00 00 00

The first valid token I see is a SESSIONSTATE (token 0xe4, length 0x0b, sequence number 0x01, fRecoverable = false, state ID = 0xfe, state length = 0x03, state value = [0x03, 0x00, 0x00, 0x00].
The final token in the packet is a DONE token - token 0xfd, status 0x02 (DONE_ERROR), CurCmd = 0xc1, DoneRowCount = 0. The TDS spec states that an earlier ERROR token should have been sent. I can't see this token though.
TDS packet 7 (TDS packet ID: 1)
04 01 00 15 00 33 01 00 fd 20 00 fd 00 00 00 00
00 00 00 00 00

This also contains a second DONE token - token 0xfd, status 0x20 (DONE_ATTN), CurCmd = 0xfd, DoneRowCount = 0.
Thoughts

The stall in network traffic between 716716 and 924659 are probably the space where this instance of the issue first takes shape: it introduces time where SQL Server is generating the row data, but isn't able to send it. That stall comes from the thread pool, which is probably why it only affects the async case.
Although the TCP window resize is occurring, expanding the TCP receive buffer size just pushes the problem further into the future. I had hoped that there was traffic on the thread pool which was associated with the initial burst of tasks from async cancellation (and that expanding the buffer size would spread the demand on the thread pool) but this isn't the case - it's genuine load, not a brief spike.
This bug only appearing rarely on most computers makes a lot of sense - most computers won't strain the thread pool by running a SQL query. Containers probably would though, and there was an issue where somebody noted they had a connectivity problem which was fixed by adding extra cores to the container.

I'm planning to re-run the same test on the main branch to compare output.

[like]  Michel Zehnder reacted to your message:

From: Edward Neal @.>
Sent: Saturday, October 26, 2024 4:59:10 PM
To: dotnet/SqlClient @.>
Cc: Michel Zehnder @.>; Mention @.>
Subject: Re: [dotnet/SqlClient] Add partial packet detection and fixup (PR #2714)
I've reproduced the problem on the instance @MichelZhttps://github.com/MichelZ provided, (thanks again for this!) and noticed some slightly unusual behaviour which (I think) points us towards TdsParser. In the packet capture I can reproducibly see cases where SQL Server acknowledges the Attention packet by sending two DONE tokens. Is that a scenario you'd expect the parser to handle?
I've attachedhttps://github.com/user-attachments/files/17531376/attempt-05.zip the packet capture, but I've extracted as much useful information as I can see below. The behaviour I can see is:
Time since capture start (ms)   Packet  Notes
507374  SQL batch
507891 / 508039 / 508176 / 508286 / 508385      Response        Initially, one TCP packet corresponds to one TDS packet - no partial packets
507910 / 508046 / 508180 / 508290 / 508388      TCP ACK Not a TDS packet - just a TCP level acknowledgement
508476 / 508565 / 508674 / 508753 / 508836      Response        Same TCP/TDS packet alignment
511164  TCP ACK TCP level acknowledgement of 508836. Not unacceptable - just a behavioural change
716692  Response        We now see three complete TDS packets and one partial packet in a single TCP packet. It looks like the generation of result sets is continuing, but network traffic pauses for 200ms
716716  TCP ZeroWindow  Sent by SqlClient. The receive buffer is full, and is being processed
924659  TCP KeepAlive   Sent by SQL Server, to keep the TCP connection alive, trying to negotiate a new packet size
924674  TCP ZeroWindow  Sent by SqlClient
995483  Attention
998476  TCP window update
998483  Response        One TDS packet per TCP packet
998489  Response        Four complete TDS packets and one partial packet per TCP packet
998508 / 1000002        TCP ACK Acknowledgement of 998483 and 998489. I won't mention acknowledgements after this point!
1000013 (onwards)       Response        Around 90 separate TCP packets, each containing four or more complete TDS packets and a partial packet
1002311 Response        Final TCP packet, containing six TDS packets. Details below
The final TCP packet is somewhat interesting. TDS packets 1-5 are the same as earlier - just standard Results, all 8000 bytes long. The final two packets are unusual though:
TDS packet 6 (TDS packet ID: 75)
04 01 00 40 00 33 4b 00 00 00 00 01 00 00 00 08
00 00 00 08 00 00 00 01 00 00 00 03 00 00 00 02
00 00 00 e4 0b 00 00 00 01 00 00 00 00 fe 04 03
00 00 00 fd 02 00 c1 00 00 00 00 00 00 00 00 00
The first valid token I see is a SESSIONSTATEhttps://learn.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/626fbe19-f356-4599-ba17-c70f44005106 (token 0xe4, length 0x0b, sequence number 0x01, fRecoverable = false, state ID = 0xfe, state length = 0x03, state value = [0x03, 0x00, 0x00, 0x00].
The final token in the packet is a DONEhttps://learn.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/3c06f110-98bd-4d5b-b836-b1ba66452cb7 token - token 0xfd, status 0x02 (DONE_ERROR), CurCmd = 0xc1, DoneRowCount = 0. The TDS spec states that an earlier ERROR token should have been sent. I can't see this token though.
TDS packet 7 (TDS packet ID: 1)
04 01 00 15 00 33 01 00 fd 20 00 fd 00 00 00 00
00 00 00 00 00
This also contains a second DONEhttps://learn.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/3c06f110-98bd-4d5b-b836-b1ba66452cb7 token - token 0xfd, status 0x20 (DONE_ATTN), CurCmd = 0xfd, DoneRowCount = 0.
Thoughts

The stall in network traffic between 716716 and 924659 are probably the space where this instance of the issue first takes shape: it introduces time where SQL Server is generating the row data, but isn't able to send it. That stall comes from the thread pool, which is probably why it only affects the async case.
Although the TCP window resize is occurring, expanding the TCP receive buffer size just pushes the problem further into the future. I had hoped that there was traffic on the thread pool which was associated with the initial burst of tasks from async cancellation (and that expanding the buffer size would spread the demand on the thread pool) but this isn't the case - it's genuine load, not a brief spike.
This bug only appearing rarely on most computers makes a lot of sense - most computers won't strain the thread pool by running a SQL query. Containers probably would though, and there was an issue where somebody noted they had a connectivity problem which was fixed by adding extra cores to the container.

I'm planning to re-run the same test on the main branch to compare output.
—
Reply to this email directly, view it on GitHubhttps://github.com/dotnet/SqlClient/pull/2714#issuecomment-2439655375, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AAH567DT576MHJLKLWIDLDTZ5PC55AVCNFSM6AAAAABLNIFAIKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDIMZZGY2TKMZXGU.
You are receiving this because you were mentioned.Message ID: @.***>

This looks like the cases I saw and resolved this week. We get an end of stream marker from the main command followed by another packet that is telling us that attention has been acknowledged. That should be covered by the changes in Reconstruct3Packets_PartPartPart now. If you've got the packet dumps you can put them into the packets directory of this update testharness and see if they parse correctly.
SQLMultiplexor (3).zip
The error I suspect that we are chasing now is that for some reason the higher layer is not getting informed that we've either finished or received attention. Since we are now getting the both packets with eom's that suggests to me that for some reason we're not running the parser to the second eom.

The error I suspect that we are chasing now is that for some reason the higher layer is not getting informed that we've either finished or received attention. Since we are now getting the both packets with eom's that suggests to me that for some reason we're not running the parser to the second eom.

I agree - the multiplexer is running over my exported packets correctly. I didn't expect to see the second DONE token, so wondered if it was a rare enough condition that the parser didn't expect it either.

I'm seeing a lot of partial packets in linux captures so I suspect that partial packets were mostly working before if there were delays and multiple packets got stuck together as we've seen with the additional done packet. At first i was very surprised wondering how linux ever worked at all. I think it's only a problem when we go too fast and that was almost impossible with the delays caused by various places in the code.
Moving to new hardware this weekend so i'm not able to invest as much time as i'd like. Will keep on looking at it when i can. What i want to try is a comparison of the paths taken through code for the working (main) and non-working (this branch) version of the simplest test we've got that reliably fails. The point of divergence and reason behind it are what i want to know.

Sounds good! I'm pretty interested in TdsParser.TryProcessDone. There's an indication that receiving DONE_ERROR without an error token is a known error case, and there's a fairly specific check which stops the parser if the DONE_MORE bit isn't set.
From re-checking the TDS spec, bit 0 of the DONE token's status is supposed to be set if there's an additional DONE token to follow, or unset if this is the final DONE token. It's odd that SQL Server has sent two consecutive tokens with this bit unset.
I'm going to look at making a sufficiently specific carveout to TdsParser.TryProcessDone - probably in the DONE_MORE handling. It seems reasonable to me that if there's more data to be processed in the packet buffer, we issued an Attention packet but haven't yet received one, we shouldn't unset HasPendingData. It just isn't strictly compliant with the TDS spec.

Even if the SQL server itself were wrong and isn't conforming to the spec, which is unlikely, it worked before these changes and it needs to work with them. So I'm less concerned about being right and more concerned about adding this functionality without forcing changes upwards into the parser etc.

I've checked the pre-PR code against a packet capture and can see the SQL Server instance sending the second DONE token, so nothing we're sending has changed its behaviour. It's odd behaviour - but we're not triggering that odd behaviour as a result of this PR.
I also switched trace logging on for the PR code and ran it while a packet capture was running, so we've got a means to directly compare the TCP traffic to the logs. Although I've not performed that comparison yet, they're below and attached, in case they make more sense to you as-is. I'm planning to add some extra debug logging for the TDS packet IDs, and to write the receive buffers out to files as they're being processed.

 Trace log
2024-10-27T20:09:46.2466084Z: <prov.DbConnectionHelper.ConnectionString_Set|API> 9, 'Data Source=tcp:localhost;Initial Catalog=Northwind;Integrated Security=False;User ID=SA;Encrypt=False'
2024-10-27T20:09:46.2472124Z: <sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
2024-10-27T20:09:46.2496827Z: SqlCommand.Set_CommandText | API | Object Id 9, String Value = '
with TenRows as (select Value from (values (1), (2), (3), (4), (5), (6), (7), (8), (9), (10)) as TenRows (Value)),
    ThousandRows as (select A.Value as A, B.Value as B, C.Value as C from TenRows as A, TenRows as B, TenRows as C)
select *
from ThousandRows as A, ThousandRows as B, ThousandRows as C;', Client Connection Id null
2024-10-27T20:09:46.2497732Z: SqlCommand.Set_Connection | API | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.2498932Z: <sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
2024-10-27T20:09:46.2510661Z: SqlCommand.InternalExecuteReaderAsync | API> 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Command Text = '
with TenRows as (select Value from (values (1), (2), (3), (4), (5), (6), (7), (8), (9), (10)) as TenRows (Value)),
    ThousandRows as (select A.Value as A, B.Value as B, C.Value as C from TenRows as A, TenRows as B, TenRows as C)
select *
from ThousandRows as A, ThousandRows as B, ThousandRows as C;'
2024-10-27T20:09:46.2528972Z: SqlCommand.RunExecuteReaderTds | Info | Object Id 9, Activity Id 46669b9d-c97c-4883-ad3b-0426415855e8:1, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Command executed as SQLBATCH, Command Text '
with TenRows as (select Value from (values (1), (2), (3), (4), (5), (6), (7), (8), (9), (10)) as TenRows (Value)),
    ThousandRows as (select A.Value as A, B.Value as B, C.Value as C from TenRows as A, TenRows as B, TenRows as C)
select *
from ThousandRows as A, ThousandRows as B, ThousandRows as C;'
2024-10-27T20:09:46.2555755Z: TdsParserStateObjectManaged.WriteAsyncCallback | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Error code returned 0
2024-10-27T20:09:46.2559165Z: TdsParserStateObjectManaged.WritePacket | Info | Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, SendAsync Result 997
2024-10-27T20:09:46.2565240Z: SqlCommand.SetActiveConnectionAndResult | API | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, MARS=False
2024-10-27T20:09:46.2587106Z: TdsParserStateObjectManaged.ReadAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 0
2024-10-27T20:09:46.7469336Z: TdsParserStateObjectManaged.ReadAsyncCallback | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Error code returned 0
2024-10-27T20:09:46.7483078Z: SqlCommand.EndExecuteReaderInternal | API | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, MARS=False, AsyncCommandInProgress=True
2024-10-27T20:09:46.7486704Z: SqlCommand.InternalEndExecuteReader | INFO | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, MARS=False, AsyncCommandInProgress=True
2024-10-27T20:09:46.7491793Z: SqlCommand.VerifyEndExecuteState | API | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, MARS=False, AsyncCommandInProgress=True
2024-10-27T20:09:46.7504913Z: CachedAsyncState.ResetAsyncState | API | ObjectId 9, Client Connection Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, AsyncCommandInProgress=True
2024-10-27T20:09:46.7544247Z: TdsParserStateObjectManaged.CreateAndSetAttentionPacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7547499Z: TdsParserStateObjectManaged.WritePacket | Info | Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, SendAsync Result 0
2024-10-27T20:09:46.7547664Z: TdsParserStateObject.SendAttention | Info | State Object Id 1, Sent Attention.
2024-10-27T20:09:46.7550065Z: TdsParserStateObject.SendAttention | Info | State Object Id 1, Attention sent to the server.
2024-10-27T20:09:46.7557549Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7557842Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7559621Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7559699Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7561389Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7561464Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7563155Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7563234Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7564973Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7565049Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7566719Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7567632Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7569418Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7569495Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7571189Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7571263Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7573070Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7573165Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7574849Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7574917Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7576634Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7576835Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7578589Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7578657Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7580773Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7580881Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7582583Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7582647Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7584366Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7584435Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7586093Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7586151Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7587837Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7587895Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7589565Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7589623Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7592019Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7592167Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7593855Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7593922Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7595879Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7595979Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7597656Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7597728Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7599408Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7599474Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7601126Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7601187Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7602838Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7602909Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7604633Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7604714Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7606388Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7606448Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7608140Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7608229Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7609951Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7610024Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7611740Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7611811Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7613682Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2
2024-10-27T20:09:46.7613761Z: TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2, Packet DataLeft 8000
2024-10-27T20:09:46.7615419Z: TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 1, Session Id a1c1dcc0-26d1-4561-82c0-dd83721009e2