From fb9c9477e9828b144165e919ab8c755b199a1ac8 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Tue, 9 Mar 2021 15:50:23 -0800 Subject: [PATCH 1/4] Support ActivityLinks --- .../AzureSdkDiagnosticsEventHandler.cs | 69 ++++++++++++++----- 1 file changed, 51 insertions(+), 18 deletions(-) diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs index 4a25454a48..c3f7a383e4 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs @@ -1,6 +1,7 @@ namespace Microsoft.ApplicationInsights.DependencyCollector.Implementation { using System; + using System.Collections; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -64,15 +65,44 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen SetEventHubsProperties(currentActivity, telemetry); } - if (this.linksPropertyFetcher.Fetch(evnt.Value) is IEnumerable activityLinks) - { - PopulateLinks(activityLinks, telemetry); + IEnumerable activityLinks; - if (telemetry is RequestTelemetry request && - TryGetAverageTimeInQueueForBatch(activityLinks, currentActivity.StartTimeUtc, out long enqueuedTime)) + // Pre ActivitySource Azure SDKs are using custom activity subtype with + // public IEnumerable Links { get; } + // property to represent links + if (evnt.Value.GetType() != typeof(Activity) && + this.linksPropertyFetcher.Fetch(evnt.Value) is IEnumerable links && + links.Any()) + { + List convertedLinks = new List(); + foreach (var linksAsActivity in links) { - request.Metrics["timeSinceEnqueued"] = enqueuedTime; + if (linksAsActivity.ParentId != null && + ActivityContext.TryParse(linksAsActivity.ParentId, null, out var context)) + { + ActivityTagsCollection tags = null; + if (linksAsActivity.TagObjects.Any()) + { + tags = new ActivityTagsCollection(linksAsActivity.TagObjects); + } + + convertedLinks.Add(new ActivityLink(context, tags)); + } } + + activityLinks = convertedLinks; + } + else + { + activityLinks = currentActivity.Links; + } + + PopulateLinks(activityLinks, telemetry); + + if (telemetry is RequestTelemetry request && + TryGetAverageTimeInQueueForBatch(activityLinks, currentActivity.StartTimeUtc, out long enqueuedTime)) + { + request.Metrics["timeSinceEnqueued"] = enqueuedTime; } this.operationHolder.Store(currentActivity, Tuple.Create(telemetry, /* isCustomCreated: */ false)); @@ -142,7 +172,7 @@ protected override bool IsOperationSuccessful(string eventName, object eventPayl return true; } - private static bool TryGetAverageTimeInQueueForBatch(IEnumerable links, DateTimeOffset requestStartTime, out long avgTimeInQueue) + private static bool TryGetAverageTimeInQueueForBatch(IEnumerable links, DateTimeOffset requestStartTime, out long avgTimeInQueue) { avgTimeInQueue = 0; int linksCount = 0; @@ -153,7 +183,7 @@ private static bool TryGetAverageTimeInQueueForBatch(IEnumerable links // instrumentation does not consistently report enqueued time, ignoring whole span return false; } - + long startEpochTime = 0; #if NET452 startEpochTime = (long)(requestStartTime - EpochStart).TotalMilliseconds; @@ -173,16 +203,19 @@ private static bool TryGetAverageTimeInQueueForBatch(IEnumerable links return true; } - private static bool TryGetEnqueuedTime(Activity link, out long enqueuedTime) + private static bool TryGetEnqueuedTime(ActivityLink link, out long enqueuedTime) { enqueuedTime = 0; - foreach (var attribute in link.Tags) + if (link.Tags != null) { - if (attribute.Key == "enqueuedTime") + foreach (var attribute in link.Tags) { - if (attribute.Value is string strValue) + if (attribute.Key == "enqueuedTime") { - return long.TryParse(strValue, out enqueuedTime); + if (attribute.Value is string strValue) + { + return long.TryParse(strValue, out enqueuedTime); + } } } } @@ -312,7 +345,7 @@ private static void SetEventHubsProperties(Activity activity, OperationTelemetry return; } - // Target uniquely identifies the resource, we use both: queueName and endpoint + // Target uniquely identifies the resource, we use both: queueName and endpoint // with schema used for SQL-dependencies string separator = "/"; if (endpoint.EndsWith(separator, StringComparison.Ordinal)) @@ -332,15 +365,15 @@ private static void SetEventHubsProperties(Activity activity, OperationTelemetry } } - private static void PopulateLinks(IEnumerable links, OperationTelemetry telemetry) + private static void PopulateLinks(IEnumerable links, OperationTelemetry telemetry) { - if (links.Any()) + if (links != null && links.Any()) { var linksJson = new StringBuilder(); linksJson.Append('['); foreach (var link in links) { - var linkTraceId = link.TraceId.ToHexString(); + var linkTraceId = link.Context.TraceId.ToHexString(); // avoiding json serializers for now because of extra dependency. // serialization is trivial and looks like `links` property with json blob @@ -356,7 +389,7 @@ private static void PopulateLinks(IEnumerable links, OperationTelemetr linksJson .Append("\"id\":") .Append('\"') - .Append(link.ParentSpanId.ToHexString()) + .Append(link.Context.SpanId.ToHexString()) .Append('\"'); // we explicitly ignore sampling flag, tracestate and attributes at this point. From 05221b64fdd97ca25387f93dc53f2984fcfca191 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Fri, 2 Apr 2021 10:32:16 -0700 Subject: [PATCH 2/4] test --- .../AzureSdkDiagnosticListenerTest.cs | 63 ++++++++++++++++++- 1 file changed, 61 insertions(+), 2 deletions(-) diff --git a/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs b/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs index 8906566ce3..90c86e9444 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs @@ -93,7 +93,7 @@ public void AzureClientSpansAreCollected() Assert.AreEqual(sendActivity.SpanId.ToHexString(), telemetry.Id); Assert.AreEqual("v1", telemetry.Properties["k1"]); - + Assert.IsTrue(telemetry.Properties.TryGetValue("tracestate", out var tracestate)); Assert.AreEqual("state=some", tracestate); } @@ -608,6 +608,65 @@ public void AzureClientSpansAreCollectedLinks() } } + [TestMethod] + public void AzureClientSpansAreCollectedLinksFromActivitySource() + { + // Create the activity listener to make sure that activitySource.StartActivity returns a value + using (var activityListener = new ActivityListener() + { + ShouldListenTo = source => source.Name == "Azure.SomeClient", + Sample = (ref ActivityCreationOptions options) => ActivitySamplingResult.AllDataAndRecorded + }) + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var activitySource = new ActivitySource("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + ActivitySource.AddActivityListener(activityListener); + + module.Initialize(this.configuration); + + var link0TraceId = "70545f717a9aa6a490d820438b9d2bf6"; + var link1TraceId = "c5aa06717eef0c4592af26323ade92f7"; + var link0SpanId = "8b0b2fb40c84e64a"; + var link1SpanId = "3a69ce690411bb4f"; + + var sendActivity = activitySource.StartActivity("Azure.SomeClient.Send", ActivityKind.Consumer, default(ActivityContext), links: new [] + { + new ActivityLink(new ActivityContext(ActivityTraceId.CreateFromString(link0TraceId.AsSpan()), ActivitySpanId.CreateFromString(link0SpanId.AsSpan()), ActivityTraceFlags.None)), + new ActivityLink(new ActivityContext(ActivityTraceId.CreateFromString(link1TraceId.AsSpan()), ActivitySpanId.CreateFromString(link1SpanId.AsSpan()), ActivityTraceFlags.None)) + }); + + listener.Write(sendActivity.OperationName + ".Start", sendActivity); + listener.Write(sendActivity.OperationName + ".Stop", null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.IsTrue(telemetry.Success.Value); + + Assert.IsNull(telemetry.Context.Operation.ParentId); + Assert.AreEqual(sendActivity.TraceId.ToHexString(), telemetry.Context.Operation.Id); + Assert.AreEqual(sendActivity.SpanId.ToHexString(), telemetry.Id); + + // does not throw + Assert.IsTrue(telemetry.Properties.TryGetValue("_MS.links", out var linksStr)); + var actualLinks = JsonConvert.DeserializeObject(linksStr, JsonSettingThrowOnError); + + Assert.IsNotNull(actualLinks); + Assert.AreEqual(2, actualLinks.Length); + + Assert.AreEqual(link0TraceId, actualLinks[0].OperationId); + Assert.AreEqual(link1TraceId, actualLinks[1].OperationId); + + Assert.AreEqual(link0SpanId, actualLinks[0].Id); + Assert.AreEqual(link1SpanId, actualLinks[1].Id); + + Assert.AreEqual($"[{{\"operation_Id\":\"{link0TraceId}\",\"id\":\"{link0SpanId}\"}},{{\"operation_Id\":\"{link1TraceId}\",\"id\":\"{link1SpanId}\"}}]", linksStr); + Assert.IsFalse(telemetry.Metrics.Any()); + } + } + [TestMethod] public void AzureServerSpansAreCollectedLinks() { @@ -847,7 +906,7 @@ public void AzureClientSpansAreCollectedForHttp() .AddTag("serviceRequestId", "service-request-id"); listener.StopActivity(httpActivity, payload); - + var telemetry = this.sentItems.Last() as DependencyTelemetry; Assert.IsNotNull(telemetry); From 096c786c51223045384050f812f651de156b70e7 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Wed, 6 Oct 2021 15:16:17 -0700 Subject: [PATCH 3/4] feedback --- .../AzureSdkDiagnosticsEventHandler.cs | 22 +++++++++---------- 1 file changed, 10 insertions(+), 12 deletions(-) diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs index 7cf8f4cb2b..b24690b448 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs @@ -71,15 +71,17 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen SetEventHubsProperties(currentActivity, telemetry); } - IEnumerable activityLinks; - - // Pre ActivitySource Azure SDKs are using custom activity subtype with - // public IEnumerable Links { get; } - // property to represent links - if (evnt.Value.GetType() != typeof(Activity) && - this.linksPropertyFetcher.Fetch(evnt.Value) is IEnumerable links && - links.Any()) + IEnumerable activityLinks = ArrayExtensions.Empty(); + + if (currentActivity.Links.Any()) + { + activityLinks = currentActivity.Links; + } + else if (this.linksPropertyFetcher.Fetch(evnt.Value) is IEnumerable links && links.Any()) { + // Pre ActivitySource Azure SDKs are using custom activity subtype with + // public IEnumerable Links { get; } + // property to represent links List convertedLinks = new List(); foreach (var linksAsActivity in links) { @@ -98,10 +100,6 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen activityLinks = convertedLinks; } - else - { - activityLinks = currentActivity.Links; - } PopulateLinks(activityLinks, telemetry); From 9c314f86e5cfb1469c620645d2cef28d512469e5 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Wed, 6 Oct 2021 17:01:53 -0700 Subject: [PATCH 4/4] changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index b20a9ebc60..8607e256f1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ - [The `{OriginalFormat}` field in ILogger Scope will be emitted as `OriginalFormat` with the braces removed](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2362) - [Enable SDK to create package for auto-instrumentation](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2365) - [Suppress long running SignalR connections](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2372) +- [Support ActivitySource in Azure SDK client libraries](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2185) ## Version 2.18.0 - [Change Self-Diagnostics to include datetimestamp in filename](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2325)