diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md index a4b6ab4c..4f4bbac0 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,6 +389,36 @@ 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. + +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: + +```csharp +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); + +// 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 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..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)); @@ -34,12 +35,10 @@ 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 operationId = logEvent.Properties.GetAsRawString(ContextProperties.Correlation.OperationId); - + var dependencyTelemetry = new DependencyTelemetry(dependencyType, target, dependencyName, data, startTime, duration, resultCode, success: outcome) { - Id = operationId + Id = dependencyId }; 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 43879d88..54e78d27 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/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"); 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]