Async reader may return wrong results on MacOS, Linux, WSL, Docker

[Nercury]

Describe the bug

Sometimes the query may return wrong results under high load, on Non-Windows clients.

To reproduce

• .NET Core
• MSSQL instance
• Client is not running on Windows (reproduced on MacOS or Linux)
• Query uses async reader methods
• High load that saturates the connection pool and causes timeouts.

Bug is seen more often when MultipleActiveResultSets=True (MARS) is in the connection string. It might be prevented by disabling MARS (unclear at this point).

The issue is hard to reproduce and rare, therefore this project was created with the code that attempts to simulate the situation.

This program starts 2000 concurrent connections that runs select @Id as Id
statement. Each Id is different, and the query result should always return
the id that was queried, yet under certain circumstances that's not the case. It looks like
sometimes the reader returns the stale data from random previous connection that experienced the timeout.

There are more details in the linked project.

Network latency can be more easily simulated using this method here: https://github.com/trainline/SqlClient659

Expected behavior

Under no circumstances a select statement should return a different result.

Further technical details

Microsoft.Data.SqlClient version: 4.8.1 or earlier
.NET target: netcoreapp2.0 - netcoreapp3.1
SQL Server version: SQL Server Web Edition 13.00.5426.0.v1, SQL Server Express Edition 14.00.3281.6.v1
Operating system: macOS 10.15.5, Docker container

Workaround

Do not use this SQL client on linux/docker.

Always check the id of the returned result and retry or crash if it is wrong.

To decrease the likelihood of this or maybe prevent it (unclear at this point), do not use MARS feature, if you are using .NET Core with MSSQL database, ensure that the connection string does not contain MultipleActiveResultSets=True.

[JRahnama]

@Nercury thanks for reaching out. Issue #422 is similar to the problem you have and is under investigation.

[DavoudEshtehari]

Hi @Nercury,

Thank you for producing the sample app and describing the issue well.
I ran your sample app multiple times at a virtual machine running Ubuntu 18.0, .Net core 3.1, and SQL Server 19 with MARS enabled and connection pool equals 100. I didn't get any Wrong results as you expected.

Do you have any comments?

[Nercury]

I didn't get any Wrong results as you expected.

Do you have any comments?

Yes, this matches my experience. As I mentioned, the issue seems to be related to timeouts, and they can not happen if the DB server and the code is on the same machine, and the query is doing basically nothing.

Try to introduce some latency between the db server and the application.

I reproduced it using a bit crude approach, by running DB server in cloud and the application on my laptop with a router in another room (so there is some considerable latency between the two). Maybe there are tools to do it a bit more cleanly.

In production environment the AWS starts throttling read operations when they go above allowed IOPS limit, that's how it originally happened when running on AWS.

[DavoudEshtehari]

By replacing the data source by a slower connection over the network I am able to reproduce the wrong result.
I checked the code and added a local index inside the QueryAndVerify method to keep the index parameter value and used this local variable instead of that parameter inside the function body and this change solved the issue. Can I ask you to give it a try and let me know?

[Nercury]

Thanks for checking it out. I am not sure I completely understand what you mean by "added a local index inside the QueryAndVerify method to keep the index parameter value and used this local variable instead of that parameter inside the function body", because the int index is already local to the QueryAndVerify function. Can you provide a changeset (in the form of PR) so that I am sure I am doing the same thing?

[DavoudEshtehari]

While I was preparing the requested changes I found out it is happening again. Maybe the network conditions simultaneously had affected my test by the last change.
The issue intermittently happens either with System.Data.Sqlclient & Microsoft.Data.SqlClient when ExecuteReaderAsync blends with exceptions.

[DavoudEshtehari]

In between investigation, I found these mitigations besides a workaround that has mentioned as disabling the MARS:

• Set Pooling = false
• Removing a connection that encountered an exception from the connection pool: SqlConnection.ClearPool(cn)
• Attempting to execute a SQL command without attaching a transaction to the command (remove the BeginTransaction & CommitAsync) :

var command = new SqlCommand(sql, cn);
command.Transaction = null;

• Using ExecuteScalarAsync instead of ExecuteReaderAsync

@Nercury Can you give them a try one by one?

[Nercury]

Set Pooling = false

MultipleActiveResultSets=True;Pooling=false; painfully slow and many timeouts, but no wrong results, which is good

Removing the connection that encountered an exception

            SqlConnection cnp = null;
            try
            {
                using (var cn = new SqlConnection(connectionString))
                {
                    cnp = cn;
                    
                    // ...
                }
            }
            catch (Exception e)
            {
                if (cnp != null)
                {
                    SqlConnection.ClearPool(cnp);
                }
                
                // ...
            }

Got wrong results on a third attempt.

Attempting to execute a SQL command without attaching a transaction to the command

This was attempted in production when it was still unclear if this is a MARS issue. It makes wrong results more rare, but they still happen. I was not able to reproduce it in this test project with a simplistic select statement.

Using ExecuteScalarAsync instead of ExecuteReaderAsync

Tried it 5 times and wrong results did not happen.

@DavoudEshtehari I hope this helps.

[gyphysics]

Same bug experienced when MARS is disabled:

We are experiencing a similar problem in our code base, although we have MARS disabled explicitly in the connection string and still see the bug.

We run this method across multiple incoming requests from an API Controller:

public async Task<T> GetAsync(string id)
        {
            var sql = $"SELECT Data FROM { _configuration.TableName } {(_configuration.InMemory ? "WITH (SNAPSHOT)" : "")} WHERE Id=@id";

            using (var connection = _connectionFactory.Create())
            {
                var record = await connection.QueryAsync<string>(sql, new { id }).ConfigureAwait(false);

                var data = record.FirstOrDefault();

                return data == null ? default(T) : _serializer.Deserialize<T>(data);
            }
        }

The connectionFactory simply returns a new SqlConnection:
return new SqlConnection(_connectionString);

id is a GUID
data will be an encrypted blob of data that decrypts to a JSON payload.
_serializer handles the decryption (if needed) then serialisation.

Things will run normally, then a single instance will experience a SQL Exception - previously there was an unexpected (and denied) request to perform a SHOWPLAN, sometimes it's a SQL Timeout exception. Following that exception, serialisation bugs will continue to appear on that instance until it is taken out of service.

The source of the serialisation failure is that the value stored in data is an id from an earlier request, rather than the expected value stored on the SQL DB. We've had this happen both on the in-memory DB and without it.

Once the instance has been out of service for a while, subsequent attempts to access the DB via this method complete successfully, so it seems to have the ability to resolve itself. Even when the instance is misbehaving, it appears that not all requests get jumbled up, as some manage to succeed.

Previously this service was hosted on Windows without any issues. Since the port to Linux this problem crops up every 7-30 days or so. We've also seen it on more than one service (the above code is in a shared library). This bug seems to be the closest thing to what we are experiencing, except that we have explicitly disabled MARS in the connection string and are still seeing it from time to time.

Libraries/Infrastructure involved:
NetCore 3.1
Dapper 2.0.35
Microsoft.Data.SqlClient 2.0.1

This is being run on an AWS T3 instance hosting Ubuntu 18.04

We are going to attempt changing the call from QueryAsync to ExecuteScalarAsync and are attempting to capture some more information to help us debug the issue. If the change to ExecuteScalarAsync resolves the problem for at least a month or so then I'll add an extra comment here indicating that it's a possible fix.