diff --git a/CHANGELOG.md b/CHANGELOG.md index 0af4112de0..fd319a5814 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,7 @@ # Changelog ## VNext +- [Support new conventions for EventHubs from Azure.Messaging.EventHubs and processor.](https://github.com/microsoft/ApplicationInsights-dotnet/pull/1674) - [Adding a flag to DependencyTrackingTelemetryModule to enable/disable collection of SQL Command text.](https://github.com/microsoft/ApplicationInsights-dotnet/pull/1514) Collecting SQL Command Text will now be opt-in, so this value will default to false. This is a change from the current behavior on .NET Core. To see how to collect SQL Command Text see here for details: https://docs.microsoft.com/en-us/azure/azure-monitor/app/asp-net-dependencies#advanced-sql-tracking-to-get-full-sql-query - [change references to log4net to version 2.0.8](https://github.com/microsoft/ApplicationInsights-dotnet/issues/1675) diff --git a/WEB/Src/DependencyCollector/Shared.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs b/WEB/Src/DependencyCollector/Shared.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs index 5403a3ef4a..2cb894b3ab 100644 --- a/WEB/Src/DependencyCollector/Shared.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs +++ b/WEB/Src/DependencyCollector/Shared.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs @@ -17,8 +17,16 @@ [TestClass] public class AzureSdkDiagnosticListenerTest { + private static readonly DateTimeOffset EpochStart = new DateTime(1970, 1, 1, 0, 0, 0, 0, System.DateTimeKind.Utc); private TelemetryConfiguration configuration; private List sentItems; + private static readonly JsonSerializerSettings JsonSettingThrowOnError = new JsonSerializerSettings + { + MissingMemberHandling = MissingMemberHandling.Error, + ReferenceLoopHandling = ReferenceLoopHandling.Error, + NullValueHandling = NullValueHandling.Include, + DefaultValueHandling = DefaultValueHandling.Include, + }; [TestInitialize] public void TestInitialize() @@ -118,6 +126,315 @@ public void AzureClientSpansAreCollectedClientKind() } } + [TestMethod] + public void AzureClientSpansAreCollectedProducerKind() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedInternalKind() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "internal"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("InProc", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedProducerKindWithComponentEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + sendActivity.AddTag("component", "eventhubs"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message | Azure Event Hubs", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedInternalKindWithComponentEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "internal"); + sendActivity.AddTag("component", "eventhubs"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("InProc | Azure Event Hubs", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedProducerKindWithComponent() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + sendActivity.AddTag("component", "foo"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message | foo", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedInternalKindWithComponent() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "internal"); + sendActivity.AddTag("component", "foo"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("InProc | foo", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedProducerKindWithAzNamespaceEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + sendActivity.AddTag("az.namespace", "Microsoft.EventHub"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message | Azure Event Hubs", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedProducerKindWithAzNamespaceEventHubsAndAttributes() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + sendActivity.AddTag("az.namespace", "Microsoft.EventHub"); + sendActivity.AddTag("peer.address", "amqps://eventHub.servicebus.windows.net/"); + sendActivity.AddTag("message_bus.destination", "queueName"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message | Azure Event Hubs", telemetry.Type); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Target); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedInternalKindWithAzNamespaceEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "internal"); + sendActivity.AddTag("az.namespace", "Microsoft.EventHub"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("InProc | Azure Event Hubs", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedProducerKindWithAzNamespace() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "producer"); + sendActivity.AddTag("az.namespace", "foo"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("Queue Message | foo", telemetry.Type); + 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); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedInternalKindWithAzNamespace() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "internal"); + sendActivity.AddTag("az.namespace", "foo"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("InProc | foo", telemetry.Type); + 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); + } + } + [TestMethod] public void AzureClientSpansAreCollectedServerKind() { @@ -141,6 +458,69 @@ public void AzureClientSpansAreCollectedServerKind() Assert.IsNull(telemetry.Context.Operation.ParentId); Assert.AreEqual(sendActivity.TraceId.ToHexString(), telemetry.Context.Operation.Id); Assert.AreEqual(sendActivity.SpanId.ToHexString(), telemetry.Id); + Assert.IsFalse(telemetry.Metrics.Any()); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedServerKindEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "server"); + sendActivity.AddTag("az.namespace", "Microsoft.EventHub"); + sendActivity.AddTag("peer.address", "amqps://eventHub.servicebus.windows.net"); + sendActivity.AddTag("message_bus.destination", "queueName"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Source); + 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); + Assert.IsFalse(telemetry.Metrics.Any()); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedConsumerKindEventHubs() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "consumer"); + sendActivity.AddTag("az.namespace", "Microsoft.EventHub"); + sendActivity.AddTag("peer.address", "amqps://eventHub.servicebus.windows.net/"); + sendActivity.AddTag("message_bus.destination", "queueName"); + + listener.StartActivity(sendActivity, null); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Source); + 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); + Assert.IsFalse(telemetry.Metrics.Any()); } } @@ -181,16 +561,64 @@ public void AzureClientSpansAreCollectedLinks() Assert.AreEqual(sendActivity.SpanId.ToHexString(), telemetry.Id); // does not throw - var jsonSettingThrowOnError = new JsonSerializerSettings + 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() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "server"); + + var link0TraceId = "70545f717a9aa6a490d820438b9d2bf6"; + var link1TraceId = "c5aa06717eef0c4592af26323ade92f7"; + var link0SpanId = "8b0b2fb40c84e64a"; + var link1SpanId = "3a69ce690411bb4f"; + + var payload = new PayloadWithLinks { - MissingMemberHandling = MissingMemberHandling.Error, - ReferenceLoopHandling = ReferenceLoopHandling.Error, - NullValueHandling = NullValueHandling.Include, - DefaultValueHandling = DefaultValueHandling.Include, + Links = new List + { + new Activity("link0").SetParentId($"00-{link0TraceId}-{link0SpanId}-01"), + new Activity("link1").SetParentId($"00-{link1TraceId}-{link1SpanId}-01"), + }, }; + listener.StartActivity(sendActivity, payload); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + 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); + var actualLinks = JsonConvert.DeserializeObject(linksStr, JsonSettingThrowOnError); Assert.IsNotNull(actualLinks); Assert.AreEqual(2, actualLinks.Length); @@ -202,6 +630,137 @@ public void AzureClientSpansAreCollectedLinks() 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 AzureConsumerSpansAreCollectedLinksAndTimeInQueue() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "consumer"); + + long enqueued0 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(-100)); + long enqueued1 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(-200)); + long enqueued2 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(-300)); + var payload = new PayloadWithLinks + { + Links = new List + { + CreateRandomLink(enqueued0), + CreateRandomLink(enqueued1), + CreateRandomLink(enqueued2), + }, + }; + + listener.StartActivity(sendActivity, payload); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + 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); + + Assert.AreEqual(1, telemetry.Metrics.Count); + Assert.IsTrue(telemetry.Metrics.TryGetValue("timeSinceEnqueued", out var timeInQueue)); + + var startTimeEpoch = ToUnixTimeStamp(sendActivity.StartTimeUtc); + long expectedTimeInQueue = ((startTimeEpoch - enqueued0) + + (startTimeEpoch - enqueued1) + + (startTimeEpoch - enqueued2)) / 3; // avg diff with request start time across links + + Assert.AreEqual(expectedTimeInQueue, timeInQueue); + } + } + + [TestMethod] + public void AzureConsumerSpansAreCollectedLinksAndTimeInQueueInvalid() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "consumer"); + + var link = new Activity("foo").SetParentId(ActivityTraceId.CreateRandom(), ActivitySpanId.CreateRandom()); + link.AddTag("enqueuedTime", "not long"); + + var payload = new PayloadWithLinks { Links = new List { link, }, }; + + listener.StartActivity(sendActivity, payload); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + 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); + + Assert.IsFalse(telemetry.Metrics.Any()); + } + } + + [TestMethod] + public void AzureConsumerSpansAreCollectedLinksAndTimeInQueueNegative() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var sendActivity = new Activity("Azure.SomeClient.Send"); + sendActivity.AddTag("kind", "consumer"); + + long enqueued0 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(-100)); + long enqueued1 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(-200)); + long enqueued2 = ToUnixTimeStamp(DateTimeOffset.UtcNow.AddMilliseconds(300)); // ignored + var payload = new PayloadWithLinks + { + Links = new List + { + CreateRandomLink(enqueued0), + CreateRandomLink(enqueued1), + CreateRandomLink(enqueued2), + }, + }; + + listener.StartActivity(sendActivity, payload); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as RequestTelemetry; + + 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); + + Assert.AreEqual(1, telemetry.Metrics.Count); + Assert.IsTrue(telemetry.Metrics.TryGetValue("timeSinceEnqueued", out var timeInQueue)); + + var startTimeEpoch = ToUnixTimeStamp(sendActivity.StartTimeUtc); + long expectedTimeInQueue = ((startTimeEpoch - enqueued0) + + (startTimeEpoch - enqueued1)) / 3; // avg diff with request start time across links ignoring outliers (negative diff) + + Assert.AreEqual(expectedTimeInQueue, timeInQueue); } } @@ -356,9 +915,9 @@ public void AzureClientSpansAreCollectedForEventHubs() var exception = new InvalidOperationException(); Activity sendActivity = new Activity("Azure.SomeClient.Send") - .AddTag("peer.address", "amqps://eventHub.servicebus.windows.net/") + .AddTag("peer.address", "amqps://eventHub.servicebus.windows.net") .AddTag("message_bus.destination", "queueName") - .AddTag("kind", "producer") + .AddTag("kind", "client") .AddTag("component", "eventhubs"); listener.StartActivity(sendActivity, null); @@ -369,7 +928,7 @@ public void AzureClientSpansAreCollectedForEventHubs() Assert.IsNotNull(telemetry); Assert.AreEqual("SomeClient.Send", telemetry.Name); - Assert.AreEqual("amqps://eventHub.servicebus.windows.net/ | queueName", telemetry.Target); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Target); Assert.AreEqual(string.Empty, telemetry.Data); Assert.AreEqual(string.Empty, telemetry.ResultCode); Assert.AreEqual("Azure Event Hubs", telemetry.Type); @@ -382,19 +941,54 @@ public void AzureClientSpansAreCollectedForEventHubs() } [TestMethod] - public void AzureClientSpansAreCollectedForEventHubsException() + public void AzureClientSpansAreCollectedForEventHubsMessages() { using (var listener = new DiagnosticListener("Azure.SomeClient")) using (var module = new DependencyTrackingTelemetryModule()) { module.Initialize(this.configuration); + var exception = new InvalidOperationException(); Activity sendActivity = new Activity("Azure.SomeClient.Send") - .AddTag("peer.address", "amqps://eventHub.servicebus.windows.net/") + .AddTag("peer.address", "amqps://eventHub.servicebus.windows.net") .AddTag("message_bus.destination", "queueName") .AddTag("kind", "producer") .AddTag("component", "eventhubs"); + listener.StartActivity(sendActivity, null); + listener.Write("Azure.SomeClient.Send.Exception", exception); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last() as DependencyTelemetry; + + Assert.IsNotNull(telemetry); + Assert.AreEqual("SomeClient.Send", telemetry.Name); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Target); + Assert.AreEqual(string.Empty, telemetry.Data); + Assert.AreEqual(string.Empty, telemetry.ResultCode); + Assert.AreEqual("Queue Message | Azure Event Hubs", telemetry.Type); + Assert.IsFalse(telemetry.Success.Value); + Assert.AreEqual(exception.ToInvariantString(), telemetry.Properties["Error"]); + Assert.IsNull(telemetry.Context.Operation.ParentId); + Assert.AreEqual(sendActivity.TraceId.ToHexString(), telemetry.Context.Operation.Id); + Assert.AreEqual(sendActivity.SpanId.ToHexString(), telemetry.Id); + } + } + + [TestMethod] + public void AzureClientSpansAreCollectedForEventHubsException() + { + using (var listener = new DiagnosticListener("Azure.SomeClient")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + Activity sendActivity = new Activity("Azure.SomeClient.Send") + .AddTag("peer.address", "amqps://eventHub.servicebus.windows.net") + .AddTag("message_bus.destination", "queueName") + .AddTag("kind", "client") + .AddTag("component", "eventhubs"); + listener.StartActivity(sendActivity, null); listener.StopActivity(sendActivity, null); @@ -402,7 +996,7 @@ public void AzureClientSpansAreCollectedForEventHubsException() Assert.IsNotNull(telemetry); Assert.AreEqual("SomeClient.Send", telemetry.Name); - Assert.AreEqual("amqps://eventHub.servicebus.windows.net/ | queueName", telemetry.Target); + Assert.AreEqual("amqps://eventHub.servicebus.windows.net/queueName", telemetry.Target); Assert.AreEqual(string.Empty, telemetry.Data); Assert.AreEqual(string.Empty, telemetry.ResultCode); Assert.AreEqual("Azure Event Hubs", telemetry.Type); @@ -450,6 +1044,23 @@ private T TrackOperation( return null; } + private Activity CreateRandomLink(long enqueuedTimeMs) + { + var activity = new Activity("foo").SetParentId(ActivityTraceId.CreateRandom(), ActivitySpanId.CreateRandom(), ActivityTraceFlags.None); + activity.AddTag("enqueuedTime", enqueuedTimeMs.ToString()); + + return activity; + } + + private long ToUnixTimeStamp(DateTimeOffset datetime) + { +#if NET45 + return (long)(datetime - EpochStart).TotalMilliseconds; +#else + return datetime.ToUnixTimeMilliseconds(); +#endif + } + private class PayloadWithLinks { public IEnumerable Links { get; set; } diff --git a/WEB/Src/DependencyCollector/Shared.Tests/Implementation/EventHubsDiagnosticListenerTests.cs b/WEB/Src/DependencyCollector/Shared.Tests/Implementation/EventHubsDiagnosticListenerTests.cs index d6eb09531b..6a8d822826 100644 --- a/WEB/Src/DependencyCollector/Shared.Tests/Implementation/EventHubsDiagnosticListenerTests.cs +++ b/WEB/Src/DependencyCollector/Shared.Tests/Implementation/EventHubsDiagnosticListenerTests.cs @@ -85,7 +85,7 @@ public void EventHubsSuccessfulSendIsHandled() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual(sendActivity.ParentSpanId.ToHexString(), telemetry.Context.Operation.ParentId); @@ -125,7 +125,7 @@ public void EventHubsSuccessfulReceiveIsHandled() Assert.IsNotNull(telemetry); Assert.AreEqual("Receive", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual(sendActivity.ParentSpanId.ToHexString(), telemetry.Context.Operation.ParentId); @@ -165,7 +165,7 @@ public void EventHubsSuccessfulReceiveShortNameIsHandled() Assert.IsNotNull(telemetry); Assert.AreEqual("Receive", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual(sendActivity.ParentSpanId.ToHexString(), telemetry.Context.Operation.ParentId); @@ -205,7 +205,7 @@ public void EventHubsSuccessfulSendShortNameIsHandled() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual(sendActivity.ParentSpanId.ToHexString(), telemetry.Context.Operation.ParentId); @@ -246,7 +246,7 @@ public void EventHubsSuccessfulSendIsHandledW3COff() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual(parentActivity.Id, telemetry.Context.Operation.ParentId); @@ -281,7 +281,7 @@ public void EventHubsSuccessfulSendIsHandledWithoutParent() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.IsNull(telemetry.Context.Operation.ParentId); @@ -315,7 +315,7 @@ public void EventHubsSuccessfulSendIsHandledWithExternalParent() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsTrue(telemetry.Success.Value); Assert.AreEqual("parent", telemetry.Context.Operation.ParentId); @@ -350,7 +350,7 @@ public void EventHubsFailedSendIsHandled() Assert.IsNotNull(telemetry); Assert.AreEqual("Send", telemetry.Name); Assert.AreEqual(RemoteDependencyConstants.AzureEventHubs, telemetry.Type); - Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ | ehname", telemetry.Target); + Assert.AreEqual("sb://eventhubname.servicebus.windows.net/ehname", telemetry.Target); Assert.IsFalse(telemetry.Success.Value); Assert.AreEqual(sendActivity.ParentSpanId.ToHexString(), telemetry.Context.Operation.ParentId); diff --git a/WEB/Src/DependencyCollector/Shared/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs b/WEB/Src/DependencyCollector/Shared/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs index 435cc3d47c..db6549b7f4 100644 --- a/WEB/Src/DependencyCollector/Shared/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs +++ b/WEB/Src/DependencyCollector/Shared/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs @@ -15,6 +15,10 @@ internal class AzureSdkDiagnosticsEventHandler : DiagnosticsEventHandlerBase { +#if NET45 + private static readonly DateTimeOffset EpochStart = new DateTime(1970, 1, 1, 0, 0, 0, 0, System.DateTimeKind.Utc); +#endif + private readonly ObjectInstanceBasedOperationHolder operationHolder = new ObjectInstanceBasedOperationHolder(); // fetchers must not be reused between sources @@ -48,40 +52,27 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen } } + string type = this.GetType(currentActivity); + if (telemetry == null) { - string dependencyType = RemoteDependencyConstants.InProc; - foreach (var tag in currentActivity.Tags) - { - if (tag.Key == "kind") - { - if (tag.Value == "internal") - { - break; - } - - dependencyType = string.Empty; - } - - if (tag.Key.StartsWith("http.", StringComparison.Ordinal)) - { - dependencyType = RemoteDependencyConstants.HTTP; - break; - } - - if (tag.Key == "component" && tag.Value == "eventhubs") - { - dependencyType = RemoteDependencyConstants.AzureEventHubs; - break; - } - } + telemetry = new DependencyTelemetry { Type = type }; + } - telemetry = new DependencyTelemetry { Type = dependencyType }; + if (type != null && type.EndsWith(RemoteDependencyConstants.AzureEventHubs, StringComparison.Ordinal)) + { + this.SetEventHubsProperties(currentActivity, telemetry); } if (this.linksPropertyFetcher.Fetch(evnt.Value) is IEnumerable activityLinks) { this.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)); @@ -89,21 +80,15 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen else if (evnt.Key.EndsWith(".Stop", StringComparison.Ordinal)) { var telemetry = this.operationHolder.Get(currentActivity).Item1; + this.SetCommonProperties(evnt.Key, evnt.Value, currentActivity, telemetry); - if (telemetry is DependencyTelemetry dependency) + if (telemetry is DependencyTelemetry dependency && dependency.Type == RemoteDependencyConstants.HTTP) { - if (dependency.Type == RemoteDependencyConstants.HTTP) - { - this.SetHttpProperties(currentActivity, dependency); - if (evnt.Value != null) - { - dependency.SetOperationDetail(evnt.Value.GetType().FullName, evnt.Value); - } - } - else if (dependency.Type == RemoteDependencyConstants.AzureEventHubs) + this.SetHttpProperties(currentActivity, dependency); + if (evnt.Value != null) { - this.SetEventHubsProperties(currentActivity, dependency); + dependency.SetOperationDetail(evnt.Value.GetType().FullName, evnt.Value); } } @@ -157,6 +142,106 @@ protected override bool IsOperationSuccessful(string eventName, object eventPayl return true; } + private static bool TryGetAverageTimeInQueueForBatch(IEnumerable links, DateTimeOffset requestStartTime, out long avgTimeInQueue) + { + avgTimeInQueue = 0; + int linksCount = 0; + foreach (var link in links) + { + if (!TryGetEnqueuedTime(link, out var msgEnqueuedTime)) + { + // instrumentation does not consistently report enqueued time, ignoring whole span + return false; + } + + long startEpochTime = 0; +#if NET45 + startEpochTime = (long)(requestStartTime - EpochStart).TotalMilliseconds; +#else + startEpochTime = requestStartTime.ToUnixTimeMilliseconds(); +#endif + avgTimeInQueue += Math.Max(startEpochTime - msgEnqueuedTime, 0); + linksCount++; + } + + if (linksCount == 0) + { + return false; + } + + avgTimeInQueue /= linksCount; + return true; + } + + private static bool TryGetEnqueuedTime(Activity link, out long enqueuedTime) + { + enqueuedTime = 0; + foreach (var attribute in link.Tags) + { + if (attribute.Key == "enqueuedTime") + { + if (attribute.Value is string strValue) + { + return long.TryParse(strValue, out enqueuedTime); + } + } + } + + return false; + } + + private string GetType(Activity currentActivity) + { + string kind = RemoteDependencyConstants.InProc; + string component = null; + foreach (var tag in currentActivity.Tags) + { + if (tag.Key.StartsWith("http.", StringComparison.Ordinal)) + { + return RemoteDependencyConstants.HTTP; + } + + switch (tag.Key) + { + case "kind": + switch (tag.Value) + { + case "internal": + break; + case "producer": + kind = RemoteDependencyConstants.QueueMessage; + break; + default: + kind = null; + break; + } + + break; + + case "component": + case "az.namespace": + component = tag.Value; + break; + } + } + + if (component == "eventhubs" || component == "Microsoft.EventHub") + { + return kind == null + ? RemoteDependencyConstants.AzureEventHubs + : string.Concat(kind, " | ", RemoteDependencyConstants.AzureEventHubs); + } + + if (component != null) + { + return kind == null + ? component + : string.Concat(kind, " | ", component); + } + + return kind ?? string.Empty; + } + private void SetHttpProperties(Activity activity, DependencyTelemetry dependency) { string method = null; @@ -205,7 +290,7 @@ private void SetHttpProperties(Activity activity, DependencyTelemetry dependency } } - private void SetEventHubsProperties(Activity activity, DependencyTelemetry dependency) + private void SetEventHubsProperties(Activity activity, OperationTelemetry telemetry) { string endpoint = null; string queueName = null; @@ -222,9 +307,29 @@ private void SetEventHubsProperties(Activity activity, DependencyTelemetry depen } } + if (endpoint == null || queueName == null) + { + return; + } + // Target uniquely identifies the resource, we use both: queueName and endpoint // with schema used for SQL-dependencies - dependency.Target = string.Concat(endpoint, " | ", queueName); + string separator = "/"; + if (endpoint.EndsWith(separator, StringComparison.Ordinal)) + { + separator = string.Empty; + } + + string eventHubInfo = string.Concat(endpoint, separator, queueName); + + if (telemetry is DependencyTelemetry dependency) + { + dependency.Target = eventHubInfo; + } + else if (telemetry is RequestTelemetry request) + { + request.Source = eventHubInfo; + } } private void PopulateLinks(IEnumerable links, OperationTelemetry telemetry) diff --git a/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/DiagnosticsEventHandlerBase.cs b/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/DiagnosticsEventHandlerBase.cs index 8b8dde6c46..37e26beb46 100644 --- a/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/DiagnosticsEventHandlerBase.cs +++ b/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/DiagnosticsEventHandlerBase.cs @@ -40,7 +40,11 @@ public virtual bool IsEventEnabled(string evnt, object arg1, object arg2) protected void SetCommonProperties(string eventName, object eventPayload, Activity activity, OperationTelemetry telemetry) { - telemetry.Name = this.GetOperationName(eventName, eventPayload, activity); + if (string.IsNullOrEmpty(telemetry.Name)) + { + telemetry.Name = this.GetOperationName(eventName, eventPayload, activity); + } + telemetry.Duration = activity.Duration; telemetry.Timestamp = activity.StartTimeUtc; diff --git a/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/EventHubsDiagnosticsEventHandler.cs b/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/EventHubsDiagnosticsEventHandler.cs index 06c5400191..6a1166d76d 100644 --- a/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/EventHubsDiagnosticsEventHandler.cs +++ b/WEB/Src/DependencyCollector/Shared/Implementation/EventHandlers/EventHubsDiagnosticsEventHandler.cs @@ -58,9 +58,21 @@ private void OnDependency(string name, object payload, Activity activity) // Target uniquely identifies the resource, we use both: queueName and endpoint // with schema used for SQL-dependencies - telemetry.Target = string.Join(" | ", endpoint, queueName); + if (endpoint == null || queueName == null) + { + return; + } + + // 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)) + { + separator = string.Empty; + } + telemetry.Target = string.Concat(endpoint, separator, queueName); this.TelemetryClient.TrackDependency(telemetry); } } -} +} \ No newline at end of file diff --git a/WEB/Src/DependencyCollector/Shared/Implementation/RemoteDependencyConstants.cs b/WEB/Src/DependencyCollector/Shared/Implementation/RemoteDependencyConstants.cs index 181f1fd122..99bd9df6ed 100644 --- a/WEB/Src/DependencyCollector/Shared/Implementation/RemoteDependencyConstants.cs +++ b/WEB/Src/DependencyCollector/Shared/Implementation/RemoteDependencyConstants.cs @@ -15,6 +15,7 @@ internal static class RemoteDependencyConstants public const string AzureIotHub = "Azure IoT Hub"; public const string AzureSearch = "Azure Search"; public const string InProc = "InProc"; + public const string QueueMessage = "Queue Message"; public const string WcfService = "WCF Service"; public const string WebService = "Web Service";