SqlClient: Connection does not support MultipleActiveResultSets error after different connection doomed

Describe the bug

We are intermittently seeing a System.InvalidOperationException: The connection does not support MultipleActiveResultSets. We have turned on tracing, and whenever the exception is thrown we see the following traces running up to the exception:


2021-03-03T05:31:14.7349735Z | <sc.SNI.SNILoadHandle.LastError \|SNI\|INFO\|SETTER > Last Error Value = Microsoft.Data.SqlClient.SNI.SNIError |  
-- | -- | --
  | 2021-03-03T05:31:14.7364294Z | <sc.TdsParser.ProcessSNIError\|ERR> |  
  | 2021-03-03T05:31:14.7369261Z | < sc.TdsParser.ProcessSNIError \|ERR\|ADV > Error message Detail: |  
  | 2021-03-03T05:31:14.7375162Z | <sc.TdsParser.ProcessSNIError \|ERR\|ADV > Empty error message received from SNI. Error Message = , SNI Error Number =35 |  
  | 2021-03-03T05:31:14.7380919Z | <sc.TdsParser.ProcessSNIError \|ERR\|ADV > SNI Native Error Code = 0 |  
  | 2021-03-03T05:31:14.7402162Z | <sc.TdsParser.ProcessSNIError \|ERR\|ADV > SNI Error Message. Native Error = 0, Line Number =0, Function =, Exception =System.IO.IOException: Unable to read data from the transport connection: Connection timed out.\n ---> System.Net.Sockets.SocketException (110): Connection timed out\n --- End of inner exception stack trace ---\n at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)\n at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)\n at Microsoft.Data.SqlClient.SNI.SslOverTdsStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)\n at System.Net.Security.SslStream.<FillBufferAsync>g__InternalFillBufferAsync\|215_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial)\n at System.Net.Security.SslStream.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer)\n at Microsoft.Data.SqlClient.SNI.SNISslStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken), Server = tcp:xxxxxxxxxxxxxx.database.windows.net,1433 |  
  | 2021-03-03T05:31:14.7402206Z | <sc.SqlError.SqlError\|ERR> infoNumber=0, errorState=0, errorClass=20, errorMessage='A transport-level error has occurred when receiving results from the server. (provider: TCP Provider, error: 35 - An internal exception was caught)', procedure='', lineNumber=0 |  
  | 2021-03-03T05:31:14.7402219Z | 9927486 |  
  | 2021-03-03T05:31:14.7402254Z | <sc.TdsParserStateObject.DecrementPendingCallbacks\|ADV> 306, after decrementing _pendingCallbacks: 1 |  
  | 2021-03-03T05:31:14.7409883Z | <sc.SqlCommand.EndExecuteReaderAsync\|Info\|Correlation> ObjectID474906, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1 |  
  | 2021-03-03T05:31:14.7410461Z | <prov.DbConnectionInternal.DoomThisConnection\|RES\|INFO\|CPOOL> 311, Dooming |  
  | 2021-03-03T05:31:14.7415426Z | <sc.TdsParserStateObject.DecrementPendingCallbacks\|ADV> 306, after decrementing _pendingCallbacks: 0 |  
  | 2021-03-03T05:31:14.7417989Z | <sc.SqlInternalConnectionTds.BreakConnection\|RES\|CPOOL> 311, Breaking connection. |  
  | 2021-03-03T05:31:14.7418008Z | <prov.DbConnectionInternal.DoomThisConnection\|RES\|INFO\|CPOOL> 311, Dooming |  
  | 2021-03-03T05:31:14.7418023Z | <sc.SqlConnection.Close\|API> 180782 |  
  | 2021-03-03T05:31:14.7418071Z | <sc.SqlConnection.Close\|API\|Correlation> ObjectID 180782, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1 |  
  | 2021-03-03T05:31:14.7418096Z | <prov.DbConnectionInternal.CloseConnection\|RES\|CPOOL> 311 Closing. |  
  | 2021-03-03T05:31:14.7418137Z | <prov.DbConnectionInternal.PrePush\|RES\|CPOOL> 311, Preparing to push into pool, owning connection 0, pooledCount=0 |  
  | 2021-03-03T05:31:14.7418163Z | <prov.DbConnectionPool.DeactivateObject\|RES\|CPOOL> 134, Connection 311, Deactivating. |  
  | 2021-03-03T05:31:14.7418198Z | <prov.DbConnectionInternal.DeactivateConnection\|RES\|INFO\|CPOOL> 311, Deactivating |  
  | 2021-03-03T05:31:14.7418213Z | <sc.SqlInternalConnection.Deactivate\|ADV> 311 deactivating |  
  | 2021-03-03T05:31:14.7418261Z | <prov.DbConnectionInternal.DoomThisConnection\|RES\|INFO\|CPOOL> 311, Dooming |  
  | 2021-03-03T05:31:14.7418273Z | <sc.TdsParser.Deactivate\|ADV> 306 deactivating |  
  | 2021-03-03T05:31:14.7418453Z | <sc.TdsParser.Deactivate\|STATE> 306 \n\t _physicalStateObj = False\n\t _pMarsPhysicalConObj = True\n\t _state = Broken\n\t _server = tcp:xxxxxxxxxxxxxx.database.windows.net,1433\n\t _fResetConnection = False\n\t _defaultCollation = (LCID=1033, Opts=25)\n\t _defaultCodePage = 1252\n\t _defaultLCID = 1033\n\t _defaultEncoding = System.Text.SBCSCodePageEncoding\n\t _encryptionOption = \n\t _currentTransaction = ON\n\t _pendingTransaction = (null)\n\t _retainedTransactionId = (null)\n\t _nonTransactedOpenResultCount = 0\n\t _connHandler = 1\n\t _fMARS = 311\n\t _sessionPool = False\n\t _isYukon = (null)\n\t _sniSpnBuffer = True\n\t _errors = (null)\n\t _warnings = (null)\n\t _attentionErrors = (null)\n\t _attentionWarnings = (null)\n\t _statistics = (null)\n\t _statisticsIsInTransaction = True\n\t _fPreserveTransaction = False _fParallel = False |  
  | 2021-03-03T05:31:14.7418472Z | <prov.DbConnectionPool.DestroyObject\|RES\|CPOOL> 134, Connection 311, Removing from pool. |  
  | 2021-03-03T05:31:14.7418516Z | <prov.DbConnectionPool.DestroyObject\|RES\|CPOOL> 134, Connection 311, Removed from pool. |  
  | 2021-03-03T05:31:14.7418528Z | <sc.SqlInternalConnectionTds.Dispose\|ADV> 311 disposing |  
  | 2021-03-03T05:31:14.7418544Z | <prov.DbConnectionPool.DestroyObject\|RES\|CPOOL> 134, Connection 311, Disposed. |  
  | 2021-03-03T05:31:14.7418601Z | 9927487 |  
  | 2021-03-03T05:31:14.7419721Z | <prov.DbConnectionPool.PoolCreateRequest\|RES\|INFO\|CPOOL> 134 |  
  | 2021-03-03T05:31:14.7419740Z | <prov.DbConnectionPool.ReclaimEmancipatedObjects\|RES\|CPOOL> 134 |  
  | 2021-03-03T05:31:14.7419763Z | 462486 |  
  | 2021-03-03T05:31:14.7468382Z | <prov.DbConnectionHelper.CreateDbCommand\|API> 180782 |  
  | 2021-03-03T05:31:14.7468423Z | <sc.SqlCommand.set_Connection\|API> 474911, 180782 |  
  | 2021-03-03T05:31:14.7468431Z | 9927488 |  
  | 2021-03-03T05:31:14.7468525Z | <sc.SqlCommand.set_CommandText\|API> 474911, String Value = 'xxxxxxxxxxxxxxxxxxxxxx' |  
  | 2021-03-03T05:31:14.7468658Z | <sc.SqlConnection.OpenAsync\|API> 180782 |  
  | 2021-03-03T05:31:14.7468712Z | <sc.SqlConnection.OpenAsync\|API\|Correlation> ObjectID 180782, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1 |  
  | 2021-03-03T05:31:14.7468775Z | <prov.DbConnectionPool.GetConnection\|RES\|CPOOL> 134, Getting connection. |  
  | 2021-03-03T05:31:14.7468861Z | <prov.DbConnectionPool.GetFromGeneralPool\|RES\|CPOOL> 134, Connection 313, Popped from general pool. |  
  | 2021-03-03T05:31:14.7468978Z | <prov.DbConnectionInternal.PostPop\|RES\|CPOOL> 313, Preparing to pop from pool, owning connection 0, pooledCount=0 |  
  | 2021-03-03T05:31:14.7468991Z | <prov.DbConnectionInternal.ActivateConnection\|RES\|INFO\|CPOOL> 313, Activating |  
  | 2021-03-03T05:31:14.7469010Z | 462487 |  
  | 2021-03-03T05:31:14.7469079Z | <sc.SqlCommand.ExecuteReaderAsync\|API\|Correlation> ObjectID 474911, behavior=0, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1 |  
  | 2021-03-03T05:31:14.7469213Z | <sc.TdsParser.GetSession\|ADV> 308 getting physical session 308 |  
  | 2021-03-03T05:31:14.7469308Z | <sc.SqlCommand.ExecuteReader\|INFO> 474911, Command executed as RPC. |  
  | 2021-03-03T05:31:14.7469438Z | <sc.SNI.SNIMarsHandle.SendAsync \|SNI\|INFO\|SCOPE> |  
  | 2021-03-03T05:31:14.7469638Z | 478026 |  
  | 2021-03-03T05:31:14.7478537Z | <comm.ADP.TraceException\|ERR\|THROW> 'System.InvalidOperationException: The connection does not support MultipleActiveResultSets.' |  
  | 2021-03-03T05:31:14.7479430Z | <sc.SqlCommand.EndExecuteReaderAsync\|Info\|Correlation> ObjectID474911, ActivityID 8a720bab-d6ec-40e4-9901-0eae4f411637:1

As can be seen a connection (311) is doomed, due to the TCP connection timing out. But then it retries on a different connection (313) and throws the exception. We repeatedly see the same pattern whenever that exception is thrown.

Expected behavior

Additional tracing to be able to diagnose the problem. The System.InvalidOperationException: The connection does not support MultipleActiveResultSets. should not be thrown.

Further technical details

Microsoft.Data.SqlClient version: 2.1.2 and 1.1.3 .NET Framework: Core 3.1 SQL Server version: Azure SQL Server Operating system: Both Windows and Linux (docker container)

About this issue

Original URL
State: closed
Created 3 years ago
Reactions: 2
Comments: 40 (22 by maintainers)

Most upvoted comments

Here are some thoughts from an EF perspective… Hopefully I’ve understood all of the above.

In regular coding patterns, EF Core closes and opens connections for every operation; this means that with a single DbContext instance, if two queries (or SaveChanges) are executed, DbConnection.OpenAsync is before each query, and DbConnection.CloseAsync is called right after each query. In contrast, when the user explicitly opens the connection via e.g. context.Database.OpenConnectionAsync, the DbConnection stays open until explicitly closed, including when multiple operations are performed.

This means that in typical scenarios, a typical retrying execution strategy will attempt to retry the entire operation multiple times - and that includes closing and opening the connection. This means that as long as the underlying ADO.NET provider handles DbConnection.Close well, the DbConnection.Open from the next retry should succeed. Importantly, this also means that in the EF sense, an exception can be considered transient even if it dooms the current connection - just as long as closing, re-opening and retrying the operation could succeed (this is wider definition of transience compared to being able to retry the operation without closing/re-opening).

To summarize, it seems to me that SqlClient should support closing and re-opening the DbConnection after this exception (or any other), without needing to Dispose; this is also how I’m reading the text in the docs linked to above by @cheenamalhotra:

The SqlConnection remains open when the severity level is 19 or less. When the severity level is 20 or greater, the server ordinarily closes the SqlConnection. However, the user can reopen the connection and continue. In both cases, a SqlException is generated by the method executing the command.

After all, SqlConnection is merely a wrapper/façade over a physical connection - which itself may be doomed - but a close/re-open should get a new physical connection from the pool etc.

Does that make sense?

roji on Mar 18, 2021

OK, good that I fully understood 😃

But this does raise an interesting question on the EF Core side - if the scenario uses a connection which has been manually opened by the user, the execution retrying strategy will not close/re-open the connection, and so exceptions which doom the connection would not be retriable. Opened https://github.com/dotnet/efcore/issues/24432 to think about this.

roji on Mar 18, 2021

Hi @lbargery

I’m able to reproduce this issue locally with just a simple code and a little modification in the driver:

Repro Code:

    using (SqlConnection sqlConnection = new SqlConnection(connString))
    {
        // Execute 2 commands - should work.
        for (int i = 0; i < 2; i++)
        {
            sqlConnection.Open(); // Throws exception second time.
            using (SqlCommand cmd = new SqlCommand("SELECT @@VERSION", sqlConnection))
            {
                cmd.CommandText = "SELECT @@VERSION";
                try
                {
                    using (var reader = await cmd.ExecuteReaderAsync())
                    {
                        while (await reader.ReadAsync())
                        { }
                    }
                    Console.WriteLine(i + 1 + " passed");
                }
                catch (SqlException e)
                {
                    Console.WriteLine(i + 1 + " " + e.Message);
                }
            }
        }
    }

Driver modification in SNIStreams.cs#L34 [Force SocketException on ReadAsync]

internal class SNISslStream : SslStream
{
    ...
    public override async Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToken)
    {
        await _readAsyncSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false);
        try
        {
            //return await base.ReadAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false);
            throw new SocketException();
        }
        finally
        {
            _readAsyncSemaphore.Release();
        }
    }
...

Output:

I sometimes also get UnhandledException (if it happens on EndExecuteReaderAsync):

And as you can see I’m not doing anything special except forcing driver to behave as if socket is not able to read anything from network, mocking the behavior as captured in traces above. What we see here is:

We’re able to capture exception in first round of query execution, so error: 35 - An internal exception was caught is captured, which also has a Class of 20 (tried printing).
If you modify the code to dispose and re-open connection, it works normally again. That’s why Dispose works in your case, as it allows driver to establish a fresh new connection instance and hence it’s a safe approach.

Given the fact that the first exception is a FATAL exception (Class 20), and internal connection and parser are no longer connected to server, as of now there is no way you can continue working on this connection instance.

I’m still yet to determine if it should be possible to recover in this state and reconnect silently if new command needs to be executed, but it will be tricky as currently driver does not behave that way.

cheenamalhotra on Mar 17, 2021

Oh great @ErikEJ, now I know to point to it 😃

roji on Feb 2, 2022

@Wraith2 @roji actually possible!

https://www.nuget.org/packages/ErikEJ.EntityFramework.SqlServer/

FyI @eolamisan

ErikEJ on Feb 2, 2022

We do plan to make it possible to use EF 6 (non-Core) with Microsoft.Data.Sqlclient - but that’s happening in the coming year, and isn’t possible at the moment.

roji on Feb 1, 2022

Closing as https://github.com/dotnet/SqlClient/pull/1128 has been merged. Fix will be available in the next preview release.

cheenamalhotra on Aug 4, 2021

As another data point for the impact of fixing this, I think this is the root cause of this issue: https://github.com/madelson/DistributedLock/issues/83

madelson on Apr 24, 2021

Thanks @roji for the explanation.

Yes the issue is in SqlClient and we’re looking into it. As you mentioned, EF Core’s retry strategy is not retrying on previously opened connection, that confirms there is no issue from EF Core layer, and as per documentation SqlClient should be able to recover and re-open without the need to dispose.

cheenamalhotra on Mar 18, 2021

@cheenamalhotra We managed to get it to work using the follow after the closeAysnc. Seems like re-open didn’t actually reset the state. So this (for now) seems to “solve” the issue for us (though will keep monitoring in Prod)

#pragma warning disable EF1001 // Internal EF Core API usage.
  var dependencies = ((IDatabaseFacadeDependenciesAccessor)dbFacade).Dependencies;
  if (dependencies is IRelationalDatabaseFacadeDependencies relationalDependencies)
  {
      var rc = relationalDependencies.RelationalConnection;
      rc.Dispose();
  }

lbargery on Mar 14, 2021