From 6869453d3e515d9a0aa0921ffd4a7d674f32d143 Mon Sep 17 00:00:00 2001 From: stijnmoreels <9039753+stijnmoreels@users.noreply.github.com> Date: Tue, 2 Nov 2021 10:57:20 +0100 Subject: [PATCH 1/7] feat: add dependency ID to az key vault dependency tracking --- .../writing-different-telemetry-types.md | 13 ++ .../ContextProperties.cs | 1 + .../Extensions/ILoggerExtensions.cs | 82 +++++++- .../Logging/DependencyLogEntry.cs | 54 ++++- .../DependencyTelemetryConverter.cs | 7 +- .../ApplicationInsightsSinkTests.cs | 3 +- .../AzureKeyVaultDependencyTests.cs | 23 ++- .../Extensions/TestLoggerExtensions.cs | 133 +++++++++---- .../Telemetry/ILoggerExtensionsTests.cs | 186 ++++++++++++++++-- 9 files changed, 439 insertions(+), 63 deletions(-) diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index a4b6ab4c..f5752dc3 100644 --- a/docs/preview/02-Features/writing-different-telemetry-types.md +++ b/docs/preview/02-Features/writing-different-telemetry-types.md @@ -388,6 +388,19 @@ catch (Exception exception) } ``` +### Making it easier to link dependencies + +Service-to-service correlation requires linkage between tracked dependencies (outgoing) and requests (incoming). +Tracking any kind of dependency with the library has the possibility to provide an dependency ID. This ID will be needed later when the incoming request is tracked (dependency ID = request's parent ID). + +// TODO: provide example. + +```csharp +using Microsoft.Extensions.Logging; + +logger.Log +``` + ## Events Events allow you to report custom events which are a great way to track business-related events. diff --git a/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs b/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs index bedf1ec2..cae315a0 100644 --- a/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs +++ b/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs @@ -17,6 +17,7 @@ public static class Correlation public static class DependencyTracking { public const string DependencyLogEntry = "Dependency"; + public const string DependencyId = "DependencyId"; public const string DependencyType = "DependencyType"; public const string TargetName = "DependencyTargetName"; public const string DependencyName = "DependencyName"; diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs index 4aa47cc4..79e4d62f 100644 --- a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs +++ b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs @@ -493,7 +493,84 @@ public static void LogAzureKeyVaultDependency( "Requires the Azure Key Vault host to be in the right format, see https://docs.microsoft.com/en-us/azure/key-vault/general/about-keys-secrets-certificates#objects-identifiers-and-versioning"); context = context ?? new Dictionary(); - LogAzureKeyVaultDependency(logger, vaultUri, secretName, isSuccessful, measurement.StartTime, measurement.Elapsed, context); + LogAzureKeyVaultDependency(logger, vaultUri, secretName, isSuccessful, measurement, dependencyId: null, context); + } + + /// + /// Logs an Azure Key Vault dependency. + /// + /// The logger to use. + /// The URI pointing to the Azure Key Vault resource. + /// The secret that is being used within the Azure Key Vault resource. + /// Indication whether or not the operation was successful + /// Measuring the latency to call the dependency + /// The ID of the dependency to link as parent ID. + /// Context that provides more insights on the dependency that was measured + /// Thrown when the or is null. + /// Thrown when the or is blank. + /// Thrown when the is not in the correct format. + /// Thrown when the is not in the correct format. + public static void LogAzureKeyVaultDependency( + this ILogger logger, + string vaultUri, + string secretName, + bool isSuccessful, + DependencyMeasurement measurement, + string dependencyId, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to write the Azure Key Vault dependency"); + Guard.NotNullOrWhitespace(vaultUri, nameof(vaultUri), "Requires a non-blank URI for the Azure Key Vault"); + Guard.NotNullOrWhitespace(secretName, nameof(secretName), "Requires a non-blank secret name for the Azure Key Vault"); + Guard.NotNull(measurement, nameof(measurement), "Requires a dependency measurement instance to track the latency of the Azure Key Vault when tracking an Azure Key Vault dependency"); + Guard.For( + () => !SecretNameRegex.IsMatch(secretName), + "Requires a Azure Key Vault secret name in the correct format, see https://docs.microsoft.com/en-us/azure/key-vault/general/about-keys-secrets-certificates#objects-identifiers-and-versioning"); + Guard.For( + () => !KeyVaultUriRegex.IsMatch(vaultUri), + "Requires the Azure Key Vault host to be in the right format, see https://docs.microsoft.com/en-us/azure/key-vault/general/about-keys-secrets-certificates#objects-identifiers-and-versioning"); + + context = context ?? new Dictionary(); + LogAzureKeyVaultDependency(logger, vaultUri, secretName, isSuccessful, measurement.StartTime, measurement.Elapsed, dependencyId, context); + } + + /// + /// Logs an Azure Key Vault dependency. + /// + /// The logger to use. + /// The URI pointing to the Azure Key Vault resource. + /// The secret that is being used within the Azure Key Vault resource. + /// Indication whether or not the operation was successful + /// Point in time when the interaction with the HTTP dependency was started + /// Duration of the operation + /// Context that provides more insights on the dependency that was measured + /// Thrown when the is null. + /// Thrown when the or is blank. + /// Thrown when the is a negative time range. + /// Thrown when the is not in the correct format. + /// Thrown when the is not in the correct format. + public static void LogAzureKeyVaultDependency( + this ILogger logger, + string vaultUri, + string secretName, + bool isSuccessful, + DateTimeOffset startTime, + TimeSpan duration, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to write the Azure Key Vault dependency"); + Guard.NotNullOrWhitespace(vaultUri, nameof(vaultUri), "Requires a non-blank URI for the Azure Key Vault"); + Guard.NotNullOrWhitespace(secretName, nameof(secretName), "Requires a non-blank secret name for the Azure Key Vault"); + Guard.For( + () => !SecretNameRegex.IsMatch(secretName), + "Requires a Azure Key Vault secret name in the correct format, see https://docs.microsoft.com/en-us/azure/key-vault/general/about-keys-secrets-certificates#objects-identifiers-and-versioning"); + Guard.For( + () => !KeyVaultUriRegex.IsMatch(vaultUri), + "Requires the Azure Key Vault host to be in the right format, see https://docs.microsoft.com/en-us/azure/key-vault/general/about-keys-secrets-certificates#objects-identifiers-and-versioning"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the Azure Key Vault operation"); + + context = context ?? new Dictionary(); + LogAzureKeyVaultDependency(logger, vaultUri, secretName, isSuccessful, startTime, duration, dependencyId: null, context); } /// @@ -505,6 +582,7 @@ public static void LogAzureKeyVaultDependency( /// Indication whether or not the operation was successful /// Point in time when the interaction with the HTTP dependency was started /// Duration of the operation + /// The ID of the dependency to link as parent ID. /// Context that provides more insights on the dependency that was measured /// Thrown when the is null. /// Thrown when the or is blank. @@ -518,6 +596,7 @@ public static void LogAzureKeyVaultDependency( bool isSuccessful, DateTimeOffset startTime, TimeSpan duration, + string dependencyId, Dictionary context = null) { Guard.NotNull(logger, nameof(logger), "Requires an logger instance to write the Azure Key Vault dependency"); @@ -539,6 +618,7 @@ public static void LogAzureKeyVaultDependency( dependencyData: secretName, targetName: vaultUri, duration: duration, + dependencyId: dependencyId, startTime: startTime, resultCode: null, isSuccessful: isSuccessful, diff --git a/src/Arcus.Observability.Telemetry.Core/Logging/DependencyLogEntry.cs b/src/Arcus.Observability.Telemetry.Core/Logging/DependencyLogEntry.cs index 28b2879c..c500780f 100644 --- a/src/Arcus.Observability.Telemetry.Core/Logging/DependencyLogEntry.cs +++ b/src/Arcus.Observability.Telemetry.Core/Logging/DependencyLogEntry.cs @@ -52,6 +52,56 @@ public DependencyLogEntry( Context[ContextProperties.General.TelemetryType] = TelemetryType.Dependency; } + /// + /// Initializes a new instance of the class. + /// + /// The custom type of dependency. + /// The name of the dependency. + /// The custom data of dependency. + /// The name of dependency target. + /// The code of the result of the interaction with the dependency. + /// The indication whether or not the operation was successful. + /// The point in time when the interaction with the HTTP dependency was started. + /// The ID of the dependency to link as parent ID. + /// The duration of the operation. + /// The context that provides more insights on the dependency that was measured. + /// Thrown when the is null. + /// Thrown when the is blank. + /// Thrown when the is a negative time range. + public DependencyLogEntry( + string dependencyType, + string dependencyName, + object dependencyData, + string targetName, + string dependencyId, + TimeSpan duration, + DateTimeOffset startTime, + int? resultCode, + bool isSuccessful, + IDictionary context) + { + Guard.NotNullOrWhitespace(dependencyType, nameof(dependencyType), "Requires a non-blank custom dependency type when tracking the custom dependency"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the dependency operation"); + + DependencyId = dependencyId; + DependencyType = dependencyType; + DependencyName = dependencyName; + DependencyData = dependencyData; + TargetName = targetName; + ResultCode = resultCode; + IsSuccessful = isSuccessful; + + StartTime = startTime.ToString(FormatSpecifiers.InvariantTimestampFormat); + Duration = duration; + Context = context; + Context[ContextProperties.General.TelemetryType] = TelemetryType.Dependency; + } + + /// + /// Gets the ID of the dependency to link as parent ID. + /// + public string DependencyId { get; } + /// /// Gets the custom type of the dependency. /// @@ -104,8 +154,8 @@ public DependencyLogEntry( public override string ToString() { string contextFormatted = $"{{{String.Join("; ", Context.Select(item => $"[{item.Key}, {item.Value}]"))}}}"; - return $"{DependencyType} {DependencyName} {DependencyData} named {TargetName} in {Duration} at {StartTime} " + - $"(Successful: {IsSuccessful} - ResultCode: {ResultCode} - Context: {contextFormatted})"; + return $"{DependencyType} {DependencyName} {DependencyData} named {TargetName} with ID {DependencyId} in {Duration} at {StartTime} " + + $"(IsSuccessful: {IsSuccessful} - ResultCode: {ResultCode} - Context: {contextFormatted})"; } } } diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs index 7e339327..0999c4a7 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs @@ -34,12 +34,13 @@ protected override DependencyTelemetry CreateTelemetryEntry(LogEvent logEvent, I string resultCode = logEntry.Properties.GetAsRawString(nameof(DependencyLogEntry.ResultCode)); bool outcome = logEntry.Properties.GetAsBool(nameof(DependencyLogEntry.IsSuccessful)); IDictionary context = logEntry.Properties.GetAsDictionary(nameof(DependencyLogEntry.Context)); - + + string dependencyId = logEntry.Properties.GetAsRawString(ContextProperties.DependencyTracking.DependencyId); string operationId = logEvent.Properties.GetAsRawString(ContextProperties.Correlation.OperationId); - + var dependencyTelemetry = new DependencyTelemetry(dependencyType, target, dependencyName, data, startTime, duration, resultCode, success: outcome) { - Id = operationId + Id = dependencyId ?? operationId }; dependencyTelemetry.Properties.AddRange(context); diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs index 6fea5a71..92e8925b 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs @@ -21,7 +21,8 @@ namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsight public class ApplicationInsightsSinkTests : IntegrationTest { protected const string OnlyLastHourFilter = "timestamp gt now() sub duration'PT1H'"; - + protected const string PastHalfHourTimeSpan = "PT30M"; + private readonly ITestOutputHelper _outputWriter; private readonly InMemoryLogSink _memoryLogSink; private readonly string _instrumentationKey; diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureKeyVaultDependencyTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureKeyVaultDependencyTests.cs index f49bc0c9..20bfca72 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureKeyVaultDependencyTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureKeyVaultDependencyTests.cs @@ -29,6 +29,7 @@ public async Task LogAzureKeyVaultDependency_SinksToApplicationInsights_ResultsI string vaultUri = "https://myvault.vault.azure.net"; string secretName = "MySecret"; string dependencyName = vaultUri; + string dependencyId = Guid.NewGuid().ToString(); using (ILoggerFactory loggerFactory = CreateLoggerFactory()) { @@ -40,7 +41,7 @@ public async Task LogAzureKeyVaultDependency_SinksToApplicationInsights_ResultsI Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, startTime, duration, telemetryContext); + logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, startTime, duration, dependencyId, telemetryContext); } // Assert @@ -49,11 +50,12 @@ public async Task LogAzureKeyVaultDependency_SinksToApplicationInsights_ResultsI await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { EventsResults results = - await client.Events.GetDependencyEventsAsync(ApplicationId, timespan: "PT30M"); + await client.Events.GetDependencyEventsAsync(ApplicationId, PastHalfHourTimeSpan); Assert.NotEmpty(results.Value); Assert.Contains(results.Value, result => { return result.Dependency.Type == dependencyType + && result.Dependency.Id == dependencyId && result.Dependency.Target == vaultUri && result.Dependency.Data == secretName && result.Dependency.Name == dependencyName; @@ -61,20 +63,27 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => }); } - AssertX.Any(GetLogEventsFromMemory(), logEvent => { + AssertSerilogLogProperties(dependencyType, secretName, vaultUri, dependencyName); + } + + private void AssertSerilogLogProperties(string dependencyType, string secretName, string vaultUri, string dependencyName) + { + IEnumerable logEvents = GetLogEventsFromMemory(); + AssertX.Any(logEvents, logEvent => + { StructureValue logEntry = logEvent.Properties.GetAsStructureValue(ContextProperties.DependencyTracking.DependencyLogEntry); Assert.NotNull(logEntry); - var actualDependencyType = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyType)); + LogEventProperty actualDependencyType = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyType)); Assert.Equal(dependencyType, actualDependencyType.Value.ToDecentString()); - var actualDependencyData = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyData)); + LogEventProperty actualDependencyData = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyData)); Assert.Equal(secretName, actualDependencyData.Value.ToDecentString()); - var actualTargetName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.TargetName)); + LogEventProperty actualTargetName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.TargetName)); Assert.Equal(vaultUri, actualTargetName.Value.ToDecentString()); - var actualDependencyName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyName)); + LogEventProperty actualDependencyName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyName)); Assert.Equal(dependencyName, actualDependencyName.Value.ToDecentString()); Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.Context)); diff --git a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs index 7e166e6f..45b379a1 100644 --- a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs +++ b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs @@ -16,6 +16,52 @@ namespace Arcus.Observability.Tests.Unit /// public static class TestLoggerExtensions { + /// + /// Gets the written message to the as a strongly-typed Dependency. + /// + /// The test logger where a test message is written to. + /// + /// The strongly-typed Dependency containing the telemetry information. + /// + /// Thrown when the is null. + /// Thrown when no test message was written to the test . + public static DependencyLogEntry GetMessageAsDependency(this TestLogger logger) + { + Guard.NotNull(logger, nameof(logger), "Requires a test logger to retrieve the written log message"); + + if (logger.WrittenMessage is null) + { + throw new InvalidOperationException( + "Cannot parse the written message as a telemetry dependency because no log message was written to this test logger"); + } + + const string pattern = @"^(?[\w\s]+) (?[\w\.\/\/:]+) (?[\w\s\-]+) named (?[\w\s\.\/\/:]+) with ID (?[\w\s\-]*) in (?(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(IsSuccessful: (?(True|False)) - ResultCode: (?\d*) - Context: \{(?((\[\w+, \w+\])(; \[[\w\-]+, \w+\])*))\}\)$"; + Match match = Regex.Match(logger.WrittenMessage, pattern); + + string dependencyType = match.GetGroupValue("dependencytype"); + string dependencyName = match.GetGroupValue("dependencyname"); + string dependencyData = match.GetGroupValue("dependencydata"); + string targetName = match.GetGroupValue("targetname"); + string dependencyId = match.GetGroupValue("dependencyid"); + TimeSpan duration = match.GetGroupValueAsTimeSpan("duration"); + DateTimeOffset startTime = match.GetGroupValueAsDateTimeOffset("starttime"); + bool isSuccessful = match.GetGroupValueAsBool("issuccessful"); + int? resultCode = match.GetGroupValueAsNullableInt("resultcode"); + IDictionary context = match.GetGroupValueAsTelemetryContext("context", TelemetryType.Dependency); + + return new DependencyLogEntry( + dependencyType, + dependencyName, + dependencyData, + targetName, + dependencyId, + duration, + startTime, + resultCode, + isSuccessful, + context); + } + /// /// Gets the written message to the as a strongly-typed Metric. /// @@ -38,62 +84,83 @@ public static MetricLogEntry GetMessageAsMetric(this TestLogger logger) const string pattern = @"^(?[\w\s]+): (?(0.\d+)) at (?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(Context: \{(?((\[\w+, \w+\])(; \[\w+, \w+\])*))\}\)$"; Match match = Regex.Match(logger.WrittenMessage, pattern); - string metricName = GetMetricName(match); - double metricValue = GetMetricValue(match); - DateTimeOffset timestamp = GetTimestamp(match); - IDictionary context = GetTelemetryContext(match); + string metricName = match.GetGroupValue("metricname"); + double metricValue = match.GetGroupValueAsDouble("metricvalue"); + DateTimeOffset timestamp = match.GetGroupValueAsDateTimeOffset("timestamp"); + IDictionary context = match.GetGroupValueAsTelemetryContext("context", TelemetryType.Metrics); return new MetricLogEntry(metricName, metricValue, timestamp, context); } - private static string GetMetricName(Match match) + private static string GetGroupValue(this Match match, string name) { Assert.True( - match.Groups.TryGetValue("metricname", out Group metricNameGroup), - "Can't find metric name in logged message"); - Assert.NotNull(metricNameGroup); - - string metricName = Assert.Single(metricNameGroup.Captures).Value; - return metricName; + match.Groups.TryGetValue(name, out Group group), + $"Cannot find {name} in logged message"); + + string value = Assert.Single(@group.Captures).Value; + return value; } - private static double GetMetricValue(Match match) + private static double GetGroupValueAsDouble(this Match match, string name) { - Assert.True( - match.Groups.TryGetValue("metricvalue", out Group metricValueGroup), - "Can't find metric value in logged message"); - - Assert.NotNull(metricValueGroup); - string metricValueText = Assert.Single(metricValueGroup.Captures).Value; + string value = match.GetGroupValue(name); Assert.True( - double.TryParse(metricValueText, NumberStyles.AllowDecimalPoint, CultureInfo.InvariantCulture, out double metricValue), - "Can't parse metric value to double"); + double.TryParse(value, NumberStyles.AllowDecimalPoint, CultureInfo.InvariantCulture, out double metricValue), + $"Cannot parse {name} to double"); return metricValue; } - private static DateTimeOffset GetTimestamp(Match match) + private static TimeSpan GetGroupValueAsTimeSpan(this Match match, string name) { - Assert.True( - match.Groups.TryGetValue("timestamp", out Group timestampGroup), - "Can't timestamp in logged message"); + string value = match.GetGroupValue(name); - Assert.NotNull(timestampGroup); - string timestampText = Assert.Single(timestampGroup.Captures).Value; + Assert.True( + TimeSpan.TryParse(value, out TimeSpan span), + $"Cannot parse {name} to a time span"); + + return span; + } + + private static DateTimeOffset GetGroupValueAsDateTimeOffset(this Match match, string name) + { + string value = match.GetGroupValue(name); Assert.True( - DateTimeOffset.TryParse(timestampText, out DateTimeOffset timestamp), - "Can't parse timestamp to date time offset"); + DateTimeOffset.TryParse(value, out DateTimeOffset timestamp), + $"Cannot parse {name} to date time offset"); return timestamp; } - private static IDictionary GetTelemetryContext(Match match) + private static bool GetGroupValueAsBool(this Match match, string name) + { + string value = match.GetGroupValue(name); + + Assert.True( + bool.TryParse(value, out bool result), + $"Cannot parse {name} to boolean"); + + return result; + } + + private static int? GetGroupValueAsNullableInt(this Match match, string name) + { + string value = match.GetGroupValue(name); + + if (int.TryParse(value, out int result)) + { + return result; + } + + return null; + } + + private static IDictionary GetGroupValueAsTelemetryContext(this Match match, string name, TelemetryType telemetryType) { - Assert.True(match.Groups.TryGetValue("context", out Group contextGroup), "Can't find context in logged message"); - Assert.NotNull(contextGroup); - string contextText = Assert.Single(contextGroup.Captures).Value; + string contextText = match.GetGroupValue(name); char[] trailingChars = {'[', ']', ' '}; IDictionary context = @@ -106,7 +173,7 @@ private static IDictionary GetTelemetryContext(Match match) Assert.Single(context, item => { return item.Key == ContextProperties.General.TelemetryType - && item.Value.ToString() == TelemetryType.Metrics.ToString(); + && item.Value.ToString() == telemetryType.ToString(); }); context.Remove(ContextProperties.General.TelemetryType); diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/ILoggerExtensionsTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/ILoggerExtensionsTests.cs index 4bc55f8d..3aaf301b 100644 --- a/src/Arcus.Observability.Tests.Unit/Telemetry/ILoggerExtensionsTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/ILoggerExtensionsTests.cs @@ -546,6 +546,31 @@ public void LogDependencyTargetWithDependencyMeasurement_WithoutDependencyMeasur Assert.ThrowsAny(() => logger.LogDependency(dependencyType, dependencyData, targetName, isSuccessful, measurement: null)); } + [Theory] + [ClassData(typeof(ValidAzureKeyVaultSecretNames))] + public void LogAzureKeyVaultDependency_WithIdWithValidSecretName_Succeeds(string secretName) + { + // Arrange + var logger = new TestLogger(); + var vaultUri = "https://myvault.vault.azure.net"; + bool isSuccessful = _bogusGenerator.PickRandom(true, false); + DateTimeOffset startTime = _bogusGenerator.Date.RecentOffset(); + TimeSpan duration = _bogusGenerator.Date.Timespan(); + var id = Guid.NewGuid().ToString(); + + // Act + logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, startTime, duration, id); + + // Assert + DependencyLogEntry entry = logger.GetMessageAsDependency(); + Assert.Equal("Azure key vault", entry.DependencyType); + Assert.Equal(id, entry.DependencyId); + Assert.Equal(entry.DependencyName, vaultUri); + Assert.Equal(secretName, entry.DependencyData); + Assert.Equal(duration, entry.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.StartTime); + } + [Theory] [ClassData(typeof(ValidAzureKeyVaultSecretNames))] public void LogAzureKeyVaultDependency_WithValidSecretName_Succeeds(string secretName) @@ -561,14 +586,71 @@ public void LogAzureKeyVaultDependency_WithValidSecretName_Succeeds(string secre logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, startTime, duration); // Assert - string logMessage = logger.WrittenMessage; - Assert.Contains(TelemetryType.Dependency.ToString(), logMessage); - Assert.Contains(vaultUri, logMessage); - Assert.Contains(secretName, logMessage); - Assert.Contains(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), logMessage); - Assert.Contains(duration.ToString(), logMessage); - string dependencyName = vaultUri; - Assert.Contains("Azure key vault " + dependencyName, logMessage); + DependencyLogEntry entry = logger.GetMessageAsDependency(); + Assert.Equal("Azure key vault", entry.DependencyType); + Assert.Equal(entry.DependencyName, vaultUri); + Assert.Equal(secretName, entry.DependencyData); + Assert.Equal(duration, entry.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.StartTime); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogAzureKeyVaultDependency_WithIdWithoutVaultUri_Fails(string vaultUri) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogAzureKeyVaultDependency(vaultUri, "MySecret", isSuccessful: true, DateTimeOffset.UtcNow, TimeSpan.FromSeconds(5), "dependency ID")); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogAzureKeyVaultDependency_WithIdWithoutSecretName_Fails(string secretName) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", secretName, isSuccessful: true, startTime: DateTimeOffset.UtcNow, duration: TimeSpan.FromSeconds(5), "dependency ID")); + } + + [Theory] + [ClassData(typeof(InvalidAzureKeyVaultSecretNames))] + public void LogAzureKeyVaultDependency_WithIdWithInvalidSecretName_Fails(string secretName) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.Throws( + () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", secretName, isSuccessful: true, startTime: DateTimeOffset.UtcNow, duration: TimeSpan.FromSeconds(value: 5), "dependency ID")); + } + + [Fact] + public void LogAzureKeyVaultDependency_WithIdWithoutMatchingVaultUri_Fails() + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.Throws( + () => logger.LogAzureKeyVaultDependency("https://vault-without-vault.azure.net-suffix", "MySecret", isSuccessful: true, startTime: DateTimeOffset.UtcNow, duration: TimeSpan.FromSeconds(5), "dependency ID")); + } + + [Fact] + public void LogAzureKeyVaultDependency_WithIdWithNegativeDuration_Fails() + { + // Arrange + var logger = new TestLogger(); + TimeSpan duration = GeneratePositiveDuration().Negate(); + + // Act / Assert + Assert.Throws( + () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", "MySecret", isSuccessful: true, startTime: DateTimeOffset.UtcNow, duration, "dependency ID")); } [Theory] @@ -629,6 +711,33 @@ public void LogAzureKeyVaultDependency_WithNegativeDuration_Fails() Assert.Throws( () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", "MySecret", isSuccessful: true, startTime: DateTimeOffset.UtcNow, duration: duration)); } + + [Theory] + [ClassData(typeof(ValidAzureKeyVaultSecretNames))] + public void LogAzureKeyVaultDependency_WithIdWithValidSecretNameDependencyMeasurement_Succeeds(string secretName) + { + // Arrange + var logger = new TestLogger(); + var vaultUri = "https://myvault.vault.azure.net"; + bool isSuccessful = _bogusGenerator.PickRandom(true, false); + DependencyMeasurement measurement = DependencyMeasurement.Start(); + DateTimeOffset startTime = measurement.StartTime; + measurement.Dispose(); + TimeSpan duration = measurement.Elapsed; + var id = Guid.NewGuid().ToString(); + + // Act + logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, measurement, id); + + // Assert + DependencyLogEntry entry = logger.GetMessageAsDependency(); + Assert.Equal("Azure key vault", entry.DependencyType); + Assert.Equal(id, entry.DependencyId); + Assert.Equal(entry.DependencyName, vaultUri); + Assert.Equal(secretName, entry.DependencyData); + Assert.Equal(duration, entry.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.StartTime); + } [Theory] [ClassData(typeof(ValidAzureKeyVaultSecretNames))] @@ -647,14 +756,59 @@ public void LogAzureKeyVaultDependency_WithValidSecretNameDependencyMeasurement_ logger.LogAzureKeyVaultDependency(vaultUri, secretName, isSuccessful, measurement); // Assert - string logMessage = logger.WrittenMessage; - Assert.Contains(TelemetryType.Dependency.ToString(), logMessage); - Assert.Contains(vaultUri, logMessage); - Assert.Contains(secretName, logMessage); - Assert.Contains(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), logMessage); - Assert.Contains(duration.ToString(), logMessage); - string dependencyName = vaultUri; - Assert.Contains("Azure key vault " + dependencyName, logMessage); + DependencyLogEntry entry = logger.GetMessageAsDependency(); + Assert.Equal("Azure key vault", entry.DependencyType); + Assert.Equal(entry.DependencyName, vaultUri); + Assert.Equal(secretName, entry.DependencyData); + Assert.Equal(duration, entry.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.StartTime); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogAzureKeyVaultDependencyDependencyMeasurement_WithIdWithoutVaultUri_Fails(string vaultUri) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogAzureKeyVaultDependency(vaultUri, "MySecret", isSuccessful: true, measurement: DependencyMeasurement.Start(), "dependency ID")); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogAzureKeyVaultDependency_WithIdWithoutSecretNameDependencyMeasurement_Fails(string secretName) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", secretName, isSuccessful: true, measurement: DependencyMeasurement.Start(), "dependency ID")); + } + + [Theory] + [ClassData(typeof(InvalidAzureKeyVaultSecretNames))] + public void LogAzureKeyVaultDependency_WithIdWithInvalidSecretNameDependencyMeasurement_Fails(string secretName) + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.Throws( + () => logger.LogAzureKeyVaultDependency("https://my-vault.vault.azure.net", secretName, isSuccessful: true, measurement: DependencyMeasurement.Start(), "dependency ID")); + } + + [Fact] + public void LogAzureKeyVaultDependencyDependencyMeasurement_WithIdWithoutMatchingVaultUri_Fails() + { + // Arrange + var logger = new TestLogger(); + + // Act / Assert + Assert.Throws( + () => logger.LogAzureKeyVaultDependency("https://vault-without-vault.azure.net-suffix", "MySecret", isSuccessful: true, measurement: DependencyMeasurement.Start(), "dependency ID")); } [Theory] From ad529ef708674d58972d92aab6cb5dd5be20266a Mon Sep 17 00:00:00 2001 From: stijnmoreels <9039753+stijnmoreels@users.noreply.github.com> Date: Tue, 14 Dec 2021 09:31:06 +0100 Subject: [PATCH 2/7] pr-docs: complete missing dependency ID tracking feature docs --- .../writing-different-telemetry-types.md | 25 +++++++++++++++---- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index f5752dc3..11a05ffb 100644 --- a/docs/preview/02-Features/writing-different-telemetry-types.md +++ b/docs/preview/02-Features/writing-different-telemetry-types.md @@ -42,11 +42,12 @@ We provide support for the following dependencies: - [Azure Search](#measuring-azure-search-dependencies) - [Azure Service Bus](#measuring-azure-service-bus-dependencies) - [Azure Table Storage](#measuring-azure-table-storage-dependencies) -- [Custom](#measuring-custom-dependencies) - [HTTP](#measuring-http-dependencies) - [SQL](#measuring-sql-dependencies) +- [Custom](#measuring-custom-dependencies) Since measuring dependencies can add some noise in your code, we've introduced `DependencyMeasurement` to make it simpler. ([docs](#making-it-easier-to-measure-dependencies)) +Linking service-to-service correlation can be hard, this can be made easier with including dependency ID's. ([docs](#making-it-easier-to-link-services)) ### Measuring Azure Blob Storage dependencies @@ -388,17 +389,31 @@ catch (Exception exception) } ``` -### Making it easier to link dependencies +### Making it easier to link services Service-to-service correlation requires linkage between tracked dependencies (outgoing) and requests (incoming). Tracking any kind of dependency with the library has the possibility to provide an dependency ID. This ID will be needed later when the incoming request is tracked (dependency ID = request's parent ID). -// TODO: provide example. +Tracking the outgoing dependency: ```csharp -using Microsoft.Extensions.Logging; +var durationMeasurement = new StopWatch(); + +// Start measuring +durationMeasurement.Start(); +var startTime = DateTimeOffset.UtcNow; + +var trackingId = "75D298F7-99FF-4BB8-8019-230974EB6D1E"; + +logger.AzureKeyVaultDependency( + vaultUri: "https://my-secret-store.vault.azure.net", + secretName: "ServiceBus-ConnectionString", + isSuccessful: true, + startTime: startTime, + duration: durationMeasurement.Elapsed, + dependencyId: trackingId); -logger.Log +// Output: {"DependencyType": "Azure key vault", "DependencyId": "75D298F7-99FF-4BB8-8019-230974EB6D1E", "DependencyData": "ServiceBus-ConnectionString", "TargetName": "https://my-secret-store.vault.azure.net", "Duration": "00:00:00.2521801", "StartTime": "03/23/2020 09:56:31 +00:00", "IsSuccessful": true, "Context": {}} ``` ## Events From 42a0091b3996ec5611f18c5cd20f4d234db1c8f1 Mon Sep 17 00:00:00 2001 From: stijnmoreels <9039753+stijnmoreels@users.noreply.github.com> Date: Wed, 15 Dec 2021 13:24:38 +0100 Subject: [PATCH 3/7] pr-fix: remove operation ID assignment in ai dependency tracking converter --- .../Converters/DependencyTelemetryConverter.cs | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs index 0999c4a7..d9fc5473 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs @@ -25,6 +25,7 @@ protected override DependencyTelemetry CreateTelemetryEntry(LogEvent logEvent, I Guard.NotNull(logEvent.Properties, nameof(logEvent), "Requires a Serilog event with a set of properties to create an Azure Application Insights Dependency telemetry instance"); StructureValue logEntry = logEvent.Properties.GetAsStructureValue(ContextProperties.DependencyTracking.DependencyLogEntry); + string dependencyId = logEntry.Properties.GetAsRawString(nameof(DependencyLogEntry.DependencyId)); string dependencyType = logEntry.Properties.GetAsRawString(nameof(DependencyLogEntry.DependencyType)); string dependencyName = logEntry.Properties.GetAsRawString(nameof(DependencyLogEntry.DependencyName)); string target = logEntry.Properties.GetAsRawString(nameof(DependencyLogEntry.TargetName)); @@ -35,12 +36,9 @@ protected override DependencyTelemetry CreateTelemetryEntry(LogEvent logEvent, I bool outcome = logEntry.Properties.GetAsBool(nameof(DependencyLogEntry.IsSuccessful)); IDictionary context = logEntry.Properties.GetAsDictionary(nameof(DependencyLogEntry.Context)); - string dependencyId = logEntry.Properties.GetAsRawString(ContextProperties.DependencyTracking.DependencyId); - string operationId = logEvent.Properties.GetAsRawString(ContextProperties.Correlation.OperationId); - var dependencyTelemetry = new DependencyTelemetry(dependencyType, target, dependencyName, data, startTime, duration, resultCode, success: outcome) { - Id = dependencyId ?? operationId + Id = dependencyId }; dependencyTelemetry.Properties.AddRange(context); From edd3e79c22fcdf6e08f8b7f9eeb78f1fef47930a Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Mon, 20 Dec 2021 08:54:06 +0100 Subject: [PATCH 4/7] Update docs/preview/02-Features/writing-different-telemetry-types.md Co-authored-by: Frederik Gheysels --- docs/preview/02-Features/writing-different-telemetry-types.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index 11a05ffb..16e93afc 100644 --- a/docs/preview/02-Features/writing-different-telemetry-types.md +++ b/docs/preview/02-Features/writing-different-telemetry-types.md @@ -392,7 +392,7 @@ catch (Exception exception) ### Making it easier to link services Service-to-service correlation requires linkage between tracked dependencies (outgoing) and requests (incoming). -Tracking any kind of dependency with the library has the possibility to provide an dependency ID. This ID will be needed later when the incoming request is tracked (dependency ID = request's parent ID). +Tracking any kind of dependency with the library has the possibility to provide a dependency ID. This dependency ID will be needed later when the incoming request is tracked (dependency ID = request's parent ID). Tracking the outgoing dependency: From 66cc9fa3695597509c9dd7889ae899d1367e7618 Mon Sep 17 00:00:00 2001 From: stijnmoreels <9039753+stijnmoreels@users.noreply.github.com> Date: Fri, 7 Jan 2022 08:19:40 +0100 Subject: [PATCH 5/7] pr-fix: update with more clear explanation of the request tracking --- .../preview/02-Features/writing-different-telemetry-types.md | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index 11a05ffb..980c7328 100644 --- a/docs/preview/02-Features/writing-different-telemetry-types.md +++ b/docs/preview/02-Features/writing-different-telemetry-types.md @@ -392,7 +392,10 @@ catch (Exception exception) ### Making it easier to link services Service-to-service correlation requires linkage between tracked dependencies (outgoing) and requests (incoming). -Tracking any kind of dependency with the library has the possibility to provide an dependency ID. This ID will be needed later when the incoming request is tracked (dependency ID = request's parent ID). +Tracking any kind of dependency with the library has the possibility to provide an dependency ID. + +To link the request (incoming) with the dependency (outgoing), the request needs to include this dependency ID in its tracking (dependency ID = request's parent ID) so that we now which dependency triggered the request. +For more information, see how to do this in a [Web API]() and [Azure Service Bus]() context. Tracking the outgoing dependency: From 3ef9c2f8485080bc094f49ef0a221a87bf0a238c Mon Sep 17 00:00:00 2001 From: stijnmoreels <9039753+stijnmoreels@users.noreply.github.com> Date: Fri, 7 Jan 2022 08:43:59 +0100 Subject: [PATCH 6/7] pr-fix: update with serialized json in unit tests --- .../ApplicationInsightsTelemetryConverterTests.cs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs index d1ac81da..a033e32e 100644 --- a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs @@ -93,10 +93,13 @@ public void LogRequestMessage_WithRequestAndResponseWithCustomId_CreatesRequestT ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var request = new HttpRequestMessage(System.Net.Http.HttpMethod.Get, new Uri("https://" + "localhost" + "/api/v1/health")); var statusCode = HttpStatusCode.OK; @@ -192,10 +195,13 @@ public void LogRequestMessage_WithRequestAndResponseStatusCodeWithCustomId_Creat ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var request = new HttpRequestMessage(System.Net.Http.HttpMethod.Get, new Uri("https://" + "localhost" + "/api/v1/health")); var statusCode = HttpStatusCode.OK; @@ -291,10 +297,13 @@ public void LogRequest_WithRequestAndResponseWithCustomId_CreatesRequestTelemetr ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var statusCode = HttpStatusCode.OK; HttpRequest request = CreateStubRequest(HttpMethod.Get, "https", "localhost", "/api/v1/health"); @@ -390,10 +399,13 @@ public void LogRequest_WithRequestAndResponseStatusCodeWithCustomId_CreatesReque ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var statusCode = (int) HttpStatusCode.OK; HttpRequest request = CreateStubRequest(HttpMethod.Get, "https", "localhost", "/api/v1/health"); From 2f13d09162c031ba17af41808d02f56ae2b7adf1 Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Fri, 7 Jan 2022 09:06:43 +0100 Subject: [PATCH 7/7] Update writing-different-telemetry-types.md --- docs/preview/02-Features/writing-different-telemetry-types.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index 980c7328..4f4bbac0 100644 --- a/docs/preview/02-Features/writing-different-telemetry-types.md +++ b/docs/preview/02-Features/writing-different-telemetry-types.md @@ -395,7 +395,7 @@ Service-to-service correlation requires linkage between tracked dependencies (ou Tracking any kind of dependency with the library has the possibility to provide an dependency ID. To link the request (incoming) with the dependency (outgoing), the request needs to include this dependency ID in its tracking (dependency ID = request's parent ID) so that we now which dependency triggered the request. -For more information, see how to do this in a [Web API]() and [Azure Service Bus]() context. +For more information, see how to do this in a Web API and Azure Service Bus context. Tracking the outgoing dependency: