Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added instrumentation for netfx SqlClient. #761

Merged
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,6 @@
using System.Data;
using System.Diagnostics;
using OpenTelemetry.Trace;
using OpenTelemetry.Trace.Samplers;

namespace OpenTelemetry.Instrumentation.Dependencies.Implementation
{
Expand Down Expand Up @@ -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());
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change was made to avoid the .ToString perf hit. Unrelated to the main changes, sorry.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:D I read this comment late, and was still trying to figure out this part !


switch (commandType)
{
case CommandType.StoredProcedure:
activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "StoredProcedure");
Copy link
Contributor

@eddynaka eddynaka Jul 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of using the magic string "StoredProcedure", i would use nameof(commandtype) or nameof(CommandType.StoredProcedure). The same comment applys for "Text" / "TableDirect"

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@eddynaka What you have against magic? j/k I added the nameof part in both Sql instrumentation classes.

@cijothomas I'll open an issue in spec for db.statement_type but my success rate there so far has been 0 😭 Maybe we should name it db.mssql.statement_type? Looking at the guide, what's interesting is that a lot of the database semantics have changed since I last worked on this instrumentation. I updated them on this PR:

  • db.type is now db.system and we send mssql instead of sql.
  • db.instance is now db.name.

if (this.options.CaptureStoredProcedureCommandName)
{
activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText);
Expand All @@ -104,12 +102,17 @@ public override void OnCustom(string name, Activity activity, object payload)
break;

case CommandType.Text:
activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "Text");
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
if (this.options.CaptureTextCommandContent)
{
activity.AddTag(SpanAttributeConstants.DatabaseStatementKey, (string)commandText);
}

break;

case CommandType.TableDirect:
activity.AddTag(DatabaseStatementTypeSpanAttributeKey, "TableDirect");
break;
}
}
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,131 @@
// <copyright file="SqlEventSourceListener.netfx.cs" company="OpenTelemetry Authors">
// 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.
// </copyright>
#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
{
/// <summary>
/// .NET Framework SqlClient doesn't emit DiagnosticSource events.
/// We hook into its EventSource if it is available:
/// See: <a href="https://github.com/microsoft/referencesource/blob/3b1eaf5203992df69de44c783a3eda37d3d4cd10/System.Data/System/Data/Common/SqlEventSource.cs#L29">reference source</a>.
/// </summary>
internal class SqlEventSourceListener : EventListener
{
internal const string ActivitySourceName = "SqlClient";
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if we make a EventSource writer (i.e FakeSql : EventSource) which mimics the SqlClient event, we could unit test, right? (similar to unit tests firing DiagnosticSource events?)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@cijothomas I'll investigate this docker thing a bit. If it's quick to get up and running that would be great. Otherwise, I'll add some "faked" tests.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay.
cc: @TimothyMothra as he'd be looking at adding E2E test pipeline soon.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried to get integration tests up and running on docker but ran into a problem. This is .NET Framework specific code, so we need a Windows container. That's not supported on GitHub at the moment, from what I can tell (ref). In the end, I did two things:

  1. Added integration tests that will skip unless an environment variable is set.
  2. Added fake event source tests. That gives us the same level of testing as the other Sql stuff.

I did get pretty far into getting the container up and running. What I would like to do is complete this PR, and then I can try to get Sql integration tests up and running for our .NET Core stuff? I think that will work because there are SQL Linux images and of course .NET Core SDK Linux images.


private readonly SqlClientInstrumentationOptions options;

public SqlEventSourceListener(SqlClientInstrumentationOptions options = null)
{
this.options = options ?? new SqlClientInstrumentationOptions();

if (SqlEventSource != null)
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
{
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)
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
{
// BeginExecuteEventId

var activity = SqlClientActivitySource.StartActivity(ActivityName, ActivityKind.Client);
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
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]))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

will this throw if Payload has less than 4 count? Lets do a safety check to ensure payload[3] is fine. (some old version did not provide all the payload , maybe irrelevant now, but lets be on defensive side)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added some defensive checks. Now validates for payload being null, payload not being the expected size. Doesn't validate the types of the payload so casts could blow up. But that seemed like taking it a step too far? LMK

{
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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we dont ever expect to this condition right? I'd suggest to add a Warning/Error log.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wouldn't this happen for samplers that return ActivityDataRequest.None which would result in no Activity being created? In that case Begin & End events would still fire, but Activity would be null.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes you are right. This part is still not expected - activity.Source != SqlClientActivitySource ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In my mind, it's expected. That case would be, sampler returned ActivityDataRequest.None for our Sql activity but there is some other parent Activity running. It could be any Activity, really. Some parent that was sampled, and the child was None, or it could be some random Activity not run through a sampler at all. Something like this:

            Activity myActivity = new Activity("Call SQL user activity");
            myActivity.Start();
            try
            {
                using (SqlConnection connection = new SqlConnection("Data Source=sqlserver;Initial Catalog=master;Integrated Security=True;"))
                {
                    connection.Open();

                    using (SqlCommand command = new SqlCommand("select 1/1", connection))
                    {
                        command.ExecuteNonQuery();
                    }
                }
            }
            catch { }
            myActivity.Stop();
            Log.LogActivity(myActivity);

In that case, when EndExecute fires Activity.Current will be non-null! The activity.Source == SqlClientActivitySource check is to make sure it is actually our activity so we don't stop/tag something that doesn't belong to us.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perfect! thanks for clarifying.

}

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
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,9 @@ public class SqlClientInstrumentation : IDisposable
internal const string SqlClientDiagnosticListenerName = "SqlClientDiagnosticListener";

private readonly DiagnosticSourceSubscriber diagnosticSourceSubscriber;
#if NETFRAMEWORK
private readonly SqlEventSourceListener sqlEventSourceListener;
#endif

/// <summary>
/// Initializes a new instance of the <see cref="SqlClientInstrumentation"/> class.
Expand All @@ -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
}

/// <inheritdoc/>
public void Dispose()
{
this.diagnosticSourceSubscriber?.Dispose();
#if NETFRAMEWORK
this.sqlEventSourceListener?.Dispose();
#endif
}
}
}