diff --git a/CHANGELOG.md b/CHANGELOG.md index 3d50241877..11011f37b0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ - AzureSdkDiagnosticListener modified to use sdkversion prefix "rdddsaz" instead of "dotnet". - [ILogger logs with LogLevel.None severity are now ignored by ApplicationInsightsLogger](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2667). Fixes ([#2666](https://github.com/microsoft/ApplicationInsights-dotnet/issues/2666)) - [Fix ExceptionTelemetry clears all Context when updating Exception property](https://github.com/microsoft/ApplicationInsights-dotnet/issues/2086) +- [Support dependency tracking and diagnostics events for Microsoft.Azure.Cosmos v3](https://github.com/microsoft/ApplicationInsights-dotnet/pull/2635) ## Version 2.21.0 - no changes since beta. diff --git a/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs b/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs index 728b90a46e..45ac1f3f45 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector.Tests/Implementation/AzureSdkDiagnosticListenerTest.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; + using System.Diagnostics.Tracing; using System.Linq; using System.Net.Http; using Microsoft.ApplicationInsights.Channel; @@ -1263,6 +1264,216 @@ public void AzureServiceBusSpansAreCollectedError(string kind) } } + [TestMethod] + public void AzureCosmosDbSpansAreCollected() + { + using (var listener = new DiagnosticListener("Azure.Cosmos")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var exception = new InvalidOperationException(); + Activity sendActivity = new Activity("Azure.Cosmos.ReadItems") + .AddTag("net.peer.name", "my.documents.azure.com") + .AddTag("db.name", "database") + .AddTag("db.operation", "ReadItems") + .AddTag("db.cosmosdb.container", "container") + .AddTag("kind", "client") + .AddTag("az.namespace", "Microsoft.DocumentDB"); + + listener.StartActivity(sendActivity, null); + listener.Write("Azure.Cosmos.ReadItems.Exception", exception); + sendActivity.AddTag("db.cosmosdb.status_code", "503"); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last(); + + Assert.IsNotNull(telemetry); + Assert.IsNull(telemetry.Context.Operation.ParentId); + Assert.AreEqual(sendActivity.TraceId.ToHexString(), telemetry.Context.Operation.Id); + + DependencyTelemetry dependency = telemetry as DependencyTelemetry; + Assert.IsFalse(dependency.Success.Value); + Assert.AreEqual(exception.ToInvariantString(), dependency.Properties["Error"]); + Assert.AreEqual(sendActivity.SpanId.ToHexString(), dependency.Id); + Assert.AreEqual("container | ReadItems", dependency.Name); + Assert.AreEqual("my.documents.azure.com | database", dependency.Target); + Assert.AreEqual("503", dependency.ResultCode); + Assert.AreEqual("Microsoft.DocumentDB", dependency.Type); + Assert.IsTrue(String.IsNullOrEmpty(dependency.Data)); + + Assert.IsTrue(dependency.Properties.ContainsKey("db.name")); + Assert.IsTrue(dependency.Properties.ContainsKey("db.operation")); + Assert.IsTrue(dependency.Properties.ContainsKey("net.peer.name")); + Assert.IsTrue(dependency.Properties.ContainsKey("db.cosmosdb.container")); + Assert.AreEqual("container", dependency.Properties["db.cosmosdb.container"]); + Assert.AreEqual("database", dependency.Properties["db.name"]); + Assert.AreEqual("ReadItems", dependency.Properties["db.operation"]); + Assert.AreEqual("my.documents.azure.com", dependency.Properties["net.peer.name"]); + } + } + + [TestMethod] + public void AzureCosmosDbSpansErrorsAreCollected() + { + using (var listener = new DiagnosticListener("Azure.Cosmos")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var exception = new InvalidOperationException(); + Activity sendActivity = new Activity("Azure.Cosmos.ReadItems") + .AddTag("net.peer.name", "my.documents.azure.com") + .AddTag("db.name", "database") + .AddTag("db.operation", "ReadItems") + .AddTag("db.cosmosdb.container", "container") + .AddTag("kind", "client") + .AddTag("az.namespace", "Microsoft.DocumentDB"); + + listener.StartActivity(sendActivity, null); + + sendActivity.AddTag("db.cosmosdb.status_code", "200"); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last(); + + Assert.IsNotNull(telemetry); + Assert.IsNull(telemetry.Context.Operation.ParentId); + Assert.AreEqual(sendActivity.TraceId.ToHexString(), telemetry.Context.Operation.Id); + + DependencyTelemetry dependency = telemetry as DependencyTelemetry; + Assert.IsTrue(dependency.Success.Value); + Assert.AreEqual(sendActivity.SpanId.ToHexString(), dependency.Id); + Assert.AreEqual("container | ReadItems", dependency.Name); + Assert.AreEqual("my.documents.azure.com | database", dependency.Target); + Assert.AreEqual("200", dependency.ResultCode); + Assert.AreEqual("Microsoft.DocumentDB", dependency.Type); + } + } + + [TestMethod] + public void AzureCosmosDbSpansAreCollectedWithExtraAttributes() + { + using (var listener = new DiagnosticListener("Azure.Cosmos")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var exception = new InvalidOperationException(); + Activity sendActivity = new Activity("Azure.Cosmos.ReadItems") + .AddTag("kind", "client") + .AddTag("net.peer.name", "my.documents.azure.com") + .AddTag("db.name", "database") + .AddTag("db.operation", "ReadItems") + .AddTag("db.cosmosdb.container", "container") + .AddTag("db.cosmosdb.retry_count", "2") + .AddTag("db.cosmosdb.connection_mode", "Direct") + .AddTag("db.cosmosdb.item_count", "42") + .AddTag("db.cosmosdb.request_charge", "0.123") + .AddTag("foo", "bar") + .AddTag("az.namespace", "Microsoft.DocumentDB"); + + listener.StartActivity(sendActivity, null); + sendActivity.AddTag("db.cosmosdb.status_code", "503"); + listener.StopActivity(sendActivity, null); + + var telemetry = this.sentItems.Last(); + DependencyTelemetry dependency = telemetry as DependencyTelemetry; + Assert.AreEqual("container | ReadItems", dependency.Name); + Assert.AreEqual("my.documents.azure.com | database", dependency.Target); + Assert.AreEqual("503", dependency.ResultCode); + Assert.AreEqual("Microsoft.DocumentDB", dependency.Type); + Assert.AreEqual("2", dependency.Properties["db.cosmosdb.retry_count"]); + Assert.AreEqual("0.123", dependency.Properties["db.cosmosdb.request_charge"]); + Assert.AreEqual("Direct", dependency.Properties["db.cosmosdb.connection_mode"]); + Assert.AreEqual("42", dependency.Properties["db.cosmosdb.item_count"]); + + Assert.AreEqual("container", dependency.Properties["db.cosmosdb.container"]); + Assert.AreEqual("database", dependency.Properties["db.name"]); + Assert.AreEqual("ReadItems", dependency.Properties["db.operation"]); + Assert.AreEqual("my.documents.azure.com", dependency.Properties["net.peer.name"]); + Assert.IsFalse(dependency.Properties.ContainsKey("foo")); + Assert.IsFalse(dependency.Properties.ContainsKey("db.system")); + } + } + +#if !NET452 + [TestMethod] + public void AzureCosmosDbSpansAreCollectedWithLogs() + { + // .NET452 does not support setting custom EventSource and Cosmos DB SDK does not have targets below net461 + // so no point in testing net452. + // but we still need to test .NET framework versions that support setting event source name + // but fallback to depednencycollector dependency net452 target + using (var listener = new DiagnosticListener("Azure.Cosmos")) + using (var module = new DependencyTrackingTelemetryModule()) + { + module.Initialize(this.configuration); + + var exception = new InvalidOperationException(); + Activity sendActivity = new Activity("Azure.Cosmos.ReadItems") + .AddTag("kind", "client") + .AddTag("net.peer.name", "my.documents.azure.com") + .AddTag("db.name", "database") + .AddTag("db.operation", "ReadItems") + .AddTag("db.cosmosdb.container", "container") + .AddTag("az.namespace", "Microsoft.DocumentDB"); + + listener.StartActivity(sendActivity, null); + + CosmosDbEventSource.Singleton.RecordVerbose("verbose message - ignored"); + CosmosDbEventSource.Singleton.RecordInfo("info message"); + CosmosDbEventSource.Singleton.RecordWarn("warn message"); + CosmosDbEventSource.Singleton.RecordError("error message"); + CosmosDbEventSource.Singleton.RecordWarnNoMessage("payload only"); + CosmosDbEventSource.Singleton.RecordWarnNoMessageTwoArguments("payload1", "payload2"); + CosmosDbEventSource.Singleton.RecordWarnNoMessageTwoArguments("payload1", null); + listener.StopActivity(sendActivity, null); + + var dependency = this.sentItems.Single(t => t is DependencyTelemetry) as DependencyTelemetry; + var logs = this.sentItems + .Where(t => t is TraceTelemetry) + .Select(t => t as TraceTelemetry) + .ToList(); + + Assert.IsTrue(dependency.Success.Value); + Assert.IsTrue(String.IsNullOrEmpty(dependency.ResultCode)); + Assert.AreEqual(6, logs.Count); + + Assert.AreEqual("info message", logs[0].Message); + Assert.AreEqual("warn message", logs[1].Message); + Assert.AreEqual("error message", logs[2].Message); + Assert.AreEqual("payload only", logs[3].Message); + Assert.AreEqual("payload1, payload2", logs[4].Message); + Assert.AreEqual("payload1, ", logs[5].Message); + + Assert.AreEqual(SeverityLevel.Information, logs[0].SeverityLevel); + Assert.AreEqual(SeverityLevel.Warning, logs[1].SeverityLevel); + Assert.AreEqual(SeverityLevel.Error, logs[2].SeverityLevel); + + Assert.AreEqual(dependency.Id, logs[0].Context.Operation.ParentId); + Assert.AreEqual(dependency.Id, logs[1].Context.Operation.ParentId); + Assert.AreEqual(dependency.Id, logs[2].Context.Operation.ParentId); + + Assert.AreEqual(dependency.Context.Operation.Id, logs[0].Context.Operation.Id); + Assert.AreEqual(dependency.Context.Operation.Id, logs[1].Context.Operation.Id); + Assert.AreEqual(dependency.Context.Operation.Id, logs[2].Context.Operation.Id); + + Assert.AreEqual("3", logs[0].Properties["EventId"]); + Assert.AreEqual("2", logs[1].Properties["EventId"]); + Assert.AreEqual("1", logs[2].Properties["EventId"]); + +#if NET5_0_OR_GREATER || NETCOREAPP2_0_OR_GREATER + // DependencyCollector has net452 and netstandard20 targets + // test targets that falls back to net452 dependency would not have EventName available + // because EventSource on .NET 4.5.2 does not support it + Assert.AreEqual("RecordInfo", logs[0].Properties["EventName"]); + Assert.AreEqual("RecordWarn", logs[1].Properties["EventName"]); + Assert.AreEqual("RecordError", logs[2].Properties["EventName"]); +#endif + } + } +#endif private T TrackOperation( DiagnosticListener listener, @@ -1330,5 +1541,54 @@ private class ApplicationInsightsLink [JsonProperty("id")] public string Id { get; set; } } + +#if !NET452 + class CosmosDbEventSource : EventSource + { + private CosmosDbEventSource() + : base("Azure.Cosmos_foo") + { + } + + public static CosmosDbEventSource Singleton { get; } = new CosmosDbEventSource(); + + [Event(1, Level = EventLevel.Error, Message = "{0}")] + public void RecordError(string diagnostics) + { + this.WriteEvent(1, diagnostics); + } + + [Event(2, Level = EventLevel.Warning, Message = "{0}")] + public void RecordWarn(string diagnostics) + { + this.WriteEvent(2, diagnostics); + } + + [Event(3, Level = EventLevel.Informational, Message = "{0}")] + public void RecordInfo(string diagnostics) + { + this.WriteEvent(3, diagnostics); + } + + [Event(4, Level = EventLevel.Warning)] + public void RecordWarnNoMessage(string diagnostics) + { + this.WriteEvent(4, diagnostics); + } + + [Event(5, Level = EventLevel.Warning)] + public void RecordWarnNoMessageTwoArguments(string diagnostics1, string diagnostics2) + { + this.WriteEvent(5, diagnostics1, diagnostics2); + } + + + [Event(6, Level = EventLevel.Verbose, Message = "{0}")] + public void RecordVerbose(string diagnostics) + { + this.WriteEvent(6, diagnostics); + } + } +#endif } } \ No newline at end of file diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticListenerSubscriber.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticListenerSubscriber.cs index 0d0e7d0a91..9aea384bfd 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticListenerSubscriber.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticListenerSubscriber.cs @@ -2,19 +2,29 @@ { using System; using System.Diagnostics; + using System.Diagnostics.Tracing; using Microsoft.ApplicationInsights.Common; using Microsoft.ApplicationInsights.Extensibility; using Microsoft.ApplicationInsights.Extensibility.Implementation; - internal sealed class AzureSdkDiagnosticListenerSubscriber : DiagnosticSourceListenerBase + internal sealed class AzureSdkDiagnosticListenerSubscriber : DiagnosticSourceListenerBase, IDisposable { public const string DiagnosticListenerName = "Azure."; + private readonly IDisposable logsListener; public AzureSdkDiagnosticListenerSubscriber(TelemetryConfiguration configuration) : base(configuration) { + // listen to Cosmos EventSource only - other logs can be sent using ILogger + this.logsListener = new AzureSdkEventListener(this.Client, EventLevel.Informational, "Azure.Cosmos"); this.Client.Context.GetInternalContext().SdkVersion = SdkVersionUtils.GetSdkVersion("rdd" + RddSource.DiagnosticSourceListenerAzure + ":"); } + public override void Dispose() + { + this.logsListener?.Dispose(); + base.Dispose(); + } + internal override bool IsSourceEnabled(DiagnosticListener diagnosticListener) { return diagnosticListener.Name.StartsWith(DiagnosticListenerName, StringComparison.Ordinal); diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs index 549ef16838..4923aec603 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkDiagnosticsEventHandler.cs @@ -15,6 +15,9 @@ internal class AzureSdkDiagnosticsEventHandler : DiagnosticsEventHandlerBase { + // Microsoft.DocumentDB is an Azure Resource Provider namespace. We use it as a dependency span as-is + // and portal will take care about visualizing it properly. + private const string CosmosDBResourceProviderNs = "Microsoft.DocumentDB"; #if NET452 private static readonly DateTimeOffset EpochStart = new DateTime(1970, 1, 1, 0, 0, 0, 0, System.DateTimeKind.Utc); #endif @@ -89,12 +92,19 @@ public override void OnEvent(KeyValuePair evnt, DiagnosticListen this.SetCommonProperties(evnt.Key, evnt.Value, currentActivity, telemetry); - if (telemetry is DependencyTelemetry dependency && dependency.Type == RemoteDependencyConstants.HTTP) + if (telemetry is DependencyTelemetry dependency) { - SetHttpProperties(currentActivity, dependency); - if (evnt.Value != null) + if (dependency.Type == RemoteDependencyConstants.HTTP) { - dependency.SetOperationDetail(evnt.Value.GetType().FullName, evnt.Value); + SetHttpProperties(currentActivity, dependency); + if (evnt.Value != null) + { + dependency.SetOperationDetail(evnt.Value.GetType().FullName, evnt.Value); + } + } + else if (dependency.Type == CosmosDBResourceProviderNs) + { + SetCosmosDbProperties(currentActivity, dependency); } } @@ -325,6 +335,64 @@ private static bool IsMessagingDependency(string dependencyType) dependencyType.EndsWith(RemoteDependencyConstants.AzureServiceBus, StringComparison.Ordinal)); } + private static void SetCosmosDbProperties(Activity activity, DependencyTelemetry telemetry) + { + string dbAccount = null; + string dbName = null; + string dbOperation = null; + string dbContainer = null; + + foreach (var tag in activity.Tags) + { + if (tag.Key == "db.name") + { + dbName = tag.Value; + } + else if (tag.Key == "db.operation") + { + dbOperation = tag.Value; + } + else if (tag.Key == "net.peer.name") + { + dbAccount = tag.Value; + } + else if (tag.Key == "db.cosmosdb.container") + { + dbContainer = tag.Value; + } + else if (tag.Key == "db.cosmosdb.status_code") + { + telemetry.ResultCode = tag.Value; + continue; + } + else if (!tag.Key.StartsWith("db.cosmosdb.", StringComparison.Ordinal)) + { + continue; + } + + telemetry.Properties[tag.Key] = tag.Value; + } + + // similar to SqlClientDiagnosticSourceListener + telemetry.Target = JoinNullable(dbAccount, dbName); + telemetry.Name = JoinNullable(dbContainer, dbOperation); + } + + private static string JoinNullable(string first, string second) + { + if (first == null) + { + return second ?? String.Empty; + } + + if (second == null) + { + return first; + } + + return String.Concat(first, " | ", second); + } + private static void SetMessagingProperties(Activity activity, OperationTelemetry telemetry) { string endpoint = null; diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkEventListener.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkEventListener.cs new file mode 100644 index 0000000000..a5495a4b2d --- /dev/null +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/AzureSdk/AzureSdkEventListener.cs @@ -0,0 +1,117 @@ +namespace Microsoft.ApplicationInsights.DependencyCollector.Implementation +{ + using System; + using System.Collections.Generic; + using System.Diagnostics.Tracing; + using System.Globalization; + using System.Linq; + using Microsoft.ApplicationInsights; + using Microsoft.ApplicationInsights.DataContracts; + + internal class AzureSdkEventListener : EventListener + { +#if NET452 + private static readonly object[] EmptyArray = new object[0]; +#else + private static readonly object[] EmptyArray = Array.Empty(); +#endif + + private readonly List eventSources = new List(); + private readonly TelemetryClient telemetryClient; + private readonly EventLevel level; + private readonly string prefix; + + public AzureSdkEventListener(TelemetryClient telemetryClient, EventLevel level, string prefix) + { + this.prefix = prefix ?? throw new ArgumentNullException(nameof(prefix)); + this.level = level; + this.telemetryClient = telemetryClient ?? throw new ArgumentNullException(nameof(telemetryClient)); + + foreach (EventSource eventSource in this.eventSources) + { + this.OnEventSourceCreated(eventSource); + } + + this.eventSources.Clear(); + } + + protected sealed override void OnEventSourceCreated(EventSource eventSource) + { + base.OnEventSourceCreated(eventSource); + + if (this.telemetryClient == null) + { + this.eventSources.Add(eventSource); + return; + } + + // EventSource names are deduplicated for environments like + // Functions where the same library can be loaded twice. + // Two EventSources with the same name are not allowed. + if (eventSource.Name != null && eventSource.Name.StartsWith(this.prefix, StringComparison.Ordinal)) + { + this.EnableEvents(eventSource, this.level); + } + } + + protected sealed override void OnEventWritten(EventWrittenEventArgs eventData) + { + // Workaround https://github.com/dotnet/corefx/issues/42600 + if (eventData.EventId == -1) + { + return; + } + + var payloadArray = eventData.Payload?.ToArray() ?? EmptyArray; + string message = string.Empty; + if (eventData.Message != null) + { + try + { + message = string.Format(CultureInfo.InvariantCulture, eventData.Message, payloadArray); + } + catch (FormatException) + { + } + } + else + { + message = String.Join(", ", payloadArray); + } + + var trace = new TraceTelemetry(message, FromEventLevel(eventData.Level)); + trace.Properties["CategoryName"] = eventData.EventSource.Name; + + if (eventData.EventId > 0) + { + trace.Properties["EventId"] = eventData.EventId.ToString(CultureInfo.InvariantCulture); + } + +#if !NET452 + if (!string.IsNullOrEmpty(eventData.EventName)) + { + trace.Properties["EventName"] = eventData.EventName; + } +#endif + this.telemetryClient?.TrackTrace(trace); + } + + private static SeverityLevel FromEventLevel(EventLevel level) + { + switch (level) + { + case EventLevel.Critical: + return SeverityLevel.Critical; + case EventLevel.Error: + return SeverityLevel.Error; + case EventLevel.Warning: + return SeverityLevel.Warning; + case EventLevel.Informational: + return SeverityLevel.Information; + case EventLevel.Verbose: + default: + return SeverityLevel.Verbose; + } + } + } +} diff --git a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/DiagnosticSourceListenerBase.cs b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/DiagnosticSourceListenerBase.cs index c032d09c62..30e7348db5 100644 --- a/WEB/Src/DependencyCollector/DependencyCollector/Implementation/DiagnosticSourceListenerBase.cs +++ b/WEB/Src/DependencyCollector/DependencyCollector/Implementation/DiagnosticSourceListenerBase.cs @@ -113,7 +113,7 @@ public void OnError(Exception error) { } - public void Dispose() + public virtual void Dispose() { this.Dispose(true); GC.SuppressFinalize(this);