Connection does not support MultipleActiveResultSets error after different connection doomed

[nickljones]

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)

[cheenamalhotra]

@nickljones

If you have a repro for this use-case, please upload it here so we can investigate further.

[lbargery]

@nickljones

If you have a repro for this use-case, please upload it here so we can investigate further.

I also work at accuRx with Nick. Sadly we've not been able to find any rhyme or reason why or when this occurs. We've spent a long time investigating internally but are really at a dead end. There is no obvious repo, but it does reliably occurs order 10s of times a day. However, not particularly linked to busy periods and can easily go off around 11pm/midnight when our traffic is really low. Is there anything else we can try to give you here to help you investigate?

Also can tell you happens on a range of queries including ones which should take 1-2ms (selecting a row which has an index on it).

[cheenamalhotra]

Is it possible to capture traces again in developer environment with a custom driver version (from nightly builds) ?
As we have additional tracing in newer builds that can be helpful to understand use-case.

You could try this feed to fetch latest build:
Microsoft.Data.SqlClient.dev

[lbargery]

@cheenamalhotra Yes, I think we see the error in our staging env and should be able to add package there with traces from Sql package.

[Wraith2]

Speculation, BeginExecuteReaderInternalReadStage calls into cachedAsyncState.SetActiveConnectionAndResult (confusingly with nameof(EndExecuteReader) as a parameter which is why I think it's linked) which does:

if (!parser.MARSOn)
{
    if (activeConnection.AsyncCommandInProgress)
        throw SQL.MARSUnsupportedOnConnection();
}

Is there any previous trace information about connection 313 in the log about when it was used and returned to the pool?

[nickljones]

Thanks. Here is the previous trace we have for connection 313, just over a minute before the logs above, which as far as I can tell shows a normal connection life-cycle.

2021-03-03T05:30:41.7956648Z	<prov.DbConnectionHelper.ConnectionString_Set|API> 180785, 'Data Source=tcp:xxxxxxxxxxxxxxxx.database.windows.net,1433;Initial Catalog=xxxxxxxxxxxxxxxxx;User Id=xxxxxxxxxxxxxxx@xxxxxxxxxx.database.windows.net;Max Pool Size=200;ConnectRetryCount=0;MultipleActiveResultSets=False;'	
2021-03-03T05:30:41.7956680Z	<prov.DbConnectionHelper.CreateDbCommand|API> 180785	
2021-03-03T05:30:41.7956714Z	<sc.SqlCommand.set_Connection|API> 474909, 180785	
2021-03-03T05:30:41.7956734Z	9927473	
2021-03-03T05:30:41.7956782Z	<sc.SqlCommand.set_CommandText|API> 474909, String Value = 'SELECT TOP(2) xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx'	
2021-03-03T05:30:41.7956911Z	<sc.SqlConnection.OpenAsync|API> 180785	
2021-03-03T05:30:41.7957004Z	<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1	
2021-03-03T05:30:41.7957068Z	<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection.	
2021-03-03T05:30:41.7957160Z	<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Wait timed out.	
2021-03-03T05:30:41.7959129Z	462484	
2021-03-03T05:30:41.7959458Z	<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection.	
2021-03-03T05:30:41.7959559Z	<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Creating new connection.
2021-03-03T05:30:41.7959717Z	<sc.SqlInternalConnectionTds.LoginNoFailover|ADV> 313, host=tcp:xxxxxxxxxxxxx.database.windows.net,1433	
2021-03-03T05:30:41.7959771Z	<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 308, after incrementing _pendingCallbacks: 1	
2021-03-03T05:30:41.7959811Z	<sc.SqlInternalConnectionTds.AttemptOneLogin|ADV> 313, timout=14999[msec], server=tcp:xxxxxxxxxxxxx.database.windows.net,1433	
2021-03-03T05:30:41.7959829Z	<sc.TdsParser.Connect|SEC> SQL authentication	
2021-03-03T05:30:41.8191634Z	<sc.TdsParser.Connect|SEC> Sending prelogin handshake	
2021-03-03T05:30:41.8191839Z	<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 2bab5025-ff5d-43a4-840f-fa36dadc1dd9, ActivityID 95ca93d5-004a-41d3-a080-c22ac8548082:1	
2021-03-03T05:30:41.8192301Z	<sc.TdsParser.Connect|SEC> Consuming prelogin handshake	
2021-03-03T05:30:41.8211967Z	<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes	
2021-03-03T05:30:41.8212302Z	478015	
2021-03-03T05:30:41.8212322Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8250548Z	478016	
2021-03-03T05:30:41.8250615Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8250657Z	478017	
2021-03-03T05:30:41.8250664Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8250708Z	478018	
2021-03-03T05:30:41.8255462Z	<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes	
2021-03-03T05:30:41.8255826Z	478019	
2021-03-03T05:30:41.8255838Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8278040Z	478020	
2021-03-03T05:30:41.8278126Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8278148Z	478021	
2021-03-03T05:30:41.8278330Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8278353Z	478022	
2021-03-03T05:30:41.8278362Z	<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes	
2021-03-03T05:30:41.8278392Z	478023	
2021-03-03T05:30:41.8614954Z	<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|SCOPE|INFO >	
2021-03-03T05:30:41.8614987Z	<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|INFO > SSL Server certificate validated.	
2021-03-03T05:30:41.8614992Z	478024	
2021-03-03T05:30:41.8615067Z	<sc.SNI.SslOverTdsStream.FinishHandshake |SNI|INFO> switched from encapsulation to passthrough mode	
2021-03-03T05:30:41.8615227Z	<sc.TdsParser.TdsLogin|ADV> 308, TDS Login7 flags = 268436448:	
2021-03-03T05:30:41.8956399Z	<sc.SqlConnection.OpenAsyncRetry|Info> 180785	
2021-03-03T05:30:41.9176149Z	<sc.TdsParser.TryRun|SEC> Received login acknowledgement token	
2021-03-03T05:30:41.9176306Z	<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for TCE	
2021-03-03T05:30:41.9176332Z	<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for GlobalTransactions	
2021-03-03T05:30:41.9176356Z	<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for DATACLASSIFICATION	
2021-03-03T05:30:41.9176374Z	<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for UTF8 support	
2021-03-03T05:30:41.9176396Z	<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for SQLDNSCACHING	
2021-03-03T05:30:41.9176576Z	<sc.SqlInternalConnectionTds.CompleteLogin|ADV> Post-Login Phase: Server connection obtained.	
2021-03-03T05:30:41.9176875Z	<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.	
2021-03-03T05:30:41.9176909Z	<sc.SqlInternalConnectionTds.ctor|ADV> 313, constructed new TDS internal connection	
2021-03-03T05:30:41.9176954Z	<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.	
2021-03-03T05:30:41.9176990Z	<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0	
2021-03-03T05:30:41.9177033Z	<prov.DbConnectionPool.CreateObject|RES|CPOOL> 134, Connection 313, Added to pool.	
2021-03-03T05:30:41.9177123Z	<prov.DbConnectionInternal.PostPop|RES|CPOOL> 313, Preparing to pop from pool, owning connection 0, pooledCount=0	
2021-03-03T05:30:41.9177147Z	<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 313, Activating	
2021-03-03T05:30:41.9177189Z	<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0	
2021-03-03T05:30:41.9177212Z	<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 313, Deactivating.	
2021-03-03T05:30:41.9177229Z	<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 313, Deactivating	
2021-03-03T05:30:41.9177248Z	<sc.SqlInternalConnection.Deactivate|ADV> 313 deactivating
2021-03-03T05:30:41.9177271Z	<sc.TdsParser.Deactivate|ADV> 308 deactivating	
2021-03-03T05:30:41.9177653Z	<sc.TdsParser.Deactivate|STATE> 308 \n\t _physicalStateObj = False\n\t _pMarsPhysicalConObj = True\n\t _state = OpenLoggedIn\n\t _server = tcp:accurxchainproduction.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 = 0\n\t _fMARS = 313\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:30:41.9177684Z	<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 313, Pushing to general pool.	
2021-03-03T05:30:41.9951474Z	<prov.DbConnectionHelper.CreateDbCommand|API> 180785	
2021-03-03T05:30:41.9951531Z	<sc.SqlCommand.set_Connection|API> 474910, 180785	
2021-03-03T05:30:41.9951541Z	9927474	
2021-03-03T05:30:41.9951596Z	<sc.SqlCommand.set_CommandText|API> 474910, String Value = 'SELECT TOP(2) xxxxxxxxxxxxxxxxxxxxxxxxxxx'	
2021-03-03T05:30:41.9951723Z	<sc.SqlConnection.OpenAsync|API> 180785	
2021-03-03T05:30:41.9951848Z	<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180785, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1	
2021-03-03T05:30:41.9951927Z	<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection.	
2021-03-03T05:30:41.9952026Z	<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 134, Connection 313, Popped from general pool.	
2021-03-03T05:30:41.9952164Z	<prov.DbConnectionInternal.PostPop|RES|CPOOL> 313, Preparing to pop from pool, owning connection 0, pooledCount=0	
2021-03-03T05:30:41.9952178Z	<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 313, Activating	
2021-03-03T05:30:41.9952200Z	462485	
2021-03-03T05:30:41.9952271Z	<sc.SqlCommand.ExecuteReaderAsync|API|Correlation> ObjectID 474910, behavior=0, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1	
2021-03-03T05:30:41.9952421Z	<sc.TdsParser.GetSession|ADV> 308 getting physical session 308	
2021-03-03T05:30:41.9952517Z	<sc.SqlCommand.ExecuteReader|INFO> 474910, Command executed as RPC.	
2021-03-03T05:30:41.9952667Z	<sc.SNI.SNIMarsHandle.SendAsync |SNI|INFO|SCOPE>	
2021-03-03T05:30:41.9952899Z	478025	
2021-03-03T05:30:41.9954560Z	<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 308, after incrementing _pendingCallbacks: 2	
2021-03-03T05:30:41.9983573Z	<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 308, after decrementing _pendingCallbacks: 1	
2021-03-03T05:30:41.9983840Z	<sc.SqlCommand.EndExecuteReaderAsync|Info|Correlation> ObjectID474910, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1	
2021-03-03T05:30:41.9984100Z	418716, 1, 0	
2021-03-03T05:30:41.9987088Z	<sc.SqlDataReader.ReadAsync|API> 1	
2021-03-03T05:30:41.9987108Z	<sc.SqlDataReader.Read|API> 1	
2021-03-03T05:30:41.9987147Z	<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> 308, NBCROW bitmap received, column count = 18	
2021-03-03T05:30:41.9987224Z	<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> NBCROW bitmap data:	
2021-03-03T05:30:41.9987238Z	9927476	
2021-03-03T05:30:41.9987457Z	9927475	
2021-03-03T05:30:41.9987527Z	<sc.SqlDataReader.ReadAsync|API> 1	
2021-03-03T05:30:41.9987541Z	<sc.SqlDataReader.Read|API> 1	
2021-03-03T05:30:41.9987554Z	9927478	
2021-03-03T05:30:41.9987561Z	9927477	
2021-03-03T05:30:41.9987586Z	<sc.SqlDataReader.NextResultAsync|API> 1	
2021-03-03T05:30:41.9987604Z	<sc.SqlDataReader.NextResult|API> 1	
2021-03-03T05:30:41.9987614Z	<sc.SqlDataReader.Read|API> 1	
2021-03-03T05:30:41.9987642Z	9927481	
2021-03-03T05:30:41.9987657Z	9927480	
2021-03-03T05:30:41.9987663Z	9927479	
2021-03-03T05:30:41.9987674Z	<sc.SqlDataReader.Close|API> 1	
2021-03-03T05:30:41.9987693Z	9927482	
2021-03-03T05:30:41.9987701Z	<sc.SqlDataReader.Close|API> 1	
2021-03-03T05:30:41.9987705Z	9927483	
2021-03-03T05:30:41.9988848Z	<sc.SqlConnection.Close|API> 180785	
2021-03-03T05:30:41.9988889Z	<sc.SqlConnection.Close|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1	
2021-03-03T05:30:41.9988910Z	<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 313 Closing.	
2021-03-03T05:30:41.9988943Z	<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0	
2021-03-03T05:30:41.9988960Z	<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 313, Deactivating.	
2021-03-03T05:30:41.9988973Z	<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 313, Deactivating	
2021-03-03T05:30:41.9988987Z	<sc.SqlInternalConnection.Deactivate|ADV> 313 deactivating	
2021-03-03T05:30:41.9989021Z	<sc.TdsParser.Deactivate|ADV> 308 deactivating	
2021-03-03T05:30:41.9989199Z	<sc.TdsParser.Deactivate|STATE> 308 \n\t _physicalStateObj = False\n\t _pMarsPhysicalConObj = True\n\t _state = OpenLoggedIn\n\t _server = tcp:xxxxxxxxxxxxx.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 = 0\n\t _fMARS = 313\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:30:41.9989221Z	<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 313, Pushing to general pool.	
2021-03-03T05:30:41.9989283Z	9927484	
2021-03-03T05:30:41.9992923Z	<sc.SqlConnection.Close|API> 180785	
2021-03-03T05:30:41.9992959Z	<sc.SqlConnection.Close|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1	
2021-03-03T05:30:41.9992975Z	9927485	
2021-03-03T05:30:45.9176888Z	<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1

[lbargery]

@cheenamalhotra I just checked all our staging logs and the error has only gone off once in last month, so pretty unlikely we'll catch it there sadly. We'd have to use the beta package in prod but am less keen for this. That does seem to indicate it's more likely with higher traffic, could mean it's a race?

Is there anything else we can do to help pin this down? It's very disruptive for us (goes of 10s of times a day in production). We are quite high traffic consumers of Azure SQL if that helps diagnose. (I imagine 100M queries/transactions a day)

[lbargery]

Again, not sure if helpful, but we've always found the MARs exception happens after this first exception:

"A transport-level error has occurred when receiving results from the server. (provider: TCP Provider, error: 35 - An internal exception was caught"

[cheenamalhotra]

@lbargery

It's an interesting situation, I'm still trying to wrap my head around what's going on..
I'm interested in the timeout and SNI giving EMPTY error that Dooms connection. I need more traces to pin down what's going on exactly, specifically before timeout occurs and about object 474906.

Can you give me full trace between 2021-03-03T05:30 and 2021-03-03T05:32 ?

Also please provide exact driver version for which traces are captured, as otherwise I cannot match behaviors properly.

[lbargery]

This is the full log trace I have for this particular function invocation (happy to email to you too). The reason it takes 15 minutes is that we needed to change a setting on K8 cluster just FYI (net.ipv4.tcp_retries2). One thing I haven't worked out is why we sometimes get 400 traces, and sometimes get 11,000. Happy to share traces from other times this has gone off too.

By driver version, do you just mean nuget package version or something else?

"2021-03-03T05:15:36.7261054Z","<prov.DbConnectionHelper.ConnectionString_Set|API> 180782, 'Data Source=tcp:xxxxx.database.windows.net,1433;Initial Catalog=xxxx;User Id=USER@xxxxx.database.windows.net;Max Pool Size=200;ConnectRetryCount=0;MultipleActiveResultSets=False;'"
"2021-03-03T05:15:36.7261087Z","<prov.DbConnectionHelper.CreateDbCommand|API> 180782"
"2021-03-03T05:15:36.7261119Z","<sc.SqlCommand.set_Connection|API> 474906, 180782"
"2021-03-03T05:15:36.7261129Z",9927447
"2021-03-03T05:15:36.7261171Z","<sc.SqlCommand.set_CommandText|API> 474906, String Value = 'QUERY_TEXT'"
"2021-03-03T05:15:36.7261305Z","<sc.SqlConnection.OpenAsync|API> 180782"
"2021-03-03T05:15:36.7261402Z","<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180782, ActivityID 745531b8-8726-4d4a-83aa-4c401f81d43e:1"
"2021-03-03T05:15:36.7261470Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:15:36.7261563Z","<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 134, Connection 311, Popped from general pool."
"2021-03-03T05:15:36.7261697Z","<prov.DbConnectionInternal.PostPop|RES|CPOOL> 311, Preparing to pop from pool,  owning connection 0, pooledCount=0"
"2021-03-03T05:15:36.7261710Z","<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 311, Activating"
"2021-03-03T05:15:36.7261733Z",462477
"2021-03-03T05:15:36.7261804Z","<sc.SqlCommand.ExecuteReaderAsync|API|Correlation> ObjectID 474906, behavior=0, ActivityID 745531b8-8726-4d4a-83aa-4c401f81d43e:1"
"2021-03-03T05:15:36.7262009Z","<sc.TdsParser.GetSession|ADV> 306 getting physical session 306"
"2021-03-03T05:15:36.7262101Z","<sc.SqlCommand.ExecuteReader|INFO> 474906, Command executed as RPC."
"2021-03-03T05:15:36.7262227Z","<sc.SNI.SNIMarsHandle.SendAsync |SNI|INFO|SCOPE>"
"2021-03-03T05:15:36.7262474Z",478002
"2021-03-03T05:15:36.7263350Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 306, after incrementing _pendingCallbacks: 2"
"2021-03-03T05:15:36.8262231Z","<sc.SqlCommand.Cancel | API > 474906"
"2021-03-03T05:15:36.8262309Z","<sc.SqlCommand.Cancel|API|Correlation> ObjectID 474906, ActivityID 745531b8-8726-4d4a-83aa-4c401f81d43e:1"
"2021-03-03T05:15:36.8263127Z","<sc.TdsParser.SendAttention|INFO> Send Attention ASync."
"2021-03-03T05:15:36.8263276Z","<sc.TdsParser.WritePacket|INFO|ADV>  Packet sent"
"2021-03-03T05:15:36.8263281Z","<sc.TdsParser.SendAttention|INFO> Attention sent to the server."
"2021-03-03T05:15:36.8263291Z",9927448
"2021-03-03T05:15:45.9177632Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:15:50.3752252Z","<prov.DbConnectionHelper.ConnectionString_Set|API> 180783, 'Data Source=tcp:xxxxx.database.windows.net,1433;Initial Catalog=xxxx;User Id=USER@xxxxx.database.windows.net;Max Pool Size=200;ConnectRetryCount=0;MultipleActiveResultSets=False;'"
"2021-03-03T05:15:50.3752299Z","<prov.DbConnectionHelper.CreateDbCommand|API> 180783"
"2021-03-03T05:15:50.3752347Z","<sc.SqlCommand.set_Connection|API> 474907, 180783"
"2021-03-03T05:15:50.3752377Z",9927449
"2021-03-03T05:15:50.3752444Z","<sc.SqlCommand.set_CommandText|API> 474907, String Value = 'QUERY_TEXT'"
"2021-03-03T05:15:50.3752623Z","<sc.SqlConnection.OpenAsync|API> 180783"
"2021-03-03T05:15:50.3752689Z","<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180783, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:50.3752797Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:15:50.3752958Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Wait timed out."
"2021-03-03T05:15:50.3754979Z",462478
"2021-03-03T05:15:50.3755364Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:15:50.3755461Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Creating new connection."
"2021-03-03T05:15:50.3755632Z","<sc.SqlInternalConnectionTds.LoginNoFailover|ADV> 312, host=tcp:xxxxx.database.windows.net,1433"
"2021-03-03T05:15:50.3755687Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 307, after incrementing _pendingCallbacks: 1"
"2021-03-03T05:15:50.3755729Z","<sc.SqlInternalConnectionTds.AttemptOneLogin|ADV> 312, timout=14999[msec], server=tcp:xxxxx.database.windows.net,1433"
"2021-03-03T05:15:50.3755744Z","<sc.TdsParser.Connect|SEC> SQL authentication"
"2021-03-03T05:15:50.3926639Z","<sc.TdsParser.Connect|SEC> Sending prelogin handshake"
"2021-03-03T05:15:50.3926844Z","<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 3be14ef4-6ac9-4949-8841-8191d6556181, ActivityID 357d7e9a-bde9-4634-9b65-6906c5f45f43:1"
"2021-03-03T05:15:50.3927309Z","<sc.TdsParser.Connect|SEC> Consuming prelogin handshake"
"2021-03-03T05:15:50.3945746Z","<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes"
"2021-03-03T05:15:50.3945989Z",478003
"2021-03-03T05:15:50.3946005Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.3979983Z",478004
"2021-03-03T05:15:50.3980111Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.3980193Z",478005
"2021-03-03T05:15:50.3980211Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.3980314Z",478006
"2021-03-03T05:15:50.3986448Z","<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes"
"2021-03-03T05:15:50.3986782Z",478007
"2021-03-03T05:15:50.3986795Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.4007292Z",478008
"2021-03-03T05:15:50.4007455Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.4007511Z",478009
"2021-03-03T05:15:50.4007871Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.4007923Z",478010
"2021-03-03T05:15:50.4007946Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:15:50.4008015Z",478011
"2021-03-03T05:15:50.4017963Z","<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|SCOPE|INFO >"
"2021-03-03T05:15:50.4017994Z","<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|INFO > SSL Server certificate validated."
"2021-03-03T05:15:50.4018001Z",478012
"2021-03-03T05:15:50.4018059Z","<sc.SNI.SslOverTdsStream.FinishHandshake |SNI|INFO> switched from encapsulation to passthrough mode"
"2021-03-03T05:15:50.4018179Z","<sc.TdsParser.TdsLogin|ADV> 307, TDS Login7 flags = 268436448:"
"2021-03-03T05:15:50.4586859Z","<sc.TdsParser.TryRun|SEC> Received login acknowledgement token"
"2021-03-03T05:15:50.4587031Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 312, Received feature extension acknowledgement for TCE"
"2021-03-03T05:15:50.4587074Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 312, Received feature extension acknowledgement for GlobalTransactions"
"2021-03-03T05:15:50.4587108Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 312, Received feature extension acknowledgement for DATACLASSIFICATION"
"2021-03-03T05:15:50.4587139Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 312, Received feature extension acknowledgement for UTF8 support"
"2021-03-03T05:15:50.4587171Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 312, Received feature extension acknowledgement for SQLDNSCACHING"
"2021-03-03T05:15:50.4587442Z","<sc.SqlInternalConnectionTds.CompleteLogin|ADV> Post-Login Phase: Server connection obtained."
"2021-03-03T05:15:50.4587909Z","<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn."
"2021-03-03T05:15:50.4587956Z","<sc.SqlInternalConnectionTds.ctor|ADV> 312, constructed new TDS internal connection"
"2021-03-03T05:15:50.4587995Z","<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created."
"2021-03-03T05:15:50.4588045Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 312, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:15:50.4588097Z","<prov.DbConnectionPool.CreateObject|RES|CPOOL> 134, Connection 312, Added to pool."
"2021-03-03T05:15:50.4588214Z","<prov.DbConnectionInternal.PostPop|RES|CPOOL> 312, Preparing to pop from pool,  owning connection 0, pooledCount=0"
"2021-03-03T05:15:50.4588242Z","<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 312, Activating"
"2021-03-03T05:15:50.4590440Z","<sc.SqlConnection.OpenAsyncRetry|Info> 180783"
"2021-03-03T05:15:50.4591026Z","<sc.SqlCommand.ExecuteReaderAsync|API|Correlation> ObjectID 474907, behavior=0, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:50.4591293Z","<sc.TdsParser.GetSession|ADV> 307 getting physical session 307"
"2021-03-03T05:15:50.4591467Z","<sc.SqlCommand.ExecuteReader|INFO> 474907, Command executed as RPC."
"2021-03-03T05:15:50.4591666Z","<sc.SNI.SNIMarsHandle.SendAsync |SNI|INFO|SCOPE>"
"2021-03-03T05:15:50.4591774Z",478013
"2021-03-03T05:15:50.4594366Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 307, after incrementing _pendingCallbacks: 2"
"2021-03-03T05:15:50.4625386Z","<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 307, after decrementing _pendingCallbacks: 1"
"2021-03-03T05:15:50.4625708Z","<sc.SqlCommand.EndExecuteReaderAsync|Info|Correlation> ObjectID474907, ActivityID efc7a7c4-b375-4c79-bc37-2799b15db0e3:1"
"2021-03-03T05:15:50.4625881Z","50435980, 1, 0"
"2021-03-03T05:15:50.4628479Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:15:50.4628500Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:50.4628536Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> 307, NBCROW bitmap received, column count = 18"
"2021-03-03T05:15:50.4628558Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> NBCROW bitmap data:"
"2021-03-03T05:15:50.4628567Z",9927451
"2021-03-03T05:15:50.4628769Z",9927450
"2021-03-03T05:15:50.4628851Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:15:50.4628865Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:50.4628876Z",9927453
"2021-03-03T05:15:50.4628883Z",9927452
"2021-03-03T05:15:50.4628907Z","<sc.SqlDataReader.NextResultAsync|API> 1"
"2021-03-03T05:15:50.4628924Z","<sc.SqlDataReader.NextResult|API> 1"
"2021-03-03T05:15:50.4628932Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:50.4628936Z",9927456
"2021-03-03T05:15:50.4628950Z",9927455
"2021-03-03T05:15:50.4628956Z",9927454
"2021-03-03T05:15:50.4628983Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:15:50.4629001Z",9927457
"2021-03-03T05:15:50.4629010Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:15:50.4629014Z",9927458
"2021-03-03T05:15:50.4630089Z","<sc.SqlConnection.Close|API> 180783"
"2021-03-03T05:15:50.4630126Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180783, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:50.4630149Z","<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 312 Closing."
"2021-03-03T05:15:50.4630194Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 312, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:15:50.4630214Z","<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 312, Deactivating."
"2021-03-03T05:15:50.4630227Z","<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 312, Deactivating"
"2021-03-03T05:15:50.4630241Z","<sc.SqlInternalConnection.Deactivate|ADV> 312 deactivating"
"2021-03-03T05:15:50.4630258Z","<sc.TdsParser.Deactivate|ADV> 307 deactivating"
"2021-03-03T05:15:50.4630571Z","<sc.TdsParser.Deactivate|STATE> 307 \n\t         _physicalStateObj = False\n\t         _pMarsPhysicalConObj = True\n\t         _state = OpenLoggedIn\n\t         _server = tcp:xxxxx.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 = 0\n\t         _fMARS = 312\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:15:50.4630592Z","<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 312, Pushing to general pool."
"2021-03-03T05:15:50.4630647Z",9927459
"2021-03-03T05:15:50.4633996Z","<sc.SqlConnection.Close|API> 180783"
"2021-03-03T05:15:50.4634042Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180783, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:50.4634056Z",9927460
"2021-03-03T05:15:51.0342408Z","<prov.DbConnectionHelper.ConnectionString_Set|API> 180784, 'Data Source=tcp:xxxxx.database.windows.net,1433;Initial Catalog=xxxx;User Id=USER@xxxxx.database.windows.net;Max Pool Size=200;ConnectRetryCount=0;MultipleActiveResultSets=False;'"
"2021-03-03T05:15:51.0342439Z","<prov.DbConnectionHelper.CreateDbCommand|API> 180784"
"2021-03-03T05:15:51.0342474Z","<sc.SqlCommand.set_Connection|API> 474908, 180784"
"2021-03-03T05:15:51.0342481Z",9927461
"2021-03-03T05:15:51.0342543Z","<sc.SqlCommand.set_CommandText|API> 474908, String Value = 'QUERY_TEXT'"
"2021-03-03T05:15:51.0342717Z","<sc.SqlConnection.OpenAsync|API> 180784"
"2021-03-03T05:15:51.0342774Z","<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180784, ActivityID efc7a7c4-b375-4c79-bc37-2799b15db0e3:1"
"2021-03-03T05:15:51.0342853Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:15:51.0342964Z","<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 134, Connection 312, Popped from general pool."
"2021-03-03T05:15:51.0343126Z","<prov.DbConnectionInternal.PostPop|RES|CPOOL> 312, Preparing to pop from pool,  owning connection 0, pooledCount=0"
"2021-03-03T05:15:51.0343146Z","<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 312, Activating"
"2021-03-03T05:15:51.0343175Z",462479
"2021-03-03T05:15:51.0343265Z","<sc.SqlCommand.ExecuteReaderAsync|API|Correlation> ObjectID 474908, behavior=0, ActivityID efc7a7c4-b375-4c79-bc37-2799b15db0e3:1"
"2021-03-03T05:15:51.0343410Z","<sc.TdsParser.GetSession|ADV> 307 getting physical session 307"
"2021-03-03T05:15:51.0343483Z","<sc.SqlCommand.ExecuteReader|INFO> 474908, Command executed as RPC."
"2021-03-03T05:15:51.0343614Z","<sc.SNI.SNIMarsHandle.SendAsync |SNI|INFO|SCOPE>"
"2021-03-03T05:15:51.0343809Z",478014
"2021-03-03T05:15:51.0344657Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 307, after incrementing _pendingCallbacks: 2"
"2021-03-03T05:15:51.0376113Z","<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 307, after decrementing _pendingCallbacks: 1"
"2021-03-03T05:15:51.0376231Z","<sc.SqlCommand.EndExecuteReaderAsync|Info|Correlation> ObjectID474908, ActivityID efc7a7c4-b375-4c79-bc37-2799b15db0e3:1"
"2021-03-03T05:15:51.0376547Z","60613259, 1, 0"
"2021-03-03T05:15:51.0377956Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:15:51.0377973Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:51.0378010Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> 307, NBCROW bitmap received, column count = 18"
"2021-03-03T05:15:51.0378033Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> NBCROW bitmap data:"
"2021-03-03T05:15:51.0378040Z",9927463
"2021-03-03T05:15:51.0378212Z",9927462
"2021-03-03T05:15:51.0378294Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:15:51.0378307Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:51.0378316Z",9927465
"2021-03-03T05:15:51.0378322Z",9927464
"2021-03-03T05:15:51.0378343Z","<sc.SqlDataReader.NextResultAsync|API> 1"
"2021-03-03T05:15:51.0378360Z","<sc.SqlDataReader.NextResult|API> 1"
"2021-03-03T05:15:51.0378381Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:15:51.0378386Z",9927468
"2021-03-03T05:15:51.0378397Z",9927467
"2021-03-03T05:15:51.0378402Z",9927466
"2021-03-03T05:15:51.0378411Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:15:51.0378426Z",9927469
"2021-03-03T05:15:51.0378433Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:15:51.0378435Z",9927470
"2021-03-03T05:15:51.0379867Z","<sc.SqlConnection.Close|API> 180784"
"2021-03-03T05:15:51.0379902Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180784, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:51.0379919Z","<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 312 Closing."
"2021-03-03T05:15:51.0379945Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 312, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:15:51.0379960Z","<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 312, Deactivating."
"2021-03-03T05:15:51.0379971Z","<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 312, Deactivating"
"2021-03-03T05:15:51.0379982Z","<sc.SqlInternalConnection.Deactivate|ADV> 312 deactivating"
"2021-03-03T05:15:51.0379997Z","<sc.TdsParser.Deactivate|ADV> 307 deactivating"
"2021-03-03T05:15:51.0380404Z","<sc.TdsParser.Deactivate|STATE> 307 \n\t         _physicalStateObj = False\n\t         _pMarsPhysicalConObj = True\n\t         _state = OpenLoggedIn\n\t         _server = tcp:xxxxx.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 = 0\n\t         _fMARS = 312\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:15:51.0380445Z","<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 312, Pushing to general pool."
"2021-03-03T05:15:51.0380498Z",9927471
"2021-03-03T05:15:51.0383659Z","<sc.SqlConnection.Close|API> 180784"
"2021-03-03T05:15:51.0383684Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180784, ActivityID fc76d27a-c5fb-44e3-b4de-c3f5f0f0a9af:1"
"2021-03-03T05:15:51.0383697Z",9927472
"2021-03-03T05:16:15.9193889Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:16:45.9182888Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:17:15.9183522Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:17:45.9180630Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:18:15.9189510Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:18:26.1616230Z","<prov.DbConnectionPool.CleanupCallback|RES|INFO|CPOOL> 134"
"2021-03-03T05:18:26.1616371Z","<prov.DbConnectionPool.CleanupCallback|RES|INFO|CPOOL> 134, ChangeStacks=312"
"2021-03-03T05:18:26.1616709Z","<prov.DbConnectionPool.PoolCreateRequest|RES|INFO|CPOOL> 134"
"2021-03-03T05:18:26.1616727Z","<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 134"
"2021-03-03T05:18:26.1616755Z",462480
"2021-03-03T05:18:45.9176009Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:19:15.9190857Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:19:45.9176844Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:20:15.9188059Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:20:45.9181150Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:21:15.9192058Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:21:45.9205470Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:21:46.1637960Z","<prov.DbConnectionPool.CleanupCallback|RES|INFO|CPOOL> 134"
"2021-03-03T05:21:46.1638049Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 312, Removing from pool."
"2021-03-03T05:21:46.1638105Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 312, Removed from pool."
"2021-03-03T05:21:46.1638123Z","<sc.SqlInternalConnectionTds.Dispose|ADV> 312 disposing"
"2021-03-03T05:21:46.1639854Z","<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 307, after decrementing _pendingCallbacks: 0"
"2021-03-03T05:21:46.1639881Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 312, Disposed."
"2021-03-03T05:21:46.1640437Z","<prov.DbConnectionPool.PoolCreateRequest|RES|INFO|CPOOL> 134"
"2021-03-03T05:21:46.1640465Z","<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 134"
"2021-03-03T05:21:46.1640496Z",462481
"2021-03-03T05:22:15.9185224Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:22:45.9185808Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:23:15.9189765Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:23:45.9178690Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:24:15.9186458Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:24:45.9182545Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:25:06.1628704Z","<prov.DbConnectionPool.CleanupCallback|RES|INFO|CPOOL> 134"
"2021-03-03T05:25:06.1629425Z","<prov.DbConnectionPool.PoolCreateRequest|RES|INFO|CPOOL> 134"
"2021-03-03T05:25:06.1629460Z","<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 134"
"2021-03-03T05:25:06.1629506Z",462482
"2021-03-03T05:25:15.9186711Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:25:45.9180429Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:26:15.9191829Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:26:45.9183417Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:27:15.9193595Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:27:45.9183183Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:28:15.9187614Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:28:26.1618389Z","<prov.DbConnectionPool.CleanupCallback|RES|INFO|CPOOL> 134"
"2021-03-03T05:28:26.1618927Z","<prov.DbConnectionPool.PoolCreateRequest|RES|INFO|CPOOL> 134"
"2021-03-03T05:28:26.1619220Z","<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 134"
"2021-03-03T05:28:26.1619261Z",462483
"2021-03-03T05:28:45.9179959Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:29:15.9189774Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:29:45.9186540Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:30:15.9189091Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"2021-03-03T05:30:41.7956648Z","<prov.DbConnectionHelper.ConnectionString_Set|API> 180785, 'Data Source=tcp:xxxxx.database.windows.net,1433;Initial Catalog=xxxx;User Id=USER@xxxxx.database.windows.net;Max Pool Size=200;ConnectRetryCount=0;MultipleActiveResultSets=False;'"
"2021-03-03T05:30:41.7956680Z","<prov.DbConnectionHelper.CreateDbCommand|API> 180785"
"2021-03-03T05:30:41.7956714Z","<sc.SqlCommand.set_Connection|API> 474909, 180785"
"2021-03-03T05:30:41.7956734Z",9927473
"2021-03-03T05:30:41.7956782Z","<sc.SqlCommand.set_CommandText|API> 474909, String Value = 'QUERY_TEXT'"
"2021-03-03T05:30:41.7956911Z","<sc.SqlConnection.OpenAsync|API> 180785"
"2021-03-03T05:30:41.7957004Z","<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1"
"2021-03-03T05:30:41.7957068Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:30:41.7957160Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Wait timed out."
"2021-03-03T05:30:41.7959129Z",462484
"2021-03-03T05:30:41.7959458Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:30:41.7959559Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Creating new connection."
"2021-03-03T05:30:41.7959717Z","<sc.SqlInternalConnectionTds.LoginNoFailover|ADV> 313, host=tcp:xxxxx.database.windows.net,1433"
"2021-03-03T05:30:41.7959771Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 308, after incrementing _pendingCallbacks: 1"
"2021-03-03T05:30:41.7959811Z","<sc.SqlInternalConnectionTds.AttemptOneLogin|ADV> 313, timout=14999[msec], server=tcp:xxxxx.database.windows.net,1433"
"2021-03-03T05:30:41.7959829Z","<sc.TdsParser.Connect|SEC> SQL authentication"
"2021-03-03T05:30:41.8191634Z","<sc.TdsParser.Connect|SEC> Sending prelogin handshake"
"2021-03-03T05:30:41.8191839Z","<sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 2bab5025-ff5d-43a4-840f-fa36dadc1dd9, ActivityID 95ca93d5-004a-41d3-a080-c22ac8548082:1"
"2021-03-03T05:30:41.8192301Z","<sc.TdsParser.Connect|SEC> Consuming prelogin handshake"
"2021-03-03T05:30:41.8211967Z","<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes"
"2021-03-03T05:30:41.8212302Z",478015
"2021-03-03T05:30:41.8212322Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8250548Z",478016
"2021-03-03T05:30:41.8250615Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8250657Z",478017
"2021-03-03T05:30:41.8250664Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8250708Z",478018
"2021-03-03T05:30:41.8255462Z","<sc.SNI.SslOverTdsStream.Write |SNI|INFO|SCOPE> writing encapsulated bytes"
"2021-03-03T05:30:41.8255826Z",478019
"2021-03-03T05:30:41.8255838Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8278040Z",478020
"2021-03-03T05:30:41.8278126Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8278148Z",478021
"2021-03-03T05:30:41.8278330Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8278353Z",478022
"2021-03-03T05:30:41.8278362Z","<sc.SNI.SslOverTdsStream.Read |SNI|INFO|SCOPE> reading encapsulated bytes"
"2021-03-03T05:30:41.8278392Z",478023
"2021-03-03T05:30:41.8614954Z","<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|SCOPE|INFO >"
"2021-03-03T05:30:41.8614987Z","<sc.SNI.SNICommon.ValidateSslServerCertificate |SNI|INFO > SSL Server certificate validated."
"2021-03-03T05:30:41.8614992Z",478024
"2021-03-03T05:30:41.8615067Z","<sc.SNI.SslOverTdsStream.FinishHandshake |SNI|INFO> switched from encapsulation to passthrough mode"
"2021-03-03T05:30:41.8615227Z","<sc.TdsParser.TdsLogin|ADV> 308, TDS Login7 flags = 268436448:"
"2021-03-03T05:30:41.8956399Z","<sc.SqlConnection.OpenAsyncRetry|Info> 180785"
"2021-03-03T05:30:41.9176149Z","<sc.TdsParser.TryRun|SEC> Received login acknowledgement token"
"2021-03-03T05:30:41.9176306Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for TCE"
"2021-03-03T05:30:41.9176332Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for GlobalTransactions"
"2021-03-03T05:30:41.9176356Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for DATACLASSIFICATION"
"2021-03-03T05:30:41.9176374Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for UTF8 support"
"2021-03-03T05:30:41.9176396Z","<sc.SqlInternalConnectionTds.OnFeatureExtAck|ADV> 313, Received feature extension acknowledgement for SQLDNSCACHING"
"2021-03-03T05:30:41.9176576Z","<sc.SqlInternalConnectionTds.CompleteLogin|ADV> Post-Login Phase: Server connection obtained."
"2021-03-03T05:30:41.9176875Z","<sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn."
"2021-03-03T05:30:41.9176909Z","<sc.SqlInternalConnectionTds.ctor|ADV> 313, constructed new TDS internal connection"
"2021-03-03T05:30:41.9176954Z","<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created."
"2021-03-03T05:30:41.9176990Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:30:41.9177033Z","<prov.DbConnectionPool.CreateObject|RES|CPOOL> 134, Connection 313, Added to pool."
"2021-03-03T05:30:41.9177123Z","<prov.DbConnectionInternal.PostPop|RES|CPOOL> 313, Preparing to pop from pool,  owning connection 0, pooledCount=0"
"2021-03-03T05:30:41.9177147Z","<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 313, Activating"
"2021-03-03T05:30:41.9177189Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:30:41.9177212Z","<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 313, Deactivating."
"2021-03-03T05:30:41.9177229Z","<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 313, Deactivating"
"2021-03-03T05:30:41.9177248Z","<sc.SqlInternalConnection.Deactivate|ADV> 313 deactivating"
"2021-03-03T05:30:41.9177271Z","<sc.TdsParser.Deactivate|ADV> 308 deactivating"
"2021-03-03T05:30:41.9177653Z","<sc.TdsParser.Deactivate|STATE> 308 \n\t         _physicalStateObj = False\n\t         _pMarsPhysicalConObj = True\n\t         _state = OpenLoggedIn\n\t         _server = tcp:xxxxx.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 = 0\n\t         _fMARS = 313\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:30:41.9177684Z","<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 313, Pushing to general pool."
"2021-03-03T05:30:41.9951474Z","<prov.DbConnectionHelper.CreateDbCommand|API> 180785"
"2021-03-03T05:30:41.9951531Z","<sc.SqlCommand.set_Connection|API> 474910, 180785"
"2021-03-03T05:30:41.9951541Z",9927474
"2021-03-03T05:30:41.9951596Z","<sc.SqlCommand.set_CommandText|API> 474910, String Value = 'QUERY_TEXT'"
"2021-03-03T05:30:41.9951723Z","<sc.SqlConnection.OpenAsync|API> 180785"
"2021-03-03T05:30:41.9951848Z","<sc.SqlConnection.OpenAsync|API|Correlation> ObjectID 180785, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1"
"2021-03-03T05:30:41.9951927Z","<prov.DbConnectionPool.GetConnection|RES|CPOOL> 134, Getting connection."
"2021-03-03T05:30:41.9952026Z","<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 134, Connection 313, Popped from general pool."
"2021-03-03T05:30:41.9952164Z","<prov.DbConnectionInternal.PostPop|RES|CPOOL> 313, Preparing to pop from pool,  owning connection 0, pooledCount=0"
"2021-03-03T05:30:41.9952178Z","<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 313, Activating"
"2021-03-03T05:30:41.9952200Z",462485
"2021-03-03T05:30:41.9952271Z","<sc.SqlCommand.ExecuteReaderAsync|API|Correlation> ObjectID 474910, behavior=0, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1"
"2021-03-03T05:30:41.9952421Z","<sc.TdsParser.GetSession|ADV> 308 getting physical session 308"
"2021-03-03T05:30:41.9952517Z","<sc.SqlCommand.ExecuteReader|INFO> 474910, Command executed as RPC."
"2021-03-03T05:30:41.9952667Z","<sc.SNI.SNIMarsHandle.SendAsync |SNI|INFO|SCOPE>"
"2021-03-03T05:30:41.9952899Z",478025
"2021-03-03T05:30:41.9954560Z","<sc.TdsParserStateObject.IncrementPendingCallbacks|ADV> 308, after incrementing _pendingCallbacks: 2"
"2021-03-03T05:30:41.9983573Z","<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 308, after decrementing _pendingCallbacks: 1"
"2021-03-03T05:30:41.9983840Z","<sc.SqlCommand.EndExecuteReaderAsync|Info|Correlation> ObjectID474910, ActivityID 6cd20906-9364-4a5c-964c-ec5afce57eb9:1"
"2021-03-03T05:30:41.9984100Z","418716, 1, 0"
"2021-03-03T05:30:41.9987088Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:30:41.9987108Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:30:41.9987147Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> 308, NBCROW bitmap received, column count = 18"
"2021-03-03T05:30:41.9987224Z","<sc.TdsParserStateObject.NullBitmap.Initialize|INFO|ADV> NBCROW bitmap data:"
"2021-03-03T05:30:41.9987238Z",9927476
"2021-03-03T05:30:41.9987457Z",9927475
"2021-03-03T05:30:41.9987527Z","<sc.SqlDataReader.ReadAsync|API> 1"
"2021-03-03T05:30:41.9987541Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:30:41.9987554Z",9927478
"2021-03-03T05:30:41.9987561Z",9927477
"2021-03-03T05:30:41.9987586Z","<sc.SqlDataReader.NextResultAsync|API> 1"
"2021-03-03T05:30:41.9987604Z","<sc.SqlDataReader.NextResult|API> 1"
"2021-03-03T05:30:41.9987614Z","<sc.SqlDataReader.Read|API> 1"
"2021-03-03T05:30:41.9987642Z",9927481
"2021-03-03T05:30:41.9987657Z",9927480
"2021-03-03T05:30:41.9987663Z",9927479
"2021-03-03T05:30:41.9987674Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:30:41.9987693Z",9927482
"2021-03-03T05:30:41.9987701Z","<sc.SqlDataReader.Close|API> 1"
"2021-03-03T05:30:41.9987705Z",9927483
"2021-03-03T05:30:41.9988848Z","<sc.SqlConnection.Close|API> 180785"
"2021-03-03T05:30:41.9988889Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1"
"2021-03-03T05:30:41.9988910Z","<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 313 Closing."
"2021-03-03T05:30:41.9988943Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:30:41.9988960Z","<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 313, Deactivating."
"2021-03-03T05:30:41.9988973Z","<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 313, Deactivating"
"2021-03-03T05:30:41.9988987Z","<sc.SqlInternalConnection.Deactivate|ADV> 313 deactivating"
"2021-03-03T05:30:41.9989021Z","<sc.TdsParser.Deactivate|ADV> 308 deactivating"
"2021-03-03T05:30:41.9989199Z","<sc.TdsParser.Deactivate|STATE> 308 \n\t         _physicalStateObj = False\n\t         _pMarsPhysicalConObj = True\n\t         _state = OpenLoggedIn\n\t         _server = tcp:xxxxx.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 = 0\n\t         _fMARS = 313\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:30:41.9989221Z","<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 134, Connection 313, Pushing to general pool."
"2021-03-03T05:30:41.9989283Z",9927484
"2021-03-03T05:30:41.9992923Z","<sc.SqlConnection.Close|API> 180785"
"2021-03-03T05:30:41.9992959Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180785, ActivityID f06cf9fa-72fe-4c26-b607-49740dbc6e16:1"
"2021-03-03T05:30:41.9992975Z",9927485
"2021-03-03T05:30:45.9176888Z","<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1"
"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:xxxxx.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:xxxxx.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 = 'QUERY_TEXT'"
"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"
"2021-03-03T05:31:14.7497098Z","<sc.SqlConnection.Close|API> 180782"
"2021-03-03T05:31:14.7497130Z","<sc.SqlConnection.Close|API|Correlation> ObjectID 180782, ActivityID 8a720bab-d6ec-40e4-9901-0eae4f411637:1"
"2021-03-03T05:31:14.7497147Z","<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 313 Closing."
"2021-03-03T05:31:14.7497174Z","<prov.DbConnectionInternal.PrePush|RES|CPOOL> 313, Preparing to push into pool, owning connection 0, pooledCount=0"
"2021-03-03T05:31:14.7497189Z","<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 134, Connection 313, Deactivating."
"2021-03-03T05:31:14.7497198Z","<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 313, Deactivating"
"2021-03-03T05:31:14.7497208Z","<sc.SqlInternalConnection.Deactivate|ADV> 313 deactivating"
"2021-03-03T05:31:14.7497220Z","<prov.DbConnectionInternal.DoomThisConnection|RES|INFO|CPOOL> 313, Dooming"
"2021-03-03T05:31:14.7497230Z","<sc.TdsParser.Deactivate|ADV> 308 deactivating"
"2021-03-03T05:31:14.7497394Z","<sc.TdsParser.Deactivate|STATE> 308 \n\t         _physicalStateObj = False\n\t         _pMarsPhysicalConObj = True\n\t         _state = OpenLoggedIn\n\t         _server = tcp:xxxxx.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 = 313\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.7497408Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 313, Removing from pool."
"2021-03-03T05:31:14.7497430Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 313, Removed from pool."
"2021-03-03T05:31:14.7497439Z","<sc.SqlInternalConnectionTds.Dispose|ADV> 313 disposing"
"2021-03-03T05:31:14.7498729Z","<sc.TdsParserStateObject.DecrementPendingCallbacks|ADV> 308, after decrementing _pendingCallbacks: 0"
"2021-03-03T05:31:14.7498744Z","<prov.DbConnectionPool.DestroyObject|RES|CPOOL> 134, Connection 313, Disposed."
"2021-03-03T05:31:14.7498862Z",9927489
"2021-03-03T05:31:14.7499373Z","<prov.DbConnectionPool.PoolCreateRequest|RES|INFO|CPOOL> 134"
"2021-03-03T05:31:14.7499392Z","<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> 134"
"2021-03-03T05:31:14.7499403Z",462488

[cheenamalhotra]

There's a chunk of trace missing here (30 seconds) or is there literally no activity?
Secondly, I see no other entry of SqlCommand with Object Id 474906, maybe it started read a while ago? Can you find any other log for this SqlCommand object?

[cheenamalhotra]

On the contrary, can you check and tell if your application is doing something like below, theoretically:

SqlConnection conn = new SqlConnection(connString);

try
{
    SqlCommand command = new SqlCommand("QUERY_TEXT", conn);
    // execute and read
}
catch { }

try
{
    // Continues to use old connection irrespective of whether last command failed with FATAL exception.
    SqlCommand command = new SqlCommand("ANOTHER QUERY_TEXT", conn);
    // execute and read
}
catch { }

Because from the logs if you see carefully, look at below lines:

// This is where 311 connection is doomed (forced killed due to FATAL CLASS (20) error)
"2021-03-03T05:31:14.7418023Z","<sc.SqlConnection.Close|API> 180782"

// Another commnd tries to use the same DEAD connection (Object 180782)
"2021-03-03T05:31:14.7468423Z","<sc.SqlCommand.set_Connection|API> 474911, 180782"

It seems that the same connection is still being used by your application in next command even when it failed with FATAL CLASS error which is non-retriable error class.

So there are 2 possibilities, for which you can provide more info:

1. Application did not receive this FATAL error?
2. Application swallows it somehow and continues to work with the same connection instance?

[lbargery]

@cheenamalhotra Don't think there are any extra logs in that 30 second window. This is how I'm capturing logs

public class SqlClientListener : EventListener
    {
        private readonly ConcurrentQueue<EventWrittenEventArgs> _logBuilder = new ConcurrentQueue<EventWrittenEventArgs>();

        public static async Task PerformWithSqlListening(Func<Task> fnPerform)
        {
            using var listener = new SqlClientListener();

            try
            {
                await fnPerform();
            }
            catch
            {
                foreach (var log in listener._logBuilder)
                {
                    LogWith.NoSampling(logger => logger.Information("SqlClient: {TimeStamp} {Level} {EventId} {ActivityID} {RelatedActivityID} {OpCode} {ThreadID} {Logs}",
                        log.TimeStamp, log.Level, log.EventId, log.ActivityId, log.RelatedActivityId, log.Opcode, log.OSThreadId, log.Payload?.ToCommaSeperated(x => x?.ToString())));
                }
                throw;
            }
        }

        protected override void OnEventSourceCreated(EventSource eventSource)
        {
            // Only enable events from SqlClientEventSource.
            if (eventSource.Name.Equals("Microsoft.Data.SqlClient.EventSource"))
            {
                //Capture all events, verbose
                EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All);
            }
        }

        // This callback runs whenever an event is written by SqlClientEventSource.
        // Event data is accessed through the EventWrittenEventArgs parameter.
        protected override void OnEventWritten(EventWrittenEventArgs eventData) => _logBuilder.Enqueue(eventData);
    }

The idea is that we only emit the verbose Sql client logs if an exception actually goes off. Let me know if we're using this wrong or misunderstood something though.

With regards to your re-using SQL connection, I can't be 100% sure but I would be very surprised. We don't interact at all with your raw library, we use EF core for all our database interactions. The context is passed into this azure function via dependency injection and we just execute a single query which immediately throws. Again not sure if helpful, but we've found that the EF core context seems to be broken after this particular exception, we can't perform an "outer" retry of the same query.

[lbargery]

I would have also expected if we were doing something like that, for this to go off more often. On the particular azure function we are logging, I see this error about 1-4 times a day (function is executing 100,000s of times a day)