From ca7bedcf17737ac73f96a7e47c3997c57b234542 Mon Sep 17 00:00:00 2001 From: Davoud Eshtehari Date: Mon, 30 Aug 2021 13:15:51 -0700 Subject: [PATCH] Reset cached async state on disposing a command (#1128) --- .../Data/SqlClient/SNI/SNIStreams.cs | 20 +++++ .../Microsoft/Data/SqlClient/SqlCommand.cs | 87 +++++++++++++++---- .../Data/SqlClient/TdsParserStateObject.cs | 1 + .../Microsoft/Data/SqlClient/SqlCommand.cs | 24 +++++ .../SqlConnectionReliabilityTest.cs | 30 +++---- 5 files changed, 129 insertions(+), 33 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIStreams.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIStreams.cs index eb8661d022..174f563ecd 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIStreams.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIStreams.cs @@ -33,6 +33,11 @@ public override async Task ReadAsync(byte[] buffer, int offset, int count, { return await base.ReadAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false); } + catch (System.Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNISslStream), EventType.ERR, "Internal Exception occurred while reading data: {0}", args0: e?.Message); + throw; + } finally { _readAsyncSemaphore.Release(); @@ -47,6 +52,11 @@ public override async Task WriteAsync(byte[] buffer, int offset, int count, Canc { await base.WriteAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false); } + catch (System.Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNISslStream), EventType.ERR, "Internal Exception occurred while writing data: {0}", args0: e?.Message); + throw; + } finally { _writeAsyncSemaphore.Release(); @@ -76,6 +86,11 @@ public override async Task ReadAsync(byte[] buffer, int offset, int count, { return await base.ReadAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false); } + catch (System.Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINetworkStream), EventType.ERR, "Internal Exception occurred while reading data: {0}", args0: e?.Message); + throw; + } finally { _readAsyncSemaphore.Release(); @@ -90,6 +105,11 @@ public override async Task WriteAsync(byte[] buffer, int offset, int count, Canc { await base.WriteAsync(buffer, offset, count, cancellationToken).ConfigureAwait(false); } + catch (System.Exception e) + { + SqlClientEventSource.Log.TrySNITraceEvent(nameof(SNINetworkStream), EventType.ERR, "Internal Exception occurred while writing data: {0}", args0: e?.Message); + throw; + } finally { _writeAsyncSemaphore.Release(); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs index 24a82db701..b7a8a559f6 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -253,6 +253,8 @@ internal bool IsActiveConnectionValid(SqlConnection activeConnection) internal void ResetAsyncState() { + SqlClientEventSource.Log.TryTraceEvent("CachedAsyncState.ResetAsyncState | API | ObjectId {0}, Client Connection Id {1}, AsyncCommandInProgress={2}", + _cachedAsyncConnection?.ObjectID, _cachedAsyncConnection?.ClientConnectionId, _cachedAsyncConnection?.AsyncCommandInProgress); _cachedAsyncCloseCount = -1; _cachedAsyncResult = null; if (_cachedAsyncConnection != null) @@ -270,6 +272,7 @@ internal void SetActiveConnectionAndResult(TaskCompletionSource completi { Debug.Assert(activeConnection != null, "Unexpected null connection argument on SetActiveConnectionAndResult!"); TdsParser parser = activeConnection?.Parser; + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.SetActiveConnectionAndResult | API | ObjectId {0}, Client Connection Id {1}, MARS={2}", activeConnection?.ObjectID, activeConnection?.ClientConnectionId, parser?.MARSOn); if ((parser == null) || (parser.State == TdsParserState.Closed) || (parser.State == TdsParserState.Broken)) { throw ADP.ClosedConnectionError(); @@ -1011,8 +1014,12 @@ protected override DbParameter CreateDbParameter() protected override void Dispose(bool disposing) { if (disposing) - { // release managed objects + { + // release managed objects _cachedMetaData = null; + + // reset async cache information to allow a second async execute + _cachedAsyncState?.ResetAsyncState(); } // release unmanaged objects base.Dispose(disposing); @@ -1271,14 +1278,23 @@ private void BeginExecuteNonQueryInternalReadStage(TaskCompletionSource cachedAsyncState.SetActiveConnectionAndResult(completion, nameof(EndExecuteNonQuery), _activeConnection); _stateObj.ReadSni(completion); } + // Cause of a possible unstable runtime situation on facing with `OutOfMemoryException` and `StackOverflowException` exceptions, + // trying to call further functions in the catch of either may fail that should be considered on debuging! + catch (System.OutOfMemoryException e) + { + _activeConnection.Abort(e); + throw; + } + catch (System.StackOverflowException e) + { + _activeConnection.Abort(e); + throw; + } catch (Exception) { // Similarly, if an exception occurs put the stateObj back into the pool. // and reset async cache information to allow a second async execute - if (null != _cachedAsyncState) - { - _cachedAsyncState.ResetAsyncState(); - } + _cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw; } @@ -1287,7 +1303,9 @@ private void BeginExecuteNonQueryInternalReadStage(TaskCompletionSource private void VerifyEndExecuteState(Task completionTask, string endMethod, bool fullCheckForColumnEncryption = false) { Debug.Assert(completionTask != null); - + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.VerifyEndExecuteState | API | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); if (completionTask.IsCanceled) { if (_stateObj != null) @@ -1394,10 +1412,7 @@ public int EndExecuteNonQueryAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage - if (cachedAsyncState != null) - { - cachedAsyncState.ResetAsyncState(); - } + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -1460,6 +1475,9 @@ private int EndExecuteNonQueryInternal(IAsyncResult asyncResult) private object InternalEndExecuteNonQuery(IAsyncResult asyncResult, bool isInternal, [CallerMemberName] string endMethod = "") { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalEndExecuteNonQuery | INFO | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); @@ -1544,6 +1562,8 @@ private object InternalEndExecuteNonQuery(IAsyncResult asyncResult, bool isInter private Task InternalExecuteNonQuery(TaskCompletionSource completion, bool sendToPipe, int timeout, out bool usedCache, bool asyncWrite = false, bool inRetry = false, [CallerMemberName] string methodName = "") { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteNonQuery | INFO | ObjectId {0}, Client Connection Id {1}, AsyncCommandInProgress={2}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, _activeConnection?.AsyncCommandInProgress); bool isAsync = (null != completion); usedCache = false; @@ -1780,14 +1800,25 @@ private void BeginExecuteXmlReaderInternalReadStage(TaskCompletionSource _cachedAsyncState.SetActiveConnectionAndResult(completion, nameof(EndExecuteXmlReader), _activeConnection); _stateObj.ReadSni(completion); } + // Cause of a possible unstable runtime situation on facing with `OutOfMemoryException` and `StackOverflowException` exceptions, + // trying to call further functions in the catch of either may fail that should be considered on debuging! + catch (System.OutOfMemoryException e) + { + _activeConnection.Abort(e); + completion.TrySetException(e); + throw; + } + catch (System.StackOverflowException e) + { + _activeConnection.Abort(e); + completion.TrySetException(e); + throw; + } catch (Exception e) { // Similarly, if an exception occurs put the stateObj back into the pool. // and reset async cache information to allow a second async execute - if (null != _cachedAsyncState) - { - _cachedAsyncState.ResetAsyncState(); - } + _cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); completion.TrySetException(e); } @@ -1814,6 +1845,7 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) Exception asyncException = ((Task)asyncResult).Exception; if (asyncException != null) { + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2011,6 +2043,7 @@ internal SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) Exception asyncException = ((Task)asyncResult).Exception; if (asyncException != null) { + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2034,6 +2067,9 @@ internal SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) private SqlDataReader EndExecuteReaderInternal(IAsyncResult asyncResult) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.EndExecuteReaderInternal | API | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); SqlStatistics statistics = null; bool success = false; int? sqlExceptionNumber = null; @@ -2404,6 +2440,7 @@ long firstAttemptStart private void BeginExecuteReaderInternalReadStage(TaskCompletionSource completion) { Debug.Assert(completion != null, "CompletionSource should not be null"); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); // Read SNI does not have catches for async exceptions, handle here. try { @@ -2411,14 +2448,25 @@ private void BeginExecuteReaderInternalReadStage(TaskCompletionSource co cachedAsyncState.SetActiveConnectionAndResult(completion, nameof(EndExecuteReader), _activeConnection); _stateObj.ReadSni(completion); } + // Cause of a possible unstable runtime situation on facing with `OutOfMemoryException` and `StackOverflowException` exceptions, + // trying to call further functions in the catch of either may fail that should be considered on debuging! + catch (System.OutOfMemoryException e) + { + _activeConnection.Abort(e); + completion.TrySetException(e); + throw; + } + catch (System.StackOverflowException e) + { + _activeConnection.Abort(e); + completion.TrySetException(e); + throw; + } catch (Exception e) { // Similarly, if an exception occurs put the stateObj back into the pool. // and reset async cache information to allow a second async execute - if (null != _cachedAsyncState) - { - _cachedAsyncState.ResetAsyncState(); - } + _cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); completion.TrySetException(e); } @@ -2426,6 +2474,9 @@ private void BeginExecuteReaderInternalReadStage(TaskCompletionSource co private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, bool isInternal, string endMethod) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalEndExecuteReader | INFO | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 05bba67a5a..deb023f228 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -2864,6 +2864,7 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) // to the outstanding GCRoot until AppDomain.Unload. // We live with the above for the time being due to the constraints of the current // reliability infrastructure provided by the CLR. + SqlClientEventSource.Log.TryTraceEvent("TdsParserStateObject.ReadAsyncCallback | Info | State Object Id {0}, received error {1} on idle connection", _objectID, (int)error); TaskCompletionSource source = _networkPacketTaskSource; #if DEBUG diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs index b0f8dc3d50..05de498e78 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -223,6 +223,8 @@ internal bool IsActiveConnectionValid(SqlConnection activeConnection) [ReliabilityContract(Consistency.WillNotCorruptState, Cer.Success)] internal void ResetAsyncState() { + SqlClientEventSource.Log.TryTraceEvent("CachedAsyncState.ResetAsyncState | API | ObjectId {0}, Client Connection Id {1}, AsyncCommandInProgress={2}", + _cachedAsyncConnection?.ObjectID, _cachedAsyncConnection?.ClientConnectionId, _cachedAsyncConnection?.AsyncCommandInProgress); _cachedAsyncCloseCount = -1; _cachedAsyncResult = null; if (_cachedAsyncConnection != null) @@ -240,6 +242,7 @@ internal void SetActiveConnectionAndResult(TaskCompletionSource completi { Debug.Assert(activeConnection != null, "Unexpected null connection argument on SetActiveConnectionAndResult!"); TdsParser parser = activeConnection.Parser; + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.SetActiveConnectionAndResult | API | ObjectId {0}, Client Connection Id {1}, MARS={2}", activeConnection?.ObjectID, activeConnection?.ClientConnectionId, parser?.MARSOn); if ((parser == null) || (parser.State == TdsParserState.Closed) || (parser.State == TdsParserState.Broken)) { throw ADP.ClosedConnectionError(); @@ -1334,6 +1337,9 @@ protected override void Dispose(bool disposing) if (disposing) { // release managed objects _cachedMetaData = null; + + // reset async cache information to allow a second async execute + _cachedAsyncState?.ResetAsyncState(); } // release unmanaged objects base.Dispose(disposing); @@ -1645,6 +1651,9 @@ private void BeginExecuteNonQueryInternalReadStage(TaskCompletionSource private void VerifyEndExecuteState(Task completionTask, string endMethod, bool fullCheckForColumnEncryption = false) { Debug.Assert(completionTask != null); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.VerifyEndExecuteState | API | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); if (completionTask.IsCanceled) { @@ -1751,6 +1760,7 @@ private int EndExecuteNonQueryAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -1812,6 +1822,9 @@ private int EndExecuteNonQueryInternal(IAsyncResult asyncResult) private object InternalEndExecuteNonQuery(IAsyncResult asyncResult, string endMethod, bool isInternal) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalEndExecuteNonQuery | INFO | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); TdsParser bestEffortCleanupTarget = null; RuntimeHelpers.PrepareConstrainedRegions(); @@ -1932,6 +1945,8 @@ private object InternalEndExecuteNonQuery(IAsyncResult asyncResult, string endMe private Task InternalExecuteNonQuery(TaskCompletionSource completion, string methodName, bool sendToPipe, int timeout, out bool usedCache, bool asyncWrite = false, bool inRetry = false) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteNonQuery | INFO | ObjectId {0}, Client Connection Id {1}, AsyncCommandInProgress={2}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, _activeConnection?.AsyncCommandInProgress); bool async = (null != completion); usedCache = false; @@ -2264,6 +2279,7 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2526,6 +2542,7 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2550,6 +2567,9 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) private SqlDataReader EndExecuteReaderInternal(IAsyncResult asyncResult) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.EndExecuteReaderInternal | API | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); SqlStatistics statistics = null; bool success = false; int? sqlExceptionNumber = null; @@ -2801,6 +2821,7 @@ private bool TriggerInternalEndAndRetryIfNecessary(CommandBehavior behavior, obj private void BeginExecuteReaderInternalReadStage(TaskCompletionSource completion) { Debug.Assert(completion != null, "CompletionSource should not be null"); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteReaderInternalReadStage | INFO | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); // Read SNI does not have catches for async exceptions, handle here. TdsParser bestEffortCleanupTarget = null; RuntimeHelpers.PrepareConstrainedRegions(); @@ -2862,6 +2883,9 @@ private void BeginExecuteReaderInternalReadStage(TaskCompletionSource co private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, string endMethod, bool isInternal) { + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalEndExecuteReader | INFO | ObjectId {0}, Client Connection Id {1}, MARS={2}, AsyncCommandInProgress={3}", + _activeConnection?.ObjectID, _activeConnection?.ClientConnectionId, + _activeConnection?.Parser?.MARSOn, _activeConnection?.AsyncCommandInProgress); VerifyEndExecuteState((Task)asyncResult, endMethod); WaitForAsyncResults(asyncResult, isInternal); diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/RetryLogic/SqlConnectionReliabilityTest.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/RetryLogic/SqlConnectionReliabilityTest.cs index 7e2e33db54..628866589e 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/RetryLogic/SqlConnectionReliabilityTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/RetryLogic/SqlConnectionReliabilityTest.cs @@ -66,34 +66,34 @@ public void CreateDatabaseWhileTryingToConnect(string cnnString, SqlRetryLogicBa using (var cnn1 = new SqlConnection(new SqlConnectionStringBuilder(cnnString) { ConnectTimeout = 60, Pooling = false }.ConnectionString)) { cnn1.Open(); - Task createDBTask = null; - try + using (var cmd = cnn1.CreateCommand()) { - provider.Retrying += (s, e) => + Task createDBTask = null; + try { - currentRetries = e.RetryCount; - using (var cmd = cnn1.CreateCommand()) + provider.Retrying += (s, e) => { + currentRetries = e.RetryCount; // Try to create database just after first faliure. if (createDBTask == null || createDBTask.Status == TaskStatus.Faulted) { cmd.CommandText = $"IF (NOT EXISTS(SELECT 1 FROM sys.databases WHERE name = '{database}')) CREATE DATABASE [{database}];"; createDBTask = cmd.ExecuteNonQueryAsync(); } - } - }; + }; - using (var cnn2 = new SqlConnection(builder.ConnectionString)) + using (var cnn2 = new SqlConnection(builder.ConnectionString)) + { + cnn2.RetryLogicProvider = provider; + cnn2.Open(); + } + } + finally { - cnn2.RetryLogicProvider = provider; - cnn2.Open(); + createDBTask?.Wait(); + DataTestUtility.DropDatabase(cnn1, database); } } - finally - { - createDBTask?.Wait(); - DataTestUtility.DropDatabase(cnn1, database); - } } Assert.True(currentRetries > 0); }