From 06978bab46f92737b37cf30c82bd0974b1e3c02b Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 1 Jul 2020 18:36:27 -0700 Subject: [PATCH 1/9] Added instrumentation for netfx SqlClient. --- .../SqlClientDiagnosticListener.cs | 9 +- .../SqlEventSourceListener.netfx.cs | 131 ++++++++++++++++++ .../OpenTelemetryBuilderExtensions.cs | 3 + .../SqlClientInstrumentation.cs | 10 ++ 4 files changed, 150 insertions(+), 3 deletions(-) create mode 100644 src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs index 6cb246d2019..9bc947e0b91 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs @@ -17,7 +17,6 @@ using System.Data; using System.Diagnostics; using OpenTelemetry.Trace; -using OpenTelemetry.Trace.Samplers; namespace OpenTelemetry.Instrumentation.Dependencies.Implementation { @@ -91,11 +90,10 @@ public override void OnCustom(string name, Activity activity, object payload) if (this.commandTypeFetcher.Fetch(command) is CommandType commandType) { - activity.AddTag(DatabaseStatementTypeSpanAttributeKey, commandType.ToString()); - switch (commandType) { case CommandType.StoredProcedure: + activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "StoredProcedure"); if (this.options.CaptureStoredProcedureCommandName) { activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText); @@ -104,12 +102,17 @@ public override void OnCustom(string name, Activity activity, object payload) break; case CommandType.Text: + activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "Text"); if (this.options.CaptureTextCommandContent) { activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText); } break; + + case CommandType.TableDirect: + activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "TableDirect"); + break; } } } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs new file mode 100644 index 00000000000..61d25586849 --- /dev/null +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs @@ -0,0 +1,131 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#if NETFRAMEWORK +using System; +using System.Data.SqlClient; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Reflection; +using OpenTelemetry.Trace; + +namespace OpenTelemetry.Instrumentation.Dependencies.Implementation +{ + /// + /// .NET Framework SqlClient doesn't emit DiagnosticSource events. + /// We hook into its EventSource if it is available: + /// See: reference source. + /// + internal class SqlEventSourceListener : EventListener + { + internal const string ActivitySourceName = "SqlClient"; + internal const string ActivityName = ActivitySourceName + ".Execute"; + + private static readonly Version Version = typeof(SqlEventSourceListener).Assembly.GetName().Version; + private static readonly ActivitySource SqlClientActivitySource = new ActivitySource(ActivitySourceName, Version.ToString()); + private static readonly EventSource SqlEventSource = (EventSource)typeof(SqlConnection).Assembly.GetType("System.Data.SqlEventSource")?.GetField("Log", BindingFlags.Static | BindingFlags.NonPublic)?.GetValue(null); + + private readonly SqlClientInstrumentationOptions options; + + public SqlEventSourceListener(SqlClientInstrumentationOptions options = null) + { + this.options = options ?? new SqlClientInstrumentationOptions(); + + if (SqlEventSource != null) + { + this.EnableEvents(SqlEventSource, EventLevel.Informational); + } + } + + public override void Dispose() + { + if (SqlEventSource != null) + { + this.DisableEvents(SqlEventSource); + } + + base.Dispose(); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventId == 1) + { + // BeginExecuteEventId + + var activity = SqlClientActivitySource.StartActivity(ActivityName, ActivityKind.Client); + if (activity == null) + { + return; + } + + activity.DisplayName = (string)eventData.Payload[2]; + + if (activity.IsAllDataRequested) + { + activity.AddTag(SpanAttributeConstants.ComponentKey, "sql"); + + activity.AddTag(SpanAttributeConstants.DatabaseTypeKey, "sql"); + activity.AddTag(SpanAttributeConstants.PeerServiceKey, (string)eventData.Payload[1]); + activity.AddTag(SpanAttributeConstants.DatabaseInstanceKey, (string)eventData.Payload[2]); + + if (string.IsNullOrEmpty((string)eventData.Payload[3])) + { + activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, "Text"); + } + else + { + activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, "StoredProcedure"); + if (this.options.CaptureStoredProcedureCommandName) + { + activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)eventData.Payload[3]); + } + } + } + } + else if (eventData.EventId == 2) + { + // EndExecuteEventId + + var activity = Activity.Current; + if (activity == null || activity.Source != SqlClientActivitySource) + { + return; + } + + try + { + if (activity.IsAllDataRequested) + { + if (((int)eventData.Payload[1] & 0x01) == 0x00) + { + activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Unknown)); + activity.AddTag(SpanAttributeConstants.StatusDescriptionKey, $"SqlExceptionNumber {eventData.Payload[2]} thrown."); + } + else + { + activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Ok)); + } + } + } + finally + { + activity.Stop(); + } + } + } + } +} +#endif diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/OpenTelemetryBuilderExtensions.cs b/src/OpenTelemetry.Instrumentation.Dependencies/OpenTelemetryBuilderExtensions.cs index 73e0d24832d..560ebca158f 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/OpenTelemetryBuilderExtensions.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/OpenTelemetryBuilderExtensions.cs @@ -133,6 +133,9 @@ public static OpenTelemetryBuilder AddSqlClientDependencyInstrumentation( configureSqlClientInstrumentationOptions?.Invoke(sqlOptions); builder.AddInstrumentation((activitySource) => new SqlClientInstrumentation(activitySource, sqlOptions)); +#if NETFRAMEWORK + builder.AddActivitySource(SqlEventSourceListener.ActivitySourceName); +#endif return builder; } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/SqlClientInstrumentation.cs b/src/OpenTelemetry.Instrumentation.Dependencies/SqlClientInstrumentation.cs index 338b90070d6..e94f9ea89bb 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/SqlClientInstrumentation.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/SqlClientInstrumentation.cs @@ -27,6 +27,9 @@ public class SqlClientInstrumentation : IDisposable internal const string SqlClientDiagnosticListenerName = "SqlClientDiagnosticListener"; private readonly DiagnosticSourceSubscriber diagnosticSourceSubscriber; +#if NETFRAMEWORK + private readonly SqlEventSourceListener sqlEventSourceListener; +#endif /// /// Initializes a new instance of the class. @@ -49,12 +52,19 @@ public SqlClientInstrumentation(ActivitySourceAdapter activitySource, SqlClientI listener => listener.Name == SqlClientDiagnosticListenerName, null); this.diagnosticSourceSubscriber.Subscribe(); + +#if NETFRAMEWORK + this.sqlEventSourceListener = new SqlEventSourceListener(options); +#endif } /// public void Dispose() { this.diagnosticSourceSubscriber?.Dispose(); +#if NETFRAMEWORK + this.sqlEventSourceListener?.Dispose(); +#endif } } } From 40dd3b17a49e833e517d31cb9bf48163188d659d Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 2 Jul 2020 11:07:18 -0700 Subject: [PATCH 2/9] Code review. --- .../Trace/SpanAttributeConstants.cs | 5 +- src/OpenTelemetry.Api/Trace/SpanExtensions.cs | 22 +-- .../JaegerActivityExtensions.cs | 2 +- .../SqlClientDiagnosticListener.cs | 12 +- .../SqlEventSourceListener.netfx.cs | 160 ++++++++++++------ .../SqlClientTests.cs | 8 +- 6 files changed, 137 insertions(+), 72 deletions(-) diff --git a/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs b/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs index e24c3ab44dd..0aac897ef78 100644 --- a/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs +++ b/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs @@ -40,9 +40,10 @@ public static class SpanAttributeConstants public const string HttpRouteKey = "http.route"; public const string HttpFlavorKey = "http.flavor"; - public const string DatabaseTypeKey = "db.type"; - public const string DatabaseInstanceKey = "db.instance"; + public const string DatabaseSystemKey = "db.system"; + public const string DatabaseNameKey = "db.name"; public const string DatabaseStatementKey = "db.statement"; + public const string DatabaseStatementTypeKey = "db.statementType"; #pragma warning restore CS1591 // Missing XML comment for publicly visible type or member } } diff --git a/src/OpenTelemetry.Api/Trace/SpanExtensions.cs b/src/OpenTelemetry.Api/Trace/SpanExtensions.cs index 7b63b3108c3..00466429ef0 100644 --- a/src/OpenTelemetry.Api/Trace/SpanExtensions.cs +++ b/src/OpenTelemetry.Api/Trace/SpanExtensions.cs @@ -207,34 +207,34 @@ public static TelemetrySpan PutHttpFlavorAttribute(this TelemetrySpan span, stri } /// - /// Helper method that populates database type - /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/data-database.md. + /// Helper method that populates database system + /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/database.md. /// /// Span to fill out. - /// Database type. + /// Database system. /// Span with populated properties. - public static TelemetrySpan PutDatabaseTypeAttribute(this TelemetrySpan span, string type) + public static TelemetrySpan PutDatabaseSystemAttribute(this TelemetrySpan span, string system) { - span.SetAttribute(SpanAttributeConstants.DatabaseTypeKey, type); + span.SetAttribute(SpanAttributeConstants.DatabaseSystemKey, system); return span; } /// - /// Helper method that populates database instance - /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/data-database.md. + /// Helper method that populates database name + /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/database.md. /// /// Span to fill out. - /// Database instance. + /// Database name. /// Span with populated properties. - public static TelemetrySpan PutDatabaseInstanceAttribute(this TelemetrySpan span, string instance) + public static TelemetrySpan PutDatabaseNameAttribute(this TelemetrySpan span, string name) { - span.SetAttribute(SpanAttributeConstants.DatabaseInstanceKey, instance); + span.SetAttribute(SpanAttributeConstants.DatabaseNameKey, name); return span; } /// /// Helper method that populates database statement - /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/data-database.md. + /// to https://github.com/open-telemetry/opentelemetry-specification/blob/master/specification/trace/semantic_conventions/database.md. /// /// Span to fill out. /// Database statement. diff --git a/src/OpenTelemetry.Exporter.Jaeger/Implementation/JaegerActivityExtensions.cs b/src/OpenTelemetry.Exporter.Jaeger/Implementation/JaegerActivityExtensions.cs index b3bd0369d72..f384a5ead17 100644 --- a/src/OpenTelemetry.Exporter.Jaeger/Implementation/JaegerActivityExtensions.cs +++ b/src/OpenTelemetry.Exporter.Jaeger/Implementation/JaegerActivityExtensions.cs @@ -98,7 +98,7 @@ public static JaegerSpan ToJaegerSpan(this Activity activity) PooledList.Add(ref jaegerTags.Tags, new JaegerTag("library.name", JaegerTagType.STRING, vStr: activitySource.Name)); if (!string.IsNullOrEmpty(activitySource.Version)) { - PooledList.Add(ref jaegerTags.Tags, new JaegerTag("library.version", JaegerTagType.STRING, vStr: activitySource.Name)); + PooledList.Add(ref jaegerTags.Tags, new JaegerTag("library.version", JaegerTagType.STRING, vStr: activitySource.Version)); } } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs index 9bc947e0b91..123262eabb9 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs @@ -31,7 +31,7 @@ internal class SqlClientDiagnosticListener : ListenerHandler internal const string SqlDataWriteCommandError = "System.Data.SqlClient.WriteCommandError"; internal const string SqlMicrosoftWriteCommandError = "Microsoft.Data.SqlClient.WriteCommandError"; - private const string DatabaseStatementTypeSpanAttributeKey = "db.statementType"; + internal const string MicrosoftSqlServerDatabaseSystemName = "mssql"; private readonly PropertyFetcher commandFetcher = new PropertyFetcher("Command"); private readonly PropertyFetcher connectionFetcher = new PropertyFetcher("Connection"); @@ -84,16 +84,16 @@ public override void OnCustom(string name, Activity activity, object payload) var commandText = this.commandTextFetcher.Fetch(command); activity.AddTag(SpanAttributeConstants.ComponentKey, "sql"); - activity.AddTag(SpanAttributeConstants.DatabaseTypeKey, "sql"); + activity.AddTag(SpanAttributeConstants.DatabaseSystemKey, MicrosoftSqlServerDatabaseSystemName); activity.AddTag(SpanAttributeConstants.PeerServiceKey, (string)dataSource); - activity.AddTag(SpanAttributeConstants.DatabaseInstanceKey, (string)database); + activity.AddTag(SpanAttributeConstants.DatabaseNameKey, (string)database); if (this.commandTypeFetcher.Fetch(command) is CommandType commandType) { switch (commandType) { case CommandType.StoredProcedure: - activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "StoredProcedure"); + activity.AddTag(SpanAttributeConstants.DatabaseStatementTypeKey, nameof(CommandType.StoredProcedure)); if (this.options.CaptureStoredProcedureCommandName) { activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText); @@ -102,7 +102,7 @@ public override void OnCustom(string name, Activity activity, object payload) break; case CommandType.Text: - activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "Text"); + activity.AddTag(SpanAttributeConstants.DatabaseStatementTypeKey, nameof(CommandType.Text)); if (this.options.CaptureTextCommandContent) { activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText); @@ -111,7 +111,7 @@ public override void OnCustom(string name, Activity activity, object payload) break; case CommandType.TableDirect: - activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "TableDirect"); + activity.AddTag(SpanAttributeConstants.DatabaseStatementTypeKey, nameof(CommandType.TableDirect)); break; } } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs index 61d25586849..7ed45c478ec 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs @@ -15,10 +15,9 @@ // #if NETFRAMEWORK using System; -using System.Data.SqlClient; +using System.Data; using System.Diagnostics; using System.Diagnostics.Tracing; -using System.Reflection; using OpenTelemetry.Trace; namespace OpenTelemetry.Instrumentation.Dependencies.Implementation @@ -30,100 +29,165 @@ namespace OpenTelemetry.Instrumentation.Dependencies.Implementation /// internal class SqlEventSourceListener : EventListener { - internal const string ActivitySourceName = "SqlClient"; + internal const string ActivitySourceName = "System.Data.SqlClient"; internal const string ActivityName = ActivitySourceName + ".Execute"; + private const string AdoNetEventSourceName = "Microsoft-AdoNet-SystemData"; + private const int BeginExecuteEventId = 1; + private const int EndExecuteEventId = 2; + private static readonly Version Version = typeof(SqlEventSourceListener).Assembly.GetName().Version; private static readonly ActivitySource SqlClientActivitySource = new ActivitySource(ActivitySourceName, Version.ToString()); - private static readonly EventSource SqlEventSource = (EventSource)typeof(SqlConnection).Assembly.GetType("System.Data.SqlEventSource")?.GetField("Log", BindingFlags.Static | BindingFlags.NonPublic)?.GetValue(null); private readonly SqlClientInstrumentationOptions options; + private EventSource eventSource; public SqlEventSourceListener(SqlClientInstrumentationOptions options = null) { this.options = options ?? new SqlClientInstrumentationOptions(); + } - if (SqlEventSource != null) + public override void Dispose() + { + if (this.eventSource != null) { - this.EnableEvents(SqlEventSource, EventLevel.Informational); + this.DisableEvents(this.eventSource); } + + base.Dispose(); } - public override void Dispose() + protected override void OnEventSourceCreated(EventSource eventSource) { - if (SqlEventSource != null) + if (eventSource?.Name == AdoNetEventSourceName) { - this.DisableEvents(SqlEventSource); + this.eventSource = eventSource; + this.EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)1); } - base.Dispose(); + base.OnEventSourceCreated(eventSource); } protected override void OnEventWritten(EventWrittenEventArgs eventData) { - if (eventData.EventId == 1) + if (eventData?.Payload == null) { - // BeginExecuteEventId + InstrumentationEventSource.Log.NullPayload(nameof(SqlEventSourceListener) + nameof(this.OnEventWritten)); + return; + } - var activity = SqlClientActivitySource.StartActivity(ActivityName, ActivityKind.Client); - if (activity == null) + try + { + if (eventData.EventId == BeginExecuteEventId) { - return; + this.OnBeginExecute(eventData); } + else if (eventData.EventId == EndExecuteEventId) + { + this.OnEndExecute(eventData); + } + } + catch (Exception exc) + { + InstrumentationEventSource.Log.UnknownErrorProcessingEvent(nameof(SqlEventSourceListener), nameof(this.OnEventWritten), exc); + } + } - activity.DisplayName = (string)eventData.Payload[2]; + private void OnBeginExecute(EventWrittenEventArgs eventData) + { + /* + Expected payload: + [0] -> ObjectId + [1] -> DataSource + [2] -> Database + [3] -> CommandText ([3] = CommandType == CommandType.StoredProcedure ? CommandText : string.Empty) + */ - if (activity.IsAllDataRequested) - { - activity.AddTag(SpanAttributeConstants.ComponentKey, "sql"); + if (eventData.Payload.Count < 4) + { + return; + } - activity.AddTag(SpanAttributeConstants.DatabaseTypeKey, "sql"); - activity.AddTag(SpanAttributeConstants.PeerServiceKey, (string)eventData.Payload[1]); - activity.AddTag(SpanAttributeConstants.DatabaseInstanceKey, (string)eventData.Payload[2]); + var activity = SqlClientActivitySource.StartActivity(ActivityName, ActivityKind.Client); + if (activity == null) + { + return; + } - if (string.IsNullOrEmpty((string)eventData.Payload[3])) - { - activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, "Text"); - } - else + string databaseName = (string)eventData.Payload[2]; + + activity.DisplayName = databaseName; + + if (activity.IsAllDataRequested) + { + activity.AddTag(SpanAttributeConstants.ComponentKey, "sql"); + + activity.AddTag(SpanAttributeConstants.DatabaseSystemKey, SqlClientDiagnosticListener.MicrosoftSqlServerDatabaseSystemName); + activity.AddTag(SpanAttributeConstants.PeerServiceKey, (string)eventData.Payload[1]); + activity.AddTag(SpanAttributeConstants.DatabaseNameKey, databaseName); + + string commandText = (string)eventData.Payload[3]; + if (string.IsNullOrEmpty(commandText)) + { + activity.AddTag(SpanAttributeConstants.DatabaseStatementTypeKey, nameof(CommandType.Text)); + } + else + { + activity.AddTag(SpanAttributeConstants.DatabaseStatementTypeKey, nameof(CommandType.StoredProcedure)); + if (this.options.CaptureStoredProcedureCommandName) { - activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, "StoredProcedure"); - if (this.options.CaptureStoredProcedureCommandName) - { - activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)eventData.Payload[3]); - } + activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, commandText); } } } - else if (eventData.EventId == 2) + } + + private void OnEndExecute(EventWrittenEventArgs eventData) + { + /* + Expected payload: + [0] -> ObjectId + [1] -> CompositeState bitmask (0b001 -> successFlag, 0b010 -> isSqlExceptionFlag , 0b100 -> synchronousFlag) + [2] -> SqlExceptionNumber + */ + + if (eventData.Payload.Count < 3) { - // EndExecuteEventId + return; + } - var activity = Activity.Current; - if (activity == null || activity.Source != SqlClientActivitySource) - { - return; - } + var activity = Activity.Current; + if (activity?.Source != SqlClientActivitySource) + { + return; + } - try + try + { + if (activity.IsAllDataRequested) { - if (activity.IsAllDataRequested) + int compositeState = (int)eventData.Payload[1]; + if ((compositeState & 0b001) == 0b001) { - if (((int)eventData.Payload[1] & 0x01) == 0x00) + activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Ok)); + } + else + { + activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Unknown)); + if ((compositeState & 0b010) == 0b010) { - activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Unknown)); activity.AddTag(SpanAttributeConstants.StatusDescriptionKey, $"SqlExceptionNumber {eventData.Payload[2]} thrown."); } else { - activity.AddTag(SpanAttributeConstants.StatusCodeKey, SpanHelper.GetCachedCanonicalCodeString(StatusCanonicalCode.Ok)); + activity.AddTag(SpanAttributeConstants.StatusDescriptionKey, $"Unknown Sql failure."); } } } - finally - { - activity.Stop(); - } + } + finally + { + activity.Stop(); } } } diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlClientTests.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlClientTests.cs index 4f4b51b28c8..6d64b914969 100644 --- a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlClientTests.cs +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlClientTests.cs @@ -117,8 +117,8 @@ public void SqlClientCallsAreCollectedSuccessfully( Assert.Null(span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.StatusDescriptionKey).Value); Assert.Equal("sql", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.ComponentKey).Value); - Assert.Equal("sql", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseTypeKey).Value); - Assert.Equal("master", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseInstanceKey).Value); + Assert.Equal(SqlClientDiagnosticListener.MicrosoftSqlServerDatabaseSystemName, span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseSystemKey).Value); + Assert.Equal("master", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseNameKey).Value); switch (commandType) { @@ -205,8 +205,8 @@ public void SqlClientErrorsAreCollectedSuccessfully(string beforeCommand, string Assert.Equal("Unknown", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.StatusCodeKey).Value); Assert.Equal("Boom!", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.StatusDescriptionKey).Value); Assert.Equal("sql", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.ComponentKey).Value); - Assert.Equal("sql", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseTypeKey).Value); - Assert.Equal("master", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseInstanceKey).Value); + Assert.Equal(SqlClientDiagnosticListener.MicrosoftSqlServerDatabaseSystemName, span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseSystemKey).Value); + Assert.Equal("master", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseNameKey).Value); Assert.Equal("SP_GetOrders", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.DatabaseStatementKey).Value); Assert.Equal("(localdb)\\MSSQLLocalDB", span.Tags.FirstOrDefault(i => i.Key == SpanAttributeConstants.PeerServiceKey).Value); } From fb25ff8507c68ed96af346d9c38040e33cd9fc43 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 2 Jul 2020 11:30:26 -0700 Subject: [PATCH 3/9] Send "db.statement_type" instead of "db.statementType". --- src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs b/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs index 0aac897ef78..1155ba2f961 100644 --- a/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs +++ b/src/OpenTelemetry.Api/Trace/SpanAttributeConstants.cs @@ -43,7 +43,7 @@ public static class SpanAttributeConstants public const string DatabaseSystemKey = "db.system"; public const string DatabaseNameKey = "db.name"; public const string DatabaseStatementKey = "db.statement"; - public const string DatabaseStatementTypeKey = "db.statementType"; + public const string DatabaseStatementTypeKey = "db.statement_type"; #pragma warning restore CS1591 // Missing XML comment for publicly visible type or member } } From 401f740a488e93b56d18a99e185a23d15d666217 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 2 Jul 2020 23:29:45 -0700 Subject: [PATCH 4/9] Added integration tests for SqlEventSource. --- .../SkipUnlessEnvVarFoundTheoryAttribute.cs | 31 +++++ .../SqlEventSourceTests.netfx.cs | 129 ++++++++++++++++++ 2 files changed, 160 insertions(+) create mode 100644 test/OpenTelemetry.Instrumentation.Dependencies.Tests/SkipUnlessEnvVarFoundTheoryAttribute.cs create mode 100644 test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SkipUnlessEnvVarFoundTheoryAttribute.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SkipUnlessEnvVarFoundTheoryAttribute.cs new file mode 100644 index 00000000000..5bb7169e567 --- /dev/null +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SkipUnlessEnvVarFoundTheoryAttribute.cs @@ -0,0 +1,31 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +using System; +using Xunit; + +namespace OpenTelemetry.Instrumentation.Dependencies.Tests +{ + public class SkipUnlessEnvVarFoundTheoryAttribute : TheoryAttribute + { + public SkipUnlessEnvVarFoundTheoryAttribute(string environmentVariable) + { + if (string.IsNullOrEmpty(Environment.GetEnvironmentVariable(environmentVariable, EnvironmentVariableTarget.Machine))) + { + this.Skip = $"Skipped because {environmentVariable} environment variable was not configured."; + } + } + } +} diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs new file mode 100644 index 00000000000..2eb8741a85a --- /dev/null +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs @@ -0,0 +1,129 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#if NETFRAMEWORK +using System; +using System.Data; +using System.Data.SqlClient; +using System.Diagnostics; +using System.Linq; +using System.Threading.Tasks; +using Moq; +using OpenTelemetry.Instrumentation.Dependencies.Implementation; +using OpenTelemetry.Trace; +using OpenTelemetry.Trace.Configuration; +using OpenTelemetry.Trace.Export; +using Xunit; + +namespace OpenTelemetry.Instrumentation.Dependencies.Tests +{ + public class SqlEventSourceTests + { + /* + To run these tests, set the ot.SqlConnectionString machine-level environment variable to a valid Sql Server connection string. + + To use Docker... + 1) Run: docker run -d --name sql2019 -e "ACCEPT_EULA=Y" -e "SA_PASSWORD=Pass@word" -p 5433:1433 mcr.microsoft.com/mssql/server:2019-latest + 2) Set ot.SqlConnectionString as: Data Source=127.0.0.1,5433; User ID=sa; Password=Pass@word + */ + + private const string SqlConnectionStringEnvVarName = "ot.SqlConnectionString"; + private static readonly string SqlConnectionString = Environment.GetEnvironmentVariable(SqlConnectionStringEnvVarName, EnvironmentVariableTarget.Machine); + + [Trait("CategoryName", "SqlIntegrationTests")] + [SkipUnlessEnvVarFoundTheory(SqlConnectionStringEnvVarName)] + [InlineData(CommandType.Text, "select 1/1", false)] + [InlineData(CommandType.Text, "select 1/0", false, true)] + [InlineData(CommandType.StoredProcedure, "sp_who", false)] + [InlineData(CommandType.StoredProcedure, "sp_who", true)] + public async Task SuccessfulCommandTest(CommandType commandType, string commandText, bool captureText, bool isFailure = false) + { + var activityProcessor = new Mock(); + using var shutdownSignal = OpenTelemetrySdk.EnableOpenTelemetry(b => + { + b.AddProcessorPipeline(c => c.AddProcessor(ap => activityProcessor.Object)); + b.AddSqlClientDependencyInstrumentation(options => + { + options.CaptureStoredProcedureCommandName = captureText; + }); + }); + + string dataSource = null; + + using (var activityListener = new ActivityListener + { + ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, + }) + { + ActivitySource.AddActivityListener(activityListener); + + using SqlConnection sqlConnection = new SqlConnection(SqlConnectionString); + + await sqlConnection.OpenAsync().ConfigureAwait(false); + + dataSource = sqlConnection.DataSource; + + sqlConnection.ChangeDatabase("master"); + + using SqlCommand sqlCommand = new SqlCommand(commandText, sqlConnection) + { + CommandType = commandType, + }; + + try + { + await sqlCommand.ExecuteNonQueryAsync().ConfigureAwait(false); + } + catch + { + } + } + + Assert.Equal(2, activityProcessor.Invocations.Count); + + var activity = (Activity)activityProcessor.Invocations[1].Arguments[0]; + + Assert.Equal("master", activity.DisplayName); + Assert.Equal(ActivityKind.Client, activity.Kind); + Assert.Equal("sql", activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.ComponentKey).Value); + Assert.Equal(SqlClientDiagnosticListener.MicrosoftSqlServerDatabaseSystemName, activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.DatabaseSystemKey).Value); + Assert.Equal(dataSource, activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.PeerServiceKey).Value); + Assert.Equal("master", activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.DatabaseNameKey).Value); + Assert.Equal(commandType.ToString(), activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.DatabaseStatementTypeKey).Value); + if (commandType == CommandType.StoredProcedure) + { + if (captureText) + { + Assert.Equal(commandText, activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.DatabaseStatementKey).Value); + } + else + { + Assert.DoesNotContain(activity.Tags, t => t.Key == SpanAttributeConstants.DatabaseStatementKey); + } + } + + if (!isFailure) + { + Assert.Equal("Ok", activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.StatusCodeKey).Value); + } + else + { + Assert.Equal("Unknown", activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.StatusCodeKey).Value); + Assert.Contains(activity.Tags, t => t.Key == SpanAttributeConstants.StatusDescriptionKey); + } + } + } +} +#endif From baa5f1b0e988a7a12b04857d2f9c8c3bbf47a14c Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 3 Jul 2020 09:22:17 -0700 Subject: [PATCH 5/9] Adding .github folder to solution. --- OpenTelemetry.sln | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/OpenTelemetry.sln b/OpenTelemetry.sln index bcfb9be4ebc..1d32d52bfd9 100644 --- a/OpenTelemetry.sln +++ b/OpenTelemetry.sln @@ -102,6 +102,26 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "OpenTelemetry.Instrumentati EndProject Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "OpenTelemetry.Exporter.OpenTelemetryProtocol.Tests", "test\OpenTelemetry.Exporter.OpenTelemetryProtocol.Tests\OpenTelemetry.Exporter.OpenTelemetryProtocol.Tests.csproj", "{7C4026CA-6434-4762-8B77-D657EAEE1325}" EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = ".github", ".github", "{F1D0972B-38CF-49C2-9F4B-4C5DE02FB71D}" + ProjectSection(SolutionItems) = preProject + .github\CODEOWNERS = .github\CODEOWNERS + .github\PULL_REQUEST_TEMPLATE.md = .github\PULL_REQUEST_TEMPLATE.md + EndProjectSection +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "ISSUE_TEMPLATE", "ISSUE_TEMPLATE", "{A533C800-3DC3-4D04-90A7-0CE7A1E6BDB3}" + ProjectSection(SolutionItems) = preProject + .github\ISSUE_TEMPLATE\bug_report.md = .github\ISSUE_TEMPLATE\bug_report.md + .github\ISSUE_TEMPLATE\feature_request.md = .github\ISSUE_TEMPLATE\feature_request.md + .github\ISSUE_TEMPLATE\question.md = .github\ISSUE_TEMPLATE\question.md + EndProjectSection +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "workflows", "workflows", "{E69578EB-B456-4062-A645-877CD964528B}" + ProjectSection(SolutionItems) = preProject + .github\workflows\dotnet-core-linux.yml = .github\workflows\dotnet-core-linux.yml + .github\workflows\dotnet-core-win.yml = .github\workflows\dotnet-core-win.yml + .github\workflows\dotnet-core.yml = .github\workflows\dotnet-core.yml + EndProjectSection +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -238,6 +258,8 @@ Global {47318988-CA8B-4C81-B55D-2FA11D295A49} = {E359BB2B-9AEC-497D-B321-7DF2450C3B8E} {25C06046-C7D0-46B4-AAAC-90C50C43DE7A} = {E359BB2B-9AEC-497D-B321-7DF2450C3B8E} {9A4E3A68-904B-4835-A3C8-F664B73098DB} = {E359BB2B-9AEC-497D-B321-7DF2450C3B8E} + {A533C800-3DC3-4D04-90A7-0CE7A1E6BDB3} = {F1D0972B-38CF-49C2-9F4B-4C5DE02FB71D} + {E69578EB-B456-4062-A645-877CD964528B} = {F1D0972B-38CF-49C2-9F4B-4C5DE02FB71D} EndGlobalSection GlobalSection(ExtensibilityGlobals) = postSolution SolutionGuid = {55639B5C-0770-4A22-AB56-859604650521} From 14c399dc3c840b1208deeaec9df86e78b6961ca4 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 3 Jul 2020 11:08:54 -0700 Subject: [PATCH 6/9] Added a couple missing files into the solution. --- OpenTelemetry.sln | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/OpenTelemetry.sln b/OpenTelemetry.sln index 1d32d52bfd9..e26d65c9b3b 100644 --- a/OpenTelemetry.sln +++ b/OpenTelemetry.sln @@ -122,6 +122,18 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "workflows", "workflows", "{ .github\workflows\dotnet-core.yml = .github\workflows\dotnet-core.yml EndProjectSection EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{C1542297-8763-4DF4-957C-489ED771C21D}" + ProjectSection(SolutionItems) = preProject + src\Directory.Build.props = src\Directory.Build.props + src\Directory.Build.targets = src\Directory.Build.targets + EndProjectSection +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "test", "test", "{D2E73927-5966-445C-94E9-EFE6F269C8D5}" + ProjectSection(SolutionItems) = preProject + test\Directory.Build.props = test\Directory.Build.props + test\Directory.Build.targets = test\Directory.Build.targets + EndProjectSection +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -260,6 +272,8 @@ Global {9A4E3A68-904B-4835-A3C8-F664B73098DB} = {E359BB2B-9AEC-497D-B321-7DF2450C3B8E} {A533C800-3DC3-4D04-90A7-0CE7A1E6BDB3} = {F1D0972B-38CF-49C2-9F4B-4C5DE02FB71D} {E69578EB-B456-4062-A645-877CD964528B} = {F1D0972B-38CF-49C2-9F4B-4C5DE02FB71D} + {C1542297-8763-4DF4-957C-489ED771C21D} = {7CB2F02E-03FA-4FFF-89A5-C51F107623FD} + {D2E73927-5966-445C-94E9-EFE6F269C8D5} = {7CB2F02E-03FA-4FFF-89A5-C51F107623FD} EndGlobalSection GlobalSection(ExtensibilityGlobals) = postSolution SolutionGuid = {55639B5C-0770-4A22-AB56-859604650521} From c3a499c3ade5c664d132001d1b0a287a66e7789c Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Fri, 3 Jul 2020 12:23:44 -0700 Subject: [PATCH 7/9] Added FakeSqlEventSource tests. --- .../Implementation/HttpInListener.cs | 8 +- .../Implementation/HttpInListener.cs | 7 +- .../HttpHandlerDiagnosticListener.cs | 7 +- .../SqlClientDiagnosticListener.cs | 4 +- .../SqlEventSourceListener.netfx.cs | 21 +-- .../InstrumentationEventSource.cs | 14 +- .../SqlEventSourceTests.netfx.cs | 151 +++++++++++++++++- 7 files changed, 176 insertions(+), 36 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.AspNet.Win/Implementation/HttpInListener.cs b/src/OpenTelemetry.Instrumentation.AspNet.Win/Implementation/HttpInListener.cs index 5f4399132c5..db4c44657f4 100644 --- a/src/OpenTelemetry.Instrumentation.AspNet.Win/Implementation/HttpInListener.cs +++ b/src/OpenTelemetry.Instrumentation.AspNet.Win/Implementation/HttpInListener.cs @@ -40,12 +40,10 @@ public HttpInListener(string name, AspNetInstrumentationOptions options, Activit public override void OnStartActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStartActivity"; - var context = HttpContext.Current; if (context == null) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStartActivity)); return; } @@ -114,8 +112,6 @@ public override void OnStartActivity(Activity activity, object payload) public override void OnStopActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStopActivity"; - Activity activityToEnrich = activity; if (!(this.options.TextFormat is TraceContextFormatActivity)) @@ -139,7 +135,7 @@ public override void OnStopActivity(Activity activity, object payload) var context = HttpContext.Current; if (context == null) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStopActivity)); return; } diff --git a/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs b/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs index cf4d655ee44..ab5ecd6324b 100644 --- a/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs +++ b/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs @@ -48,12 +48,11 @@ public HttpInListener(string name, AspNetCoreInstrumentationOptions options, Act public override void OnStartActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStartActivity"; var context = this.startContextFetcher.Fetch(payload) as HttpContext; if (context == null) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStartActivity)); return; } @@ -120,13 +119,11 @@ public override void OnStartActivity(Activity activity, object payload) public override void OnStopActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStopActivity"; - if (activity.IsAllDataRequested) { if (!(this.stopContextFetcher.Fetch(payload) is HttpContext context)) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStopActivity)); return; } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/HttpHandlerDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/HttpHandlerDiagnosticListener.cs index 8ea527473da..1938fb7f315 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/HttpHandlerDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/HttpHandlerDiagnosticListener.cs @@ -62,10 +62,9 @@ public HttpHandlerDiagnosticListener(HttpClientInstrumentationOptions options, A public override void OnStartActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStartActivity"; if (!(this.startRequestFetcher.Fetch(payload) is HttpRequestMessage request)) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpHandlerDiagnosticListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpHandlerDiagnosticListener), nameof(this.OnStartActivity)); return; } @@ -141,13 +140,11 @@ public override void OnStopActivity(Activity activity, object payload) public override void OnException(Activity activity, object payload) { - const string EventNameSuffix = ".OnException"; - if (activity.IsAllDataRequested) { if (!(this.stopExceptionFetcher.Fetch(payload) is Exception exc)) { - InstrumentationEventSource.Log.NullPayload(nameof(HttpHandlerDiagnosticListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(HttpHandlerDiagnosticListener), nameof(this.OnException)); return; } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs index 123262eabb9..cbb44ebed0c 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlClientDiagnosticListener.cs @@ -65,7 +65,7 @@ public override void OnCustom(string name, Activity activity, object payload) if (command == null) { - InstrumentationEventSource.Log.NullPayload($"{nameof(SqlClientDiagnosticListener)}-{name}"); + InstrumentationEventSource.Log.NullPayload(nameof(SqlClientDiagnosticListener), name); return; } @@ -139,7 +139,7 @@ public override void OnCustom(string name, Activity activity, object payload) } else { - InstrumentationEventSource.Log.NullPayload($"{nameof(SqlClientDiagnosticListener)}-{name}"); + InstrumentationEventSource.Log.NullPayload(nameof(SqlClientDiagnosticListener), name); } } diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs index 7ed45c478ec..f9b84f84aaa 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/SqlEventSourceListener.netfx.cs @@ -31,10 +31,9 @@ internal class SqlEventSourceListener : EventListener { internal const string ActivitySourceName = "System.Data.SqlClient"; internal const string ActivityName = ActivitySourceName + ".Execute"; - - private const string AdoNetEventSourceName = "Microsoft-AdoNet-SystemData"; - private const int BeginExecuteEventId = 1; - private const int EndExecuteEventId = 2; + internal const string AdoNetEventSourceName = "Microsoft-AdoNet-SystemData"; + internal const int BeginExecuteEventId = 1; + internal const int EndExecuteEventId = 2; private static readonly Version Version = typeof(SqlEventSourceListener).Assembly.GetName().Version; private static readonly ActivitySource SqlClientActivitySource = new ActivitySource(ActivitySourceName, Version.ToString()); @@ -59,7 +58,7 @@ public override void Dispose() protected override void OnEventSourceCreated(EventSource eventSource) { - if (eventSource?.Name == AdoNetEventSourceName) + if (eventSource?.Name.StartsWith(AdoNetEventSourceName) == true) { this.eventSource = eventSource; this.EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)1); @@ -70,12 +69,6 @@ protected override void OnEventSourceCreated(EventSource eventSource) protected override void OnEventWritten(EventWrittenEventArgs eventData) { - if (eventData?.Payload == null) - { - InstrumentationEventSource.Log.NullPayload(nameof(SqlEventSourceListener) + nameof(this.OnEventWritten)); - return; - } - try { if (eventData.EventId == BeginExecuteEventId) @@ -103,8 +96,9 @@ private void OnBeginExecute(EventWrittenEventArgs eventData) [3] -> CommandText ([3] = CommandType == CommandType.StoredProcedure ? CommandText : string.Empty) */ - if (eventData.Payload.Count < 4) + if ((eventData?.Payload?.Count ?? 0) < 4) { + InstrumentationEventSource.Log.InvalidPayload(nameof(SqlEventSourceListener), nameof(this.OnBeginExecute)); return; } @@ -151,8 +145,9 @@ private void OnEndExecute(EventWrittenEventArgs eventData) [2] -> SqlExceptionNumber */ - if (eventData.Payload.Count < 3) + if ((eventData?.Payload?.Count ?? 0) < 3) { + InstrumentationEventSource.Log.InvalidPayload(nameof(SqlEventSourceListener), nameof(this.OnEndExecute)); return; } diff --git a/src/OpenTelemetry/Instrumentation/InstrumentationEventSource.cs b/src/OpenTelemetry/Instrumentation/InstrumentationEventSource.cs index f2ce6d4b0c6..3637d68a509 100644 --- a/src/OpenTelemetry/Instrumentation/InstrumentationEventSource.cs +++ b/src/OpenTelemetry/Instrumentation/InstrumentationEventSource.cs @@ -67,16 +67,16 @@ public void UnknownErrorProcessingEvent(string handlerName, string eventName, Ex this.UnknownErrorProcessingEvent(handlerName, eventName, ToInvariantString(ex)); } - [Event(4, Message = "Unknown error processing event '{0}' from handler '{1}', Exception: {2}", Level = EventLevel.Error)] + [Event(4, Message = "Unknown error processing event '{1}' from handler '{0}', Exception: {2}", Level = EventLevel.Error)] public void UnknownErrorProcessingEvent(string handlerName, string eventName, string ex) { this.WriteEvent(4, handlerName, eventName, ex); } - [Event(5, Message = "Payload is NULL in '{0}' callback. Span will not be recorded.", Level = EventLevel.Warning)] - public void NullPayload(string eventName) + [Event(5, Message = "Payload is NULL in event '{1}' from handler '{0}', span will not be recorded.", Level = EventLevel.Warning)] + public void NullPayload(string handlerName, string eventName) { - this.WriteEvent(5, eventName); + this.WriteEvent(5, handlerName, eventName); } [Event(6, Message = "Request is filtered out.", Level = EventLevel.Verbose)] @@ -100,6 +100,12 @@ public void ExceptionInitializingInstrumentation(string instrumentationType, str this.WriteEvent(7, instrumentationType, ex); } + [Event(8, Message = "Payload is invalid in event '{1}' from handler '{0}', span will not be recorded.", Level = EventLevel.Warning)] + public void InvalidPayload(string handlerName, string eventName) + { + this.WriteEvent(8, handlerName, eventName); + } + /// /// Returns a culture-independent string representation of the given object, /// appropriate for diagnostics tracing. diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs index 2eb8741a85a..591fdde046d 100644 --- a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs @@ -18,6 +18,7 @@ using System.Data; using System.Data.SqlClient; using System.Diagnostics; +using System.Diagnostics.Tracing; using System.Linq; using System.Threading.Tasks; using Moq; @@ -32,7 +33,7 @@ namespace OpenTelemetry.Instrumentation.Dependencies.Tests public class SqlEventSourceTests { /* - To run these tests, set the ot.SqlConnectionString machine-level environment variable to a valid Sql Server connection string. + To run the integration tests, set the ot.SqlConnectionString machine-level environment variable to a valid Sql Server connection string. To use Docker... 1) Run: docker run -d --name sql2019 -e "ACCEPT_EULA=Y" -e "SA_PASSWORD=Pass@word" -p 5433:1433 mcr.microsoft.com/mssql/server:2019-latest @@ -95,6 +96,114 @@ public async Task SuccessfulCommandTest(CommandType commandType, string commandT var activity = (Activity)activityProcessor.Invocations[1].Arguments[0]; + VerifyActivityData(commandType, commandText, captureText, isFailure, dataSource, activity); + } + + [Theory] + [InlineData(CommandType.Text, "select 1/1", false)] + [InlineData(CommandType.Text, "select 1/0", false, true)] + [InlineData(CommandType.StoredProcedure, "sp_who", false)] + [InlineData(CommandType.StoredProcedure, "sp_who", true)] + public void EventSourceFakeTests(CommandType commandType, string commandText, bool captureText, bool isFailure = false, int sqlExceptionNumber = 0) + { + using FakeBehavingSqlEventSource fakeSqlEventSource = new FakeBehavingSqlEventSource(); + + var activityProcessor = new Mock(); + using var shutdownSignal = OpenTelemetrySdk.EnableOpenTelemetry(b => + { + b.AddProcessorPipeline(c => c.AddProcessor(ap => activityProcessor.Object)); + b.AddSqlClientDependencyInstrumentation(options => + { + options.CaptureStoredProcedureCommandName = captureText; + }); + }); + + int objectId = Guid.NewGuid().GetHashCode(); + + using (var activityListener = new ActivityListener + { + ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, + }) + { + ActivitySource.AddActivityListener(activityListener); + + fakeSqlEventSource.WriteBeginExecuteEvent(objectId, "127.0.0.1", "master", commandType == CommandType.StoredProcedure ? commandText : string.Empty); + + // success is stored in the first bit in compositeState 0b001 + int successFlag = !isFailure ? 1 : 0; + + // isSqlException is stored in the second bit in compositeState 0b010 + int isSqlExceptionFlag = sqlExceptionNumber > 0 ? 2 : 0; + + // synchronous state is stored in the third bit in compositeState 0b100 + int synchronousFlag = false ? 4 : 0; + + int compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; + + fakeSqlEventSource.WriteEndExecuteEvent(objectId, compositeState, sqlExceptionNumber); + } + + Assert.Equal(2, activityProcessor.Invocations.Count); + + var activity = (Activity)activityProcessor.Invocations[1].Arguments[0]; + + VerifyActivityData(commandType, commandText, captureText, isFailure, "127.0.0.1", activity); + } + + [Fact] + public void EventSourceFakeUnknownEventWithNullPayloadTest() + { + using FakeMisbehavingSqlEventSource fakeSqlEventSource = new FakeMisbehavingSqlEventSource(); + + var activityProcessor = new Mock(); + using var shutdownSignal = OpenTelemetrySdk.EnableOpenTelemetry(b => + { + b.AddProcessorPipeline(c => c.AddProcessor(ap => activityProcessor.Object)); + b.AddSqlClientDependencyInstrumentation(); + }); + + using (var activityListener = new ActivityListener + { + ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, + }) + { + ActivitySource.AddActivityListener(activityListener); + + fakeSqlEventSource.WriteUnknownEventWithNullPayload(); + } + + Assert.Equal(0, activityProcessor.Invocations.Count); + } + + [Fact] + public void EventSourceFakeInvalidPayloadTest() + { + using FakeMisbehavingSqlEventSource fakeSqlEventSource = new FakeMisbehavingSqlEventSource(); + + var activityProcessor = new Mock(); + using var shutdownSignal = OpenTelemetrySdk.EnableOpenTelemetry(b => + { + b.AddProcessorPipeline(c => c.AddProcessor(ap => activityProcessor.Object)); + b.AddSqlClientDependencyInstrumentation(); + }); + + using (var activityListener = new ActivityListener + { + ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, + }) + { + ActivitySource.AddActivityListener(activityListener); + + fakeSqlEventSource.WriteBeginExecuteEvent("arg1"); + + fakeSqlEventSource.WriteEndExecuteEvent("arg1", "arg2", "arg3", "arg4"); + } + + Assert.Equal(0, activityProcessor.Invocations.Count); + } + + private static void VerifyActivityData(CommandType commandType, string commandText, bool captureText, bool isFailure, string dataSource, Activity activity) + { Assert.Equal("master", activity.DisplayName); Assert.Equal(ActivityKind.Client, activity.Kind); Assert.Equal("sql", activity.Tags.FirstOrDefault(t => t.Key == SpanAttributeConstants.ComponentKey).Value); @@ -124,6 +233,46 @@ public async Task SuccessfulCommandTest(CommandType commandType, string commandT Assert.Contains(activity.Tags, t => t.Key == SpanAttributeConstants.StatusDescriptionKey); } } + + [EventSource(Name = SqlEventSourceListener.AdoNetEventSourceName + "-FakeFriendly")] + private class FakeBehavingSqlEventSource : EventSource + { + [Event(SqlEventSourceListener.BeginExecuteEventId)] + public void WriteBeginExecuteEvent(int objectId, string dataSource, string databaseName, string commandText) + { + this.WriteEvent(SqlEventSourceListener.BeginExecuteEventId, objectId, dataSource, databaseName, commandText); + } + + [Event(SqlEventSourceListener.EndExecuteEventId)] + public void WriteEndExecuteEvent(int objectId, int compositeState, int sqlExceptionNumber) + { + this.WriteEvent(SqlEventSourceListener.EndExecuteEventId, objectId, compositeState, sqlExceptionNumber); + } + } + + [EventSource(Name = SqlEventSourceListener.AdoNetEventSourceName + "-FakeEvil")] + private class FakeMisbehavingSqlEventSource : EventSource + { + [Event(SqlEventSourceListener.BeginExecuteEventId)] + public void WriteBeginExecuteEvent(string arg1) + { + this.WriteEvent(SqlEventSourceListener.BeginExecuteEventId, arg1); + } + + [Event(SqlEventSourceListener.EndExecuteEventId)] + public void WriteEndExecuteEvent(string arg1, string arg2, string arg3, string arg4) + { + this.WriteEvent(SqlEventSourceListener.EndExecuteEventId, arg1, arg2, arg3, arg4); + } + + [Event(3)] + public void WriteUnknownEventWithNullPayload() + { + object[] args = null; + + this.WriteEvent(3, args); + } + } } } #endif From 7e62d1b8ccf9fdc7c408d0b04e703532e71859f5 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Tue, 7 Jul 2020 07:56:37 -0700 Subject: [PATCH 8/9] Fixed up GrpcClientDiagnosticListener for EventSource changes. --- .../Implementation/GrpcClientDiagnosticListener.cs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/GrpcClientDiagnosticListener.cs b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/GrpcClientDiagnosticListener.cs index 85f0ba2bce6..a00fe5930f8 100644 --- a/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/GrpcClientDiagnosticListener.cs +++ b/src/OpenTelemetry.Instrumentation.Dependencies/Implementation/GrpcClientDiagnosticListener.cs @@ -41,10 +41,9 @@ public GrpcClientDiagnosticListener(ActivitySourceAdapter activitySource) public override void OnStartActivity(Activity activity, object payload) { - const string EventNameSuffix = ".OnStartActivity"; if (!(this.startRequestFetcher.Fetch(payload) is HttpRequestMessage request)) { - InstrumentationEventSource.Log.NullPayload(nameof(GrpcClientDiagnosticListener) + EventNameSuffix); + InstrumentationEventSource.Log.NullPayload(nameof(GrpcClientDiagnosticListener), nameof(this.OnStartActivity)); return; } From b9908b831281bc1c097354b2edaad9b1ea379f8e Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Tue, 7 Jul 2020 08:09:52 -0700 Subject: [PATCH 9/9] Removed extra ActivityListener from unit tests. --- .../HttpWebRequestTests.Basic.netfx.cs | 24 +----- .../SqlEventSourceTests.netfx.cs | 86 ++++++------------- 2 files changed, 30 insertions(+), 80 deletions(-) diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/HttpWebRequestTests.Basic.netfx.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/HttpWebRequestTests.Basic.netfx.cs index cf89f21066f..ea3b3f59076 100644 --- a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/HttpWebRequestTests.Basic.netfx.cs +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/HttpWebRequestTests.Basic.netfx.cs @@ -165,16 +165,8 @@ public async Task HttpDependenciesInstrumentationBacksOffIfAlreadyInstrumented() request.Headers.Add("traceparent", "00-0123456789abcdef0123456789abcdef-0123456789abcdef-01"); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == HttpWebRequestActivitySource.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - using var c = new HttpClient(); - await c.SendAsync(request); - } + using var c = new HttpClient(); + await c.SendAsync(request); Assert.Equal(0, activityProcessor.Invocations.Count); } @@ -193,16 +185,8 @@ public async Task HttpDependenciesInstrumentationFiltersOutRequests() arg1 is HttpWebRequest request && request.RequestUri.OriginalString.Contains(this.url))); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == HttpWebRequestActivitySource.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - using var c = new HttpClient(); - await c.GetAsync(this.url); - } + using var c = new HttpClient(); + await c.GetAsync(this.url); Assert.Equal(0, spanProcessor.Invocations.Count); } diff --git a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs index 591fdde046d..4936adda95e 100644 --- a/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs +++ b/test/OpenTelemetry.Instrumentation.Dependencies.Tests/SqlEventSourceTests.netfx.cs @@ -61,35 +61,25 @@ public async Task SuccessfulCommandTest(CommandType commandType, string commandT }); }); - string dataSource = null; + using SqlConnection sqlConnection = new SqlConnection(SqlConnectionString); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - using SqlConnection sqlConnection = new SqlConnection(SqlConnectionString); - - await sqlConnection.OpenAsync().ConfigureAwait(false); + await sqlConnection.OpenAsync().ConfigureAwait(false); - dataSource = sqlConnection.DataSource; + string dataSource = sqlConnection.DataSource; - sqlConnection.ChangeDatabase("master"); + sqlConnection.ChangeDatabase("master"); - using SqlCommand sqlCommand = new SqlCommand(commandText, sqlConnection) - { - CommandType = commandType, - }; + using SqlCommand sqlCommand = new SqlCommand(commandText, sqlConnection) + { + CommandType = commandType, + }; - try - { - await sqlCommand.ExecuteNonQueryAsync().ConfigureAwait(false); - } - catch - { - } + try + { + await sqlCommand.ExecuteNonQueryAsync().ConfigureAwait(false); + } + catch + { } Assert.Equal(2, activityProcessor.Invocations.Count); @@ -120,28 +110,20 @@ public void EventSourceFakeTests(CommandType commandType, string commandText, bo int objectId = Guid.NewGuid().GetHashCode(); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - fakeSqlEventSource.WriteBeginExecuteEvent(objectId, "127.0.0.1", "master", commandType == CommandType.StoredProcedure ? commandText : string.Empty); + fakeSqlEventSource.WriteBeginExecuteEvent(objectId, "127.0.0.1", "master", commandType == CommandType.StoredProcedure ? commandText : string.Empty); - // success is stored in the first bit in compositeState 0b001 - int successFlag = !isFailure ? 1 : 0; + // success is stored in the first bit in compositeState 0b001 + int successFlag = !isFailure ? 1 : 0; - // isSqlException is stored in the second bit in compositeState 0b010 - int isSqlExceptionFlag = sqlExceptionNumber > 0 ? 2 : 0; + // isSqlException is stored in the second bit in compositeState 0b010 + int isSqlExceptionFlag = sqlExceptionNumber > 0 ? 2 : 0; - // synchronous state is stored in the third bit in compositeState 0b100 - int synchronousFlag = false ? 4 : 0; + // synchronous state is stored in the third bit in compositeState 0b100 + int synchronousFlag = false ? 4 : 0; - int compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; + int compositeState = successFlag | isSqlExceptionFlag | synchronousFlag; - fakeSqlEventSource.WriteEndExecuteEvent(objectId, compositeState, sqlExceptionNumber); - } + fakeSqlEventSource.WriteEndExecuteEvent(objectId, compositeState, sqlExceptionNumber); Assert.Equal(2, activityProcessor.Invocations.Count); @@ -162,15 +144,7 @@ public void EventSourceFakeUnknownEventWithNullPayloadTest() b.AddSqlClientDependencyInstrumentation(); }); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - fakeSqlEventSource.WriteUnknownEventWithNullPayload(); - } + fakeSqlEventSource.WriteUnknownEventWithNullPayload(); Assert.Equal(0, activityProcessor.Invocations.Count); } @@ -187,17 +161,9 @@ public void EventSourceFakeInvalidPayloadTest() b.AddSqlClientDependencyInstrumentation(); }); - using (var activityListener = new ActivityListener - { - ShouldListenTo = (activitySource) => activitySource.Name == SqlEventSourceListener.ActivitySourceName, - }) - { - ActivitySource.AddActivityListener(activityListener); - - fakeSqlEventSource.WriteBeginExecuteEvent("arg1"); + fakeSqlEventSource.WriteBeginExecuteEvent("arg1"); - fakeSqlEventSource.WriteEndExecuteEvent("arg1", "arg2", "arg3", "arg4"); - } + fakeSqlEventSource.WriteEndExecuteEvent("arg1", "arg2", "arg3", "arg4"); Assert.Equal(0, activityProcessor.Invocations.Count); }