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..4a23d7b2f4 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("SNISslStream.ReadAsync | 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("SNISslStream.ReadAsync | 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("SNINetworkStream.ReadAsync | 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("SNINetworkStream.ReadAsync | 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 10d5064a87..6e0f4ac5a5 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 @@ -235,6 +235,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) @@ -252,6 +254,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(); @@ -972,8 +975,12 @@ override protected DbParameter CreateDbParameter() override protected 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); @@ -1213,14 +1220,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; } @@ -1229,7 +1245,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) @@ -1336,10 +1354,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; } @@ -1402,6 +1417,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); @@ -1486,6 +1504,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; @@ -1716,14 +1736,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); } @@ -1750,6 +1781,7 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) Exception asyncException = ((Task)asyncResult).Exception; if (asyncException != null) { + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -1944,6 +1976,7 @@ internal SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) Exception asyncException = ((Task)asyncResult).Exception; if (asyncException != null) { + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -1967,6 +2000,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; @@ -2337,6 +2373,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 { @@ -2344,14 +2381,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); } @@ -2359,6 +2407,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 94f7f32ea9..b60027db1f 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 @@ -2859,6 +2859,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 d19c2b16bd..65c51a537c 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 @@ -206,6 +206,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) @@ -223,6 +225,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(); @@ -1320,6 +1323,9 @@ override protected void Dispose(bool disposing) //_statistics = null; //CommandText = null; _cachedMetaData = null; + + // reset async cache information to allow a second async execute + _cachedAsyncState?.ResetAsyncState(); } // release unmanaged objects base.Dispose(disposing); @@ -1615,6 +1621,10 @@ private void VerifyEndExecuteState(Task completionTask, String endMethod, bool f { throw ADP.ArgumentNull("asyncResult"); } + 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) @@ -1720,6 +1730,7 @@ private int EndExecuteNonQueryAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -1787,6 +1798,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(); @@ -1907,6 +1921,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; @@ -2237,6 +2253,7 @@ private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2492,6 +2509,7 @@ private SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) if (asyncException != null) { // Leftover exception from the Begin...InternalReadStage + cachedAsyncState?.ResetAsyncState(); ReliablePutStateObject(); throw asyncException.InnerException; } @@ -2516,6 +2534,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; @@ -2766,6 +2787,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(); @@ -2827,7 +2849,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/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs index d7f0decbf5..ef54f791fb 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlClientEventSource.cs @@ -739,6 +739,15 @@ internal void TryCorrelationTraceEvent(string message, T0 args0) CorrelationTrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr)); } } + + [NonEvent] + internal void TryCorrelationTraceEvent(string message, T0 args0, T1 args1, T2 args2, T3 args3) + { + if (Log.IsCorrelationEnabled()) + { + CorrelationTrace(string.Format(message, args0?.ToString() ?? NullStr, args1?.ToString() ?? NullStr, args2?.ToString() ?? NullStr, args3?.ToString() ?? NullStr)); + } + } #endregion #region State Dump without if statements