From dbabd7678d2290f1aef44815fe96b4310cd0c3e6 Mon Sep 17 00:00:00 2001 From: Thomas Stringer Date: Tue, 22 Mar 2016 20:35:21 -0400 Subject: [PATCH] Added diagnostics to sqlclient --- .../src/System.Data.SqlClient.csproj | 3 +- .../SqlClientDiagnosticListenerExtensions.cs | 74 +++ .../src/System/Data/SqlClient/SqlCommand.cs | 110 +++- .../System/Data/SqlClient/SqlConnection.cs | 11 +- src/System.Data.SqlClient/src/project.json | 8 +- .../tests/FunctionalTests/DiagnosticTest.cs | 490 ++++++++++++++++++ .../FakeDiagnosticListenerObserver.cs | 72 +++ .../System.Data.SqlClient.Tests.csproj | 6 +- .../tests/FunctionalTests/project.json | 4 + 9 files changed, 766 insertions(+), 12 deletions(-) create mode 100644 src/System.Data.SqlClient/src/System/Data/SqlClient/SqlClientDiagnosticListenerExtensions.cs create mode 100644 src/System.Data.SqlClient/tests/FunctionalTests/DiagnosticTest.cs create mode 100644 src/System.Data.SqlClient/tests/FunctionalTests/FakeDiagnosticListenerObserver.cs diff --git a/src/System.Data.SqlClient/src/System.Data.SqlClient.csproj b/src/System.Data.SqlClient/src/System.Data.SqlClient.csproj index 81fa44a90fbc..b55914ae8409 100644 --- a/src/System.Data.SqlClient/src/System.Data.SqlClient.csproj +++ b/src/System.Data.SqlClient/src/System.Data.SqlClient.csproj @@ -1,4 +1,4 @@ - + Windows_Debug @@ -88,6 +88,7 @@ + diff --git a/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlClientDiagnosticListenerExtensions.cs b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlClientDiagnosticListenerExtensions.cs new file mode 100644 index 000000000000..e2038e3bce57 --- /dev/null +++ b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlClientDiagnosticListenerExtensions.cs @@ -0,0 +1,74 @@ +using System.Collections; +using System.Diagnostics; +using System.Runtime.CompilerServices; + +namespace System.Data.SqlClient +{ + /// + /// Extension methods on the DiagnosticListener class to log SqlCommand data + /// + internal static class SqlClientDiagnosticListenerExtensions + { + public const string DiagnosticListenerName = "SqlClientDiagnosticListener"; + + private const string SqlClientPrefix = "System.Data.SqlClient."; + public const string SqlBeforeExecuteCommand = SqlClientPrefix + nameof(WriteCommandBefore); + public const string SqlAfterExecuteCommand = SqlClientPrefix + nameof(WriteCommandAfter); + public const string SqlErrorExecuteCommand = SqlClientPrefix + nameof(WriteCommandError); + + public static Guid WriteCommandBefore(this DiagnosticListener @this, SqlCommand sqlCommand, [CallerMemberName] string operation = "") + { + if (@this.IsEnabled(SqlBeforeExecuteCommand)) + { + Guid operationId = Guid.NewGuid(); + + @this.Write( + SqlBeforeExecuteCommand, + new + { + OperationId = operationId, + Operation = operation, + Command = sqlCommand + }); + + return operationId; + } + else + return Guid.Empty; + } + + public static void WriteCommandAfter(this DiagnosticListener @this, Guid operationId, SqlCommand sqlCommand, [CallerMemberName] string operation = "") + { + if (@this.IsEnabled(SqlAfterExecuteCommand)) + { + @this.Write( + SqlAfterExecuteCommand, + new + { + OperationId = operationId, + Operation = operation, + Command = sqlCommand, + Statistics = sqlCommand.Statistics?.GetDictionary(), + Timestamp = Stopwatch.GetTimestamp() + }); + } + } + + public static void WriteCommandError(this DiagnosticListener @this, Guid operationId, SqlCommand sqlCommand, Exception ex, [CallerMemberName] string operation = "") + { + if (@this.IsEnabled(SqlErrorExecuteCommand)) + { + @this.Write( + SqlErrorExecuteCommand, + new + { + OperationId = operationId, + Operation = operation, + Command = sqlCommand, + Exception = ex, + Timestamp = Stopwatch.GetTimestamp() + }); + } + } + } +} \ No newline at end of file diff --git a/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlCommand.cs b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlCommand.cs index db105b91b3e7..37e31c9ba0b1 100644 --- a/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlCommand.cs +++ b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlCommand.cs @@ -23,6 +23,9 @@ public sealed class SqlCommand : DbCommand private UpdateRowSource _updatedRowSource = UpdateRowSource.Both; private bool _designTimeInvisible; + private readonly static DiagnosticListener _diagnosticListener = new DiagnosticListener(SqlClientDiagnosticListenerExtensions.DiagnosticListenerName); + private bool _parentOperationStarted = false; + // Prepare // Against 7.0 Serve a prepare/unprepare requires an extra roundtrip to the server. // @@ -290,7 +293,8 @@ internal SqlStatistics Statistics { if (null != _activeConnection) { - if (_activeConnection.StatisticsEnabled) + if (_activeConnection.StatisticsEnabled || + _diagnosticListener.IsEnabled(SqlClientDiagnosticListenerExtensions.SqlAfterExecuteCommand)) { return _activeConnection.Statistics; } @@ -738,9 +742,11 @@ override public object ExecuteScalar() // between entry into Execute* API and the thread obtaining the stateObject. _pendingCancel = false; - SqlStatistics statistics = null; - + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + SqlStatistics statistics = null; + + Exception e = null; try { statistics = SqlStatistics.StartTimer(Statistics); @@ -748,9 +754,23 @@ override public object ExecuteScalar() ds = RunExecuteReader(0, RunBehavior.ReturnImmediately, returnStream: true); return CompleteExecuteScalar(ds, false); } + catch (Exception ex) + { + e = ex; + throw; + } finally { SqlStatistics.StopTimer(statistics); + + if (e != null) + { + _diagnosticListener.WriteCommandError(operationId, this, e); + } + else + { + _diagnosticListener.WriteCommandAfter(operationId, this); + } } } @@ -790,16 +810,34 @@ override public int ExecuteNonQuery() // between entry into Execute* API and the thread obtaining the stateObject. _pendingCancel = false; + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + SqlStatistics statistics = null; + + Exception e = null; try { statistics = SqlStatistics.StartTimer(Statistics); InternalExecuteNonQuery(completion: null, sendToPipe: false, timeout: CommandTimeout); return _rowsAffected; } + catch (Exception ex) + { + e = ex; + throw; + } finally { SqlStatistics.StopTimer(statistics); + + if (e != null) + { + _diagnosticListener.WriteCommandError(operationId, this, e); + } + else + { + _diagnosticListener.WriteCommandAfter(operationId, this); + } } } @@ -1091,7 +1129,11 @@ public XmlReader ExecuteXmlReader() // between entry into Execute* API and the thread obtaining the stateObject. _pendingCancel = false; + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + SqlStatistics statistics = null; + + Exception e = null; try { statistics = SqlStatistics.StartTimer(Statistics); @@ -1101,9 +1143,23 @@ public XmlReader ExecuteXmlReader() ds = RunExecuteReader(CommandBehavior.SequentialAccess, RunBehavior.ReturnImmediately, returnStream: true); return CompleteXmlReader(ds); } + catch (Exception ex) + { + e = ex; + throw; + } finally { SqlStatistics.StopTimer(statistics); + + if (e != null) + { + _diagnosticListener.WriteCommandError(operationId, this, e); + } + else + { + _diagnosticListener.WriteCommandAfter(operationId, this); + } } } @@ -1286,16 +1342,33 @@ override protected DbDataReader ExecuteDbDataReader(CommandBehavior behavior) // between entry into Execute* API and the thread obtaining the stateObject. _pendingCancel = false; - SqlStatistics statistics = null; + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + SqlStatistics statistics = null; + + Exception e = null; try { statistics = SqlStatistics.StartTimer(Statistics); return RunExecuteReader(behavior, RunBehavior.ReturnImmediately, returnStream: true); } + catch (Exception ex) + { + e = ex; + throw; + } finally { SqlStatistics.StopTimer(statistics); + + if (e != null) + { + _diagnosticListener.WriteCommandError(operationId, this, e); + } + else + { + _diagnosticListener.WriteCommandAfter(operationId, this); + } } } @@ -1438,6 +1511,8 @@ private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, string public override Task ExecuteNonQueryAsync(CancellationToken cancellationToken) { + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + TaskCompletionSource source = new TaskCompletionSource(); CancellationTokenRegistration registration = new CancellationTokenRegistration(); @@ -1462,6 +1537,7 @@ public override Task ExecuteNonQueryAsync(CancellationToken cancellationTok if (t.IsFaulted) { Exception e = t.Exception.InnerException; + _diagnosticListener.WriteCommandError(operationId, this, e); source.SetException(e); } else @@ -1474,11 +1550,13 @@ public override Task ExecuteNonQueryAsync(CancellationToken cancellationTok { source.SetResult(t.Result); } + _diagnosticListener.WriteCommandAfter(operationId, this); } }, TaskScheduler.Default); } catch (Exception e) { + _diagnosticListener.WriteCommandError(operationId, this, e); source.SetException(e); } @@ -1514,6 +1592,10 @@ protected override Task ExecuteDbDataReaderAsync(CommandBehavior b new public Task ExecuteReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken) { + Guid operationId; + if (!_parentOperationStarted) + operationId = _diagnosticListener.WriteCommandBefore(this); + TaskCompletionSource source = new TaskCompletionSource(); CancellationTokenRegistration registration = new CancellationTokenRegistration(); @@ -1538,6 +1620,8 @@ protected override Task ExecuteDbDataReaderAsync(CommandBehavior b if (t.IsFaulted) { Exception e = t.Exception.InnerException; + if (!_parentOperationStarted) + _diagnosticListener.WriteCommandError(operationId, this, e); source.SetException(e); } else @@ -1550,11 +1634,16 @@ protected override Task ExecuteDbDataReaderAsync(CommandBehavior b { source.SetResult(t.Result); } + if (!_parentOperationStarted) + _diagnosticListener.WriteCommandAfter(operationId, this); } }, TaskScheduler.Default); } catch (Exception e) { + if (!_parentOperationStarted) + _diagnosticListener.WriteCommandError(operationId, this, e); + source.SetException(e); } @@ -1563,6 +1652,9 @@ protected override Task ExecuteDbDataReaderAsync(CommandBehavior b public override Task ExecuteScalarAsync(CancellationToken cancellationToken) { + _parentOperationStarted = true; + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + return ExecuteReaderAsync(cancellationToken).ContinueWith((executeTask) => { TaskCompletionSource source = new TaskCompletionSource(); @@ -1572,6 +1664,7 @@ public override Task ExecuteScalarAsync(CancellationToken cancellationTo } else if (executeTask.IsFaulted) { + _diagnosticListener.WriteCommandError(operationId, this, executeTask.Exception.InnerException); source.SetException(executeTask.Exception.InnerException); } else @@ -1589,6 +1682,7 @@ public override Task ExecuteScalarAsync(CancellationToken cancellationTo else if (readTask.IsFaulted) { reader.Dispose(); + _diagnosticListener.WriteCommandError(operationId, this, readTask.Exception.InnerException); source.SetException(readTask.Exception.InnerException); } else @@ -1616,10 +1710,12 @@ public override Task ExecuteScalarAsync(CancellationToken cancellationTo } if (exception != null) { + _diagnosticListener.WriteCommandError(operationId, this, exception); source.SetException(exception); } else { + _diagnosticListener.WriteCommandAfter(operationId, this); source.SetResult(result); } } @@ -1631,6 +1727,7 @@ public override Task ExecuteScalarAsync(CancellationToken cancellationTo } }, TaskScheduler.Default); } + _parentOperationStarted = false; return source.Task; }, TaskScheduler.Default).Unwrap(); } @@ -1642,6 +1739,8 @@ public Task ExecuteXmlReaderAsync() public Task ExecuteXmlReaderAsync(CancellationToken cancellationToken) { + Guid operationId = _diagnosticListener.WriteCommandBefore(this); + TaskCompletionSource source = new TaskCompletionSource(); CancellationTokenRegistration registration = new CancellationTokenRegistration(); @@ -1666,6 +1765,7 @@ public Task ExecuteXmlReaderAsync(CancellationToken cancellationToken if (t.IsFaulted) { Exception e = t.Exception.InnerException; + _diagnosticListener.WriteCommandError(operationId, this, e); source.SetException(e); } else @@ -1678,11 +1778,13 @@ public Task ExecuteXmlReaderAsync(CancellationToken cancellationToken { source.SetResult(t.Result); } + _diagnosticListener.WriteCommandAfter(operationId, this); } }, TaskScheduler.Default); } catch (Exception e) { + _diagnosticListener.WriteCommandError(operationId, this, e); source.SetException(e); } diff --git a/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlConnection.cs b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlConnection.cs index e48828f5d737..ee8a39cdf36a 100644 --- a/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlConnection.cs +++ b/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlConnection.cs @@ -40,6 +40,9 @@ public sealed partial class SqlConnection : DbConnection internal bool _supressStateChangeForReconnection; private int _reconnectCount; + // diagnostics listener + private readonly static DiagnosticListener s_diagnosticListener = new DiagnosticListener(SqlClientDiagnosticListenerExtensions.DiagnosticListenerName); + // Transient Fault handling flag. This is needed to convey to the downstream mechanism of connection establishment, if Transient Fault handling should be used or not // The downstream handling of Connection open is the same for idle connection resiliency. Currently we want to apply transient fault handling only to the connections opened // using SqlConnection.Open() method. @@ -748,7 +751,7 @@ private void CancelOpenAndWait() public override Task OpenAsync(CancellationToken cancellationToken) { PrepareStatisticsForNewConnection(); - + SqlStatistics statistics = null; try { @@ -876,7 +879,8 @@ internal void Retry(Task retryTask) private void PrepareStatisticsForNewConnection() { - if (StatisticsEnabled) + if (StatisticsEnabled || + s_diagnosticListener.IsEnabled(SqlClientDiagnosticListenerExtensions.SqlAfterExecuteCommand)) { if (null == _statistics) { @@ -919,7 +923,8 @@ private bool TryOpen(TaskCompletionSource retry) GC.ReRegisterForFinalize(this); } - if (StatisticsEnabled) + if (StatisticsEnabled || + s_diagnosticListener.IsEnabled(SqlClientDiagnosticListenerExtensions.SqlAfterExecuteCommand)) { ADP.TimerCurrent(out _statistics._openTimestamp); tdsInnerConnection.Parser.Statistics = _statistics; diff --git a/src/System.Data.SqlClient/src/project.json b/src/System.Data.SqlClient/src/project.json index 448fd4b1ff05..d7b1a6911aad 100644 --- a/src/System.Data.SqlClient/src/project.json +++ b/src/System.Data.SqlClient/src/project.json @@ -1,4 +1,4 @@ -{ +{ "frameworks": { "netstandard1.3": { "imports": "dotnet5.4", @@ -9,6 +9,7 @@ "System.Collections.Concurrent": "4.0.0", "System.Data.Common": "4.0.1-rc3-24112-00", "System.Diagnostics.Debug": "4.0.10", + "System.Diagnostics.DiagnosticSource": "4.0.0-rc3-24112-00", "System.Diagnostics.Tools": "4.0.0", "System.Globalization": "4.0.10", "System.IO": "4.0.10", @@ -51,5 +52,6 @@ "Microsoft.TargetingPack.NETFramework.v4.6": "1.0.1" } } - } -} + }, + "dependencies": {} +} \ No newline at end of file diff --git a/src/System.Data.SqlClient/tests/FunctionalTests/DiagnosticTest.cs b/src/System.Data.SqlClient/tests/FunctionalTests/DiagnosticTest.cs new file mode 100644 index 000000000000..211afe17e032 --- /dev/null +++ b/src/System.Data.SqlClient/tests/FunctionalTests/DiagnosticTest.cs @@ -0,0 +1,490 @@ +using Xunit; +using System.Reflection; +using System.Diagnostics; +using System.Collections; +using System.Xml; +using Xunit.Abstractions; +using System.Threading.Tasks; + +namespace System.Data.SqlClient.Tests +{ + public class DiagnosticTest + { + private string _connectionString = "server=tcp:server,1432;database=test;uid=admin;pwd=SQLDB;connect timeout=60;"; + private readonly ITestOutputHelper _output; + + public DiagnosticTest(ITestOutputHelper output) + { + _output = output; + } + + [Fact] + public void ExecuteScalarTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + var output = cmd.ExecuteScalar(); + } + }); + } + [Fact] + public void ExecuteScalarErrorTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + conn.Open(); + + try { var output = cmd.ExecuteScalar(); } + catch { } + } + }); + } + [Fact] + public void ExecuteNonQueryTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + var output = cmd.ExecuteNonQuery(); + } + }); + } + [Fact] + public void ExecuteNonQueryErrorTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + conn.Open(); + try { var output = cmd.ExecuteNonQuery(); } + catch { } + } + }); + } + [Fact] + public void ExecuteReaderTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + SqlDataReader reader = cmd.ExecuteReader(); + while (reader.Read()) { } + } + }); + } + [Fact] + public void ExecuteReaderErrorTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + try + { + SqlDataReader reader = cmd.ExecuteReader(); + while (reader.Read()) { } + } + catch { } + } + }); + } + [Fact] + public void ExecuteReaderWithCommandBehaviorTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + SqlDataReader reader = cmd.ExecuteReader(CommandBehavior.Default); + while (reader.Read()) { } + } + }); + } + [Fact] + public void ExecuteXmlReaderTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select * from sys.objects for xml auto, xmldata;"; + + conn.Open(); + XmlReader reader = cmd.ExecuteXmlReader(); + while (reader.Read()) { } + } + }); + } + [Fact] + public void ExecuteXmlReaderErrorTest() + { + CollectStatisticsDiagnostics(() => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select *, baddata = 1 / 0 from sys.objects for xml auto, xmldata;"; + + try + { + XmlReader reader = cmd.ExecuteXmlReader(); + while (reader.Read()) { } + } + catch { } + } + }); + } + + [Fact] + public void ExecuteScalarAsyncTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + var output = await cmd.ExecuteScalarAsync(); + } + }); + } + [Fact] + public void ExecuteScalarAsyncErrorTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + conn.Open(); + + try { var output = await cmd.ExecuteScalarAsync(); } + catch { } + } + }); + } + [Fact] + public void ExecuteNonQueryAsyncTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + var output = await cmd.ExecuteNonQueryAsync(); + } + }); + } + [Fact] + public void ExecuteNonQueryAsyncErrorTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + conn.Open(); + try { var output = await cmd.ExecuteNonQueryAsync(); } + catch { } + } + }); + } + [Fact] + public void ExecuteReaderAsyncTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select @@servername;"; + + conn.Open(); + SqlDataReader reader = await cmd.ExecuteReaderAsync(); + while (reader.Read()) { } + } + }); + } + [Fact] + public void ExecuteReaderAsyncErrorTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select 1 / 0;"; + + try + { + SqlDataReader reader = await cmd.ExecuteReaderAsync(); + while (reader.Read()) { } + } + catch { } + } + }); + } + [Fact] + public void ExecuteXmlReaderAsyncTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select * from sys.objects for xml auto, xmldata;"; + + conn.Open(); + XmlReader reader = await cmd.ExecuteXmlReaderAsync(); + while (reader.Read()) { } + } + }); + } + [Fact] + public void ExecuteXmlReaderAsyncErrorTest() + { + CollectStatisticsDiagnosticsAsync(async () => + { + using (SqlConnection conn = new SqlConnection(_connectionString)) + using (SqlCommand cmd = new SqlCommand()) + { + cmd.Connection = conn; + cmd.CommandText = "select *, baddata = 1 / 0 from sys.objects for xml auto, xmldata;"; + + try + { + XmlReader reader = await cmd.ExecuteXmlReaderAsync(); + while (reader.Read()) { } + } + catch { } + } + }); + } + + private void CollectStatisticsDiagnostics(Action sqlOperation) + { + bool statsLogged = false; + bool operationHasError = false; + Guid beginOperationId = Guid.Empty; + + FakeDiagnosticListenerObserver diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + IDictionary statistics; + + if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandBefore")) + { + Assert.NotNull(kvp.Value); + + Guid retrievedOperationId = GetPropertyValueFromType(kvp.Value, "OperationId"); + Assert.NotEqual(retrievedOperationId, Guid.Empty); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + beginOperationId = retrievedOperationId; + + statsLogged = true; + } + else if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandAfter")) + { + Assert.NotNull(kvp.Value); + + Guid retrievedOperationId = GetPropertyValueFromType(kvp.Value, "OperationId"); + Assert.NotEqual(retrievedOperationId, Guid.Empty); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + statistics = GetPropertyValueFromType(kvp.Value, "Statistics"); + if (!operationHasError) + Assert.NotNull(statistics); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + // if we get to this point, then statistics exist and this must be the "end" + // event, so we need to make sure the operation IDs match + Assert.Equal(retrievedOperationId, beginOperationId); + beginOperationId = Guid.Empty; + + statsLogged = true; + } + else if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandError")) + { + operationHasError = true; + Assert.NotNull(kvp.Value); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + Exception ex = GetPropertyValueFromType(kvp.Value, "Exception"); + Assert.NotNull(ex); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + statsLogged = true; + } + }); + + diagnosticListenerObserver.Enable(); + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + sqlOperation(); + + Assert.True(statsLogged); + + diagnosticListenerObserver.Disable(); + } + } + private async void CollectStatisticsDiagnosticsAsync(Func sqlOperation) + { + bool statsLogged = false; + bool operationHasError = false; + Guid beginOperationId = Guid.Empty; + + FakeDiagnosticListenerObserver diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + IDictionary statistics; + + if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandBefore")) + { + Assert.NotNull(kvp.Value); + + Guid retrievedOperationId = GetPropertyValueFromType(kvp.Value, "OperationId"); + Assert.NotEqual(retrievedOperationId, Guid.Empty); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + beginOperationId = retrievedOperationId; + + statsLogged = true; + } + else if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandAfter")) + { + Assert.NotNull(kvp.Value); + + Guid retrievedOperationId = GetPropertyValueFromType(kvp.Value, "OperationId"); + Assert.NotEqual(retrievedOperationId, Guid.Empty); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + statistics = GetPropertyValueFromType(kvp.Value, "Statistics"); + if (!operationHasError) + Assert.NotNull(statistics); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + // if we get to this point, then statistics exist and this must be the "end" + // event, so we need to make sure the operation IDs match + Assert.Equal(retrievedOperationId, beginOperationId); + beginOperationId = Guid.Empty; + + statsLogged = true; + } + else if (kvp.Key.Equals("System.Data.SqlClient.WriteCommandError")) + { + operationHasError = true; + Assert.NotNull(kvp.Value); + + SqlCommand sqlCommand = GetPropertyValueFromType(kvp.Value, "Command"); + Assert.NotNull(sqlCommand); + + Exception ex = GetPropertyValueFromType(kvp.Value, "Exception"); + Assert.NotNull(ex); + + string operation = GetPropertyValueFromType(kvp.Value, "Operation"); + Assert.False(string.IsNullOrWhiteSpace(operation)); + + statsLogged = true; + } + }); + + diagnosticListenerObserver.Enable(); + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + await sqlOperation(); + + Assert.True(statsLogged); + + diagnosticListenerObserver.Disable(); + } + } + + private T GetPropertyValueFromType(object obj, string propName) + { + Type type = obj.GetType(); + PropertyInfo pi = type.GetRuntimeProperty(propName); + + var propertyValue = pi.GetValue(obj); + return (T)propertyValue; + } + } +} \ No newline at end of file diff --git a/src/System.Data.SqlClient/tests/FunctionalTests/FakeDiagnosticListenerObserver.cs b/src/System.Data.SqlClient/tests/FunctionalTests/FakeDiagnosticListenerObserver.cs new file mode 100644 index 000000000000..8d448bac3b03 --- /dev/null +++ b/src/System.Data.SqlClient/tests/FunctionalTests/FakeDiagnosticListenerObserver.cs @@ -0,0 +1,72 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; +using System.Threading.Tasks; +using System.Diagnostics; + +namespace System.Data.SqlClient.Tests +{ + public sealed class FakeDiagnosticListenerObserver : IObserver + { + private class FakeDiagnosticSourceWriteObserver : IObserver> + { + private readonly Action> _writeCallback; + + public FakeDiagnosticSourceWriteObserver(Action> writeCallback) + { + _writeCallback = writeCallback; + } + + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(KeyValuePair value) + { + _writeCallback(value); + } + } + + private readonly Action> _writeCallback; + private bool _writeObserverEnabled; + + public FakeDiagnosticListenerObserver(Action> writeCallback) + { + _writeCallback = writeCallback; + } + + public void OnCompleted() + { + } + + public void OnError(Exception error) + { + } + + public void OnNext(DiagnosticListener value) + { + if (value.Name.Equals("SqlClientDiagnosticListener")) + { + value.Subscribe(new FakeDiagnosticSourceWriteObserver(_writeCallback), IsEnabled); + } + } + + public void Enable() + { + _writeObserverEnabled = true; + } + public void Disable() + { + _writeObserverEnabled = false; + } + private bool IsEnabled(string s) + { + return _writeObserverEnabled; + } + } +} \ No newline at end of file diff --git a/src/System.Data.SqlClient/tests/FunctionalTests/System.Data.SqlClient.Tests.csproj b/src/System.Data.SqlClient/tests/FunctionalTests/System.Data.SqlClient.Tests.csproj index 7a387e768721..8775a641322c 100644 --- a/src/System.Data.SqlClient/tests/FunctionalTests/System.Data.SqlClient.Tests.csproj +++ b/src/System.Data.SqlClient/tests/FunctionalTests/System.Data.SqlClient.Tests.csproj @@ -1,4 +1,4 @@ - + @@ -15,8 +15,12 @@ + + + + diff --git a/src/System.Data.SqlClient/tests/FunctionalTests/project.json b/src/System.Data.SqlClient/tests/FunctionalTests/project.json index 60b85feadbe8..1241d60f8845 100644 --- a/src/System.Data.SqlClient/tests/FunctionalTests/project.json +++ b/src/System.Data.SqlClient/tests/FunctionalTests/project.json @@ -4,6 +4,10 @@ "Microsoft.NETCore.Platforms": "1.0.1-rc3-24112-00", "System.Data.Common": "4.0.1-rc3-24112-00", "System.Text.RegularExpressions": "4.1.0-rc3-24112-00", + "System.Collections": "4.0.11-rc3-24112-00", + "System.Collections.Concurrent": "4.0.12-rc3-24112-00", + "System.Diagnostics.DiagnosticSource": "4.0.0-rc3-24112-00", + "System.Xml.ReaderWriter": "4.0.11-rc3-24112-00", "xunit": "2.1.0", "xunit.netcore.extensions": "1.0.0-prerelease-00312-04", "test-runtime": {