From 68bd4593991d6b974c4d7c6881c34da3faa924c2 Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Thu, 25 Aug 2022 11:40:09 +0200 Subject: [PATCH] feat: track custom request (#447) --- .../writing-different-telemetry-types.md | 32 +++ .../ContextProperties.cs | 4 +- .../ILoggerEventHubsRequestExtensions.cs | 16 +- .../ILoggerGeneralRequestExtensions.cs | 129 ++++++++++ .../Logging/RequestLogEntry.cs | 67 +++++ .../Logging/RequestSourceSystem.cs | 7 +- .../Converters/RequestTelemetryConverter.cs | 10 +- .../ApplicationInsights/CustomRequestTests.cs | 53 ++++ .../EventHubsRequestTests.cs | 3 +- .../Extensions/TestLoggerExtensions.cs | 10 +- .../Logging/CustomRequestLoggingTests.cs | 243 ++++++++++++++++++ .../Logging/EventHubsRequestLoggingTests.cs | 16 +- 12 files changed, 569 insertions(+), 21 deletions(-) create mode 100644 src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerGeneralRequestExtensions.cs create mode 100644 src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/CustomRequestTests.cs create mode 100644 src/Arcus.Observability.Tests.Unit/Telemetry/Logging/CustomRequestLoggingTests.cs diff --git a/docs/preview/03-Features/writing-different-telemetry-types.md b/docs/preview/03-Features/writing-different-telemetry-types.md index 476021f8..a749312e 100644 --- a/docs/preview/03-Features/writing-different-telemetry-types.md +++ b/docs/preview/03-Features/writing-different-telemetry-types.md @@ -593,6 +593,38 @@ using (var measurement = DurationMeasurement.Start()) > 💡 Note that [Arcus Web API request tracking middleware](https://webapi.arcus-azure.net/features/logging#logging-incoming-requests) can already do this for you in a ASP.NET Core application +### Incoming custom requests +Requests allow you to keep track of incoming messages. We provide an extension to track type of requests that aren't out-of-the-box so you can track your custom systems. + +Here is how you can log a custom request on an event that's being processed: + +```csharp +using Microsoft.Extensions.Logging; + +bool isSuccessful = false; + +// Start measuring. +using (var measurement = DurationMeasurement.Start()) +{ + try + { + // Processing message. + + // End processing. + + isSuccessful = true; + } + finally + { + logger.LogCustomRequest("", "", isSuccessful, measurement); + // Output: Custom from Process completed in 0.00:12:20.8290760 at 2021-10-26T05:36:03.6067975 +02:00 - (IsSuccessful: True, Context: {[TelemetryType, Request]}) + } +} +``` + +The `` will reflect the `Source` in Application Insights telemetry. This is set automatically in our HTTP, Azure Service Bus, Azure EventHubs, etc. requests but is configurable when you track custom requests. +We provide overloads to configure the functional operation name (default: `Process`). + ## Traces & Exceptions Application Insights telemetry traces and exceptions are log messages not directly linked by an incoming request, outgoing dependency, or metric. These traces are also linked with correlation and are therefore part of the whole application component in Application Insights. diff --git a/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs b/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs index c69a440f..cd9ae065 100644 --- a/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs +++ b/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs @@ -66,7 +66,9 @@ public static class RequestTracking public const string ResponseStatusCode = "ResponseStatusCode"; public const string RequestDuration = "RequestDuration"; public const string RequestTime = "RequestTime"; - + + public const string DefaultOperationName = "Process"; + public static class ServiceBus { public const string Endpoint = "ServiceBus-Endpoint"; diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerEventHubsRequestExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerEventHubsRequestExtensions.cs index e8aafa43..a83080f6 100644 --- a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerEventHubsRequestExtensions.cs +++ b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerEventHubsRequestExtensions.cs @@ -37,7 +37,7 @@ public static void LogEventHubsRequest( Guard.NotNullOrWhitespace(eventHubsName, nameof(eventHubsName), "Requires an Azure EventHubs name to track the request"); Guard.NotNull(measurement, nameof(measurement), "Requires an instance to measure the Azure EventHubs request process latency duration"); - LogEventHubsRequest(logger, eventHubsNamespace, eventHubsName, isSuccessful, measurement.Elapsed, measurement.StartTime, context); + LogEventHubsRequest(logger, eventHubsNamespace, eventHubsName, isSuccessful, measurement.StartTime, measurement.Elapsed, context); } /// @@ -47,18 +47,19 @@ public static void LogEventHubsRequest( /// The namespace in which the Azure EventHUbs is located. /// The name of the Event Hub that the processor is connected to, specific to the EventHubs namespace that contains it. /// The indication whether or not the Azure EventHubs request was successfully processed. - /// The duration it took to process the Azure EventHubs request. /// The time when the request was received. + /// The duration it took to process the Azure EventHubs request. /// The telemetry context that provides more insights on the Azure EventHubs request. /// Thrown when the is null. /// Thrown when the , is blank. + /// Thrown when the is a negative time range. public static void LogEventHubsRequest( this ILogger logger, string eventHubsNamespace, string eventHubsName, bool isSuccessful, - TimeSpan duration, DateTimeOffset startTime, + TimeSpan duration, Dictionary context = null) { Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); @@ -66,7 +67,7 @@ public static void LogEventHubsRequest( Guard.NotNullOrWhitespace(eventHubsName, nameof(eventHubsName), "Requires an Azure EventHubs name to track the request"); Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the Azure EventHubs request operation"); - LogEventHubsRequest(logger, eventHubsNamespace, "$Default", eventHubsName, operationName: null, isSuccessful, duration, startTime, context); + LogEventHubsRequest(logger, eventHubsNamespace, "$Default", eventHubsName, operationName: null, isSuccessful: isSuccessful, startTime: startTime, duration: duration, context: context); } /// @@ -100,7 +101,7 @@ public static void LogEventHubsRequest( Guard.NotNullOrWhitespace(eventHubsName, nameof(eventHubsName), "Requires an Azure EventHubs name to track the request"); Guard.NotNull(measurement, nameof(measurement), "Requires an instance to measure the Azure EventHubs request process latency duration"); - LogEventHubsRequest(logger, eventHubsNamespace, consumerGroup, eventHubsName, operationName, isSuccessful, measurement.Elapsed, measurement.StartTime, context); + LogEventHubsRequest(logger, eventHubsNamespace, consumerGroup, eventHubsName, operationName, isSuccessful, measurement.StartTime, measurement.Elapsed, context); } /// @@ -112,13 +113,14 @@ public static void LogEventHubsRequest( /// The name of the Event Hub that the processor is connected to, specific to the EventHubs namespace that contains it. /// The optional logical name that can be used to identify the operation that consumes the message. /// The indication whether or not the Azure EventHubs request was successfully processed. - /// The duration it took to process the Azure EventHubs request. /// The time when the request was received. + /// The duration it took to process the Azure EventHubs request. /// The telemetry context that provides more insights on the Azure EventHubs request. /// Thrown when the is null. /// /// Thrown when the , , is blank. /// + /// Thrown when the is a negative time range. public static void LogEventHubsRequest( this ILogger logger, string eventHubsNamespace, @@ -126,8 +128,8 @@ public static void LogEventHubsRequest( string eventHubsName, string operationName, bool isSuccessful, - TimeSpan duration, DateTimeOffset startTime, + TimeSpan duration, Dictionary context = null) { Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerGeneralRequestExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerGeneralRequestExtensions.cs new file mode 100644 index 00000000..dd64fc23 --- /dev/null +++ b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerGeneralRequestExtensions.cs @@ -0,0 +1,129 @@ +using System; +using System.Collections.Generic; +using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; +using GuardNet; + +// ReSharper disable once CheckNamespace +namespace Microsoft.Extensions.Logging +{ + /// + /// Telemetry extensions on the instance to write Application Insights compatible log messages. + /// + // ReSharper disable once InconsistentNaming + public static partial class ILoggerExtensions + { + /// + /// Logs a custom request. + /// + /// The logger instance to track the telemetry. + /// The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus). + /// The indication whether or not the custom request was successfully processed. + /// The instance to measure the duration of the custom request. + /// The telemetry context that provides more insights on the custom request. + /// Thrown when the or the is null. + /// Thrown when the is blank. + public static void LogCustomRequest( + this ILogger logger, + string requestSource, + bool isSuccessful, + DurationMeasurement measurement, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); + Guard.NotNullOrWhitespace(requestSource, nameof(requestSource), "Requires a non-blank request source to identify the caller"); + Guard.NotNull(measurement, nameof(measurement), "Requires an instance to measure the custom request process latency duration"); + + LogCustomRequest(logger, requestSource, isSuccessful, measurement.StartTime, measurement.Elapsed, context); + } + + /// + /// Logs a custom request. + /// + /// The logger instance to track the telemetry. + /// The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus). + /// The indication whether or not the custom request was successfully processed. + /// The time when the request was received. + /// The duration it took to process the custom request. + /// The telemetry context that provides more insights on the custom request. + /// Thrown when the is null. + /// Thrown when the is blank. + /// Thrown when the is a negative time range. + public static void LogCustomRequest( + this ILogger logger, + string requestSource, + bool isSuccessful, + DateTimeOffset startTime, + TimeSpan duration, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); + Guard.NotNullOrWhitespace(requestSource, nameof(requestSource), "Requires a non-blank request source to identify the caller"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the custom request operation"); + + LogCustomRequest(logger, requestSource, operationName: null, isSuccessful, startTime, duration, context); + } + + /// + /// Logs a custom request. + /// + /// The logger instance to track the telemetry. + /// The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus). + /// The optional logical name that can be used to identify the operation that consumes the message. + /// The indication whether or not the custom request was successfully processed. + /// The instance to measure the duration of the custom request. + /// The telemetry context that provides more insights on the custom request. + /// Thrown when the or the is null. + /// Thrown when the is blank. + public static void LogCustomRequest( + this ILogger logger, + string requestSource, + string operationName, + bool isSuccessful, + DurationMeasurement measurement, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); + Guard.NotNullOrWhitespace(requestSource, nameof(requestSource), "Requires a non-blank request source to identify the caller"); + Guard.NotNull(measurement, nameof(measurement), "Requires an instance to measure the custom request process latency duration"); + + LogCustomRequest(logger, requestSource, operationName, isSuccessful, measurement.StartTime, measurement.Elapsed, context); + } + + /// + /// Logs a custom request. + /// + /// The logger instance to track the telemetry. + /// The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus). + /// The optional logical name that can be used to identify the operation that consumes the message. + /// The indication whether or not the custom request was successfully processed. + /// The time when the request was received. + /// The duration it took to process the custom request. + /// The telemetry context that provides more insights on the custom request. + /// Thrown when the is null. + /// Thrown when the is blank. + /// Thrown when the is a negative time range. + public static void LogCustomRequest( + this ILogger logger, + string requestSource, + string operationName, + bool isSuccessful, + DateTimeOffset startTime, + TimeSpan duration, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry"); + Guard.NotNullOrWhitespace(requestSource, nameof(requestSource), "Requires a non-blank request source to identify the caller"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the custom request operation"); + + if (string.IsNullOrWhiteSpace(operationName)) + { + operationName = ContextProperties.RequestTracking.DefaultOperationName; + } + + context = context ?? new Dictionary(); + + logger.LogWarning(MessageFormats.RequestFormat, RequestLogEntry.CreateForCustomRequest(requestSource, operationName, isSuccessful, duration, startTime, context)); + } + } +} diff --git a/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs b/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs index 77ae4c89..fcca95d8 100644 --- a/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs +++ b/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs @@ -81,6 +81,21 @@ public RequestLogEntry( Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation"); } + private RequestLogEntry( + string method, + string host, + string uri, + string operationName, + int statusCode, + string customRequestSource, + string requestTime, + TimeSpan duration, + IDictionary context) + : this(method, host, uri, operationName, statusCode, RequestSourceSystem.Custom, requestTime, duration, context) + { + CustomRequestSource = customRequestSource; + } + private RequestLogEntry( string method, string host, @@ -190,6 +205,7 @@ public static RequestLogEntry CreateForEventHubs( DateTimeOffset startTime, IDictionary context) { + Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires a non-blank operation name"); Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation"); return CreateWithoutHttpRequest(RequestSourceSystem.AzureEventHubs, operationName, isSuccessful, duration, startTime, context); @@ -215,6 +231,51 @@ private static RequestLogEntry CreateWithoutHttpRequest( context: context); } + /// + /// Creates an instance for custom requests. + /// + /// The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus). + /// The name of the operation of the request. + /// The indication whether or not the custom request was successfully processed. + /// The duration it took to process the custom request. + /// The time when the request was received. + /// The telemetry context that provides more insights on the custom request. + /// Thrown when the is a negative time range. + public static RequestLogEntry CreateForCustomRequest( + string requestSource, + string operationName, + bool isSuccessful, + TimeSpan duration, + DateTimeOffset startTime, + IDictionary context) + { + Guard.NotNullOrWhitespace(requestSource, nameof(requestSource), "Requires a non-blank request source to identify the caller"); + Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires a non-blank operation name"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request duration"); + + return CreateWithoutHttpRequest(requestSource, operationName, isSuccessful, duration, startTime, context); + } + + private static RequestLogEntry CreateWithoutHttpRequest( + string requestSource, + string operationName, + bool isSuccessful, + TimeSpan duration, + DateTimeOffset startTime, + IDictionary context) + { + return new RequestLogEntry( + method: "", + host: "", + uri: "", + operationName: operationName, + statusCode: isSuccessful ? 200 : 500, + customRequestSource: requestSource, + requestTime: startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), + duration: duration, + context: context); + } + /// /// Gets the HTTP method of the request. /// @@ -250,6 +311,11 @@ private static RequestLogEntry CreateWithoutHttpRequest( /// public RequestSourceSystem SourceSystem { get; set; } + /// + /// Gets the custom request source if the is . + /// + public string CustomRequestSource { get; } + /// /// Gets the name of the operation of the source system from where the request came from. /// @@ -285,6 +351,7 @@ private string DetermineSource() { case RequestSourceSystem.AzureServiceBus: return "Azure Service Bus"; case RequestSourceSystem.AzureEventHubs: return "Azure EventHubs"; + case RequestSourceSystem.Custom: return "Custom " + CustomRequestSource; default: throw new ArgumentOutOfRangeException(nameof(SourceSystem), "Cannot determine request source as it represents something outside the bounds of the enumeration"); } diff --git a/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs b/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs index 153678b5..63054511 100644 --- a/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs +++ b/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs @@ -18,6 +18,11 @@ public enum RequestSourceSystem /// /// Specifies that the request-source is an Azure EventHubs. /// - AzureEventHubs = 4 + AzureEventHubs = 4, + + /// + /// Specifies that the request-source is a custom system. + /// + Custom = 8 } } \ No newline at end of file diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs index f1e2f948..8e1ca8e8 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs @@ -67,11 +67,12 @@ protected override RequestTelemetry CreateTelemetryEntry(LogEvent logEvent, IFor DateTimeOffset requestTime = logEntry.Properties.GetAsDateTimeOffset(nameof(RequestLogEntry.RequestTime)); IDictionary context = logEntry.Properties.GetAsDictionary(nameof(RequestLogEntry.Context)); var sourceSystem = logEntry.Properties.GetAsObject(nameof(RequestLogEntry.SourceSystem)); + string customRequestSource = logEntry.Properties.GetAsRawString(nameof(RequestLogEntry.CustomRequestSource)); string sourceName = DetermineSourceName(sourceSystem, requestMethod, requestUri, operationName); bool isSuccessfulRequest = DetermineRequestOutcome(responseStatusCode); Uri url = DetermineUrl(sourceSystem, requestHost, requestUri); - string source = DetermineRequestSource(sourceSystem, context); + string source = DetermineRequestSource(sourceSystem, customRequestSource, context); string requestOperationName = DetermineRequestOperationName(sourceSystem, requestMethod, operationName); var requestTelemetry = new RequestTelemetry(sourceName, requestTime, requestDuration, responseStatusCode, isSuccessfulRequest) @@ -112,7 +113,7 @@ private static Uri DetermineUrl(RequestSourceSystem sourceSystem, string request return null; } - private static string DetermineRequestSource(RequestSourceSystem sourceSystem, IDictionary context) + private static string DetermineRequestSource(RequestSourceSystem sourceSystem, string customRequestSource, IDictionary context) { if (sourceSystem is RequestSourceSystem.AzureServiceBus) { @@ -130,6 +131,11 @@ private static string DetermineRequestSource(RequestSourceSystem sourceSystem, I return $"{namespaceEndpoint}.servicebus.windows.net/{name}"; } + if (sourceSystem is RequestSourceSystem.Custom) + { + return customRequestSource; + } + return null; } diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/CustomRequestTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/CustomRequestTests.cs new file mode 100644 index 00000000..36ff9f76 --- /dev/null +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/CustomRequestTests.cs @@ -0,0 +1,53 @@ +using System; +using System.Collections.Generic; +using System.Threading.Tasks; +using Microsoft.Azure.ApplicationInsights.Query.Models; +using Microsoft.Extensions.Logging; +using Serilog; +using Xunit; +using Xunit.Abstractions; + +namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights +{ + public class CustomRequestTests : ApplicationInsightsSinkTests + { + public CustomRequestTests(ITestOutputHelper outputWriter) : base(outputWriter) + { + } + + [Fact] + public async Task LogCustomRequest_SinksToApplicationInsights_ResultsInCustomRequestTelemetry() + { + // Arrange + string componentName = BogusGenerator.Commerce.ProductName(); + LoggerConfiguration.Enrich.WithComponentName(componentName); + + string customRequestSource = BogusGenerator.Lorem.Word(); + string operationName = BogusGenerator.Lorem.Word(); + + bool isSuccessful = BogusGenerator.Random.Bool(); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = DateTimeOffset.Now; + Dictionary telemetryContext = CreateTestTelemetryContext(); + + // Act + Logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, startTime, duration, telemetryContext); + + // Assert + await RetryAssertUntilTelemetryShouldBeAvailableAsync(async client => + { + EventsRequestResult[] requests = await client.GetRequestsAsync(); + AssertX.Any(requests, result => + { + Assert.Equal(operationName, result.Request.Name); + Assert.Contains(customRequestSource, result.Request.Source); + Assert.Empty(result.Request.Url); + Assert.Equal(operationName, result.Operation.Name); + Assert.True(bool.TryParse(result.Request.Success, out bool success)); + Assert.Equal(isSuccessful, success); + Assert.Equal(componentName, result.Cloud.RoleName); + }); + }); + } + } +} diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventHubsRequestTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventHubsRequestTests.cs index 7c803671..4a4fb1dc 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventHubsRequestTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventHubsRequestTests.cs @@ -34,7 +34,7 @@ public async Task LogEventHubsRequest_SinksToApplicationInsights_ResultsInEventH Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - Logger.LogEventHubsRequest(eventHubsNamespace, eventHubsConsumerGroup, eventHubsName, operationName, isSuccessful, duration, startTime, telemetryContext); + Logger.LogEventHubsRequest(eventHubsNamespace, eventHubsConsumerGroup, eventHubsName, operationName, isSuccessful, startTime, duration, telemetryContext); // Assert await RetryAssertUntilTelemetryShouldBeAvailableAsync(async client => @@ -49,6 +49,7 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async client => Assert.Equal(operationName, result.Operation.Name); Assert.True(bool.TryParse(result.Request.Success, out bool success)); Assert.Equal(isSuccessful, success); + Assert.Equal(componentName, result.Cloud.RoleName); AssertContainsCustomDimension(result.CustomDimensions, EventHubs.Namespace, eventHubsNamespace); AssertContainsCustomDimension(result.CustomDimensions, EventHubs.ConsumerGroup, eventHubsConsumerGroup); diff --git a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs index e7facc51..8f5359e9 100644 --- a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs +++ b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs @@ -100,7 +100,7 @@ public static RequestLogEntry GetMessageAsRequest(this TestLogger logger) } else { - const string pattern = @"(Azure Service Bus|Azure EventHubs) from (?[\w\s]+) completed 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)), Context: \{(?((\[[\w\-]+, [\w\$]+\])(; \[[\w\-]+, [\w\$\.]+\])*))\}\)$"; + const string pattern = @"(Azure Service Bus|Azure EventHubs|Custom \w+) from (?[\w\s]+) completed 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)), Context: \{(?((\[[\w\-]+, [\w\$]+\])(; \[[\w\-]+, [\w\$\.]+\])*))\}\)$"; Match match = Regex.Match(logger.WrittenMessage, pattern); string operationName = match.GetGroupValue("operationname"); @@ -119,6 +119,14 @@ public static RequestLogEntry GetMessageAsRequest(this TestLogger logger) return RequestLogEntry.CreateForEventHubs(operationName, isSuccessful, duration, startTime, context); } + if (logger.WrittenMessage.StartsWith("Custom")) + { + int length = logger.WrittenMessage.IndexOf(" from ", StringComparison.CurrentCulture); + int startIndex = "Custom ".Length; + string customRequestSource = logger.WrittenMessage.Substring(startIndex, length - startIndex); + return RequestLogEntry.CreateForCustomRequest(customRequestSource, operationName, isSuccessful, duration, startTime, context); + } + throw new InvalidOperationException("Cannot determine request source system during parsing of logged request"); } } diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/CustomRequestLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/CustomRequestLoggingTests.cs new file mode 100644 index 00000000..bf2a59dd --- /dev/null +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/CustomRequestLoggingTests.cs @@ -0,0 +1,243 @@ +using System; +using System.Collections.Generic; +using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; +using Bogus; +using Microsoft.Extensions.Logging; +using Xunit; +using static Arcus.Observability.Telemetry.Core.ContextProperties.RequestTracking; + +namespace Arcus.Observability.Tests.Unit.Telemetry.Logging +{ + public class CustomRequestLoggingTests + { + private static readonly Faker BogusGenerator = new Faker(); + + [Fact] + public void LogWithoutOperationNameWithDurationMeasurement_WithValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogCustomRequest(customRequestSource, isSuccessful, measurement, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.Equal(RequestSourceSystem.Custom, entry.SourceSystem); + Assert.Equal(customRequestSource, entry.CustomRequestSource); + Assert.Equal(DefaultOperationName, entry.OperationName); + Assert.Equal(isSuccessful, entry.ResponseStatusCode is 200); + Assert.Equal(measurement.StartTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(measurement.Elapsed, entry.RequestDuration); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogWithoutOperationNameWithDurationMeasurement_WithoutEventHubsNamespace_Fails(string customRequestSource) + { + // Arrange + var logger = new TestLogger(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, isSuccessful, measurement)); + } + + [Fact] + public void LogWithoutOperationNameWithDurationMeasurement_WithoutDurationMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + string eventHubsName = BogusGenerator.Lorem.Word(); + string customRequestSource = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, eventHubsName, isSuccessful, measurement: null)); + } + + [Fact] + public void LogWithoutOperationName_WithValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogCustomRequest(customRequestSource, isSuccessful, startTime, duration, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.Equal(RequestSourceSystem.Custom, entry.SourceSystem); + Assert.Equal(customRequestSource, entry.CustomRequestSource); + Assert.Equal(DefaultOperationName, entry.OperationName); + Assert.Equal(isSuccessful, entry.ResponseStatusCode is 200); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(duration, entry.RequestDuration); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogWithoutOperationName_WithoutEventHubsNamespace_Fails(string customRequestSource) + { + // Arrange + var logger = new TestLogger(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, isSuccessful, startTime, duration)); + } + + [Fact] + public void LogWithoutOperationName_WithNegativeDuration_Fails() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan().Negate(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, isSuccessful, startTime, duration)); + } + + [Fact] + public void LogWithOperationNameWithDurationMeasurement_WithValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, measurement, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.Equal(RequestSourceSystem.Custom, entry.SourceSystem); + Assert.Equal(customRequestSource, entry.CustomRequestSource); + Assert.Equal(operationName, entry.OperationName); + Assert.Equal(isSuccessful, entry.ResponseStatusCode is 200); + Assert.Equal(measurement.StartTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(measurement.Elapsed, entry.RequestDuration); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogWithOperationNameWithDurationMeasurement_WithoutEventHubsNamespace_Fails(string customRequestSource) + { + // Arrange + var logger = new TestLogger(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, measurement)); + } + + [Fact] + public void LogWithOperationNameWithDurationMeasurement_WithoutDurationMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, measurement: null)); + } + + [Fact] + public void LogWithOperationName_WithValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, startTime, duration, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.Equal(RequestSourceSystem.Custom, entry.SourceSystem); + Assert.Equal(customRequestSource, entry.CustomRequestSource); + Assert.Equal(operationName, entry.OperationName); + Assert.Equal(isSuccessful, entry.ResponseStatusCode is 200); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(duration, entry.RequestDuration); + } + + [Theory] + [ClassData(typeof(Blanks))] + public void LogWithOperationName_WithoutEventHubsNamespace_Fails(string customRequestSource) + { + // Arrange + var logger = new TestLogger(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, startTime, duration)); + } + + [Fact] + public void LogWithOperationName_WithNegativeDuration_Fails() + { + // Arrange + var logger = new TestLogger(); + string customRequestSource = BogusGenerator.Lorem.Word(); + string operationName = BogusGenerator.Lorem.Word(); + bool isSuccessful = BogusGenerator.PickRandom(false, true); + TimeSpan duration = BogusGenerator.Date.Timespan().Negate(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + // Act / Assert + Assert.ThrowsAny( + () => logger.LogCustomRequest(customRequestSource, operationName, isSuccessful, startTime, duration)); + } + } +} diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/EventHubsRequestLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/EventHubsRequestLoggingTests.cs index 5974d62e..545f98dc 100644 --- a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/EventHubsRequestLoggingTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/EventHubsRequestLoggingTests.cs @@ -106,7 +106,7 @@ public void LogWithoutConsumerGroup_WithValidArguments_Succeeds() var context = new Dictionary { [key] = value }; // Act - logger.LogEventHubsRequest(@namespace, name, isSuccessful, duration, startTime, context); + logger.LogEventHubsRequest(@namespace, name, isSuccessful, startTime, duration, context); // Assert RequestLogEntry entry = logger.GetMessageAsRequest(); @@ -133,7 +133,7 @@ public void LogWithoutConsumerGroup_WithoutEventHubsNamespace_Fails(string @name // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, startTime, duration)); } [Theory] @@ -149,7 +149,7 @@ public void LogWithoutConsumerGroup_WithoutEventHubsName_Fails(string eventHubsN // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, startTime, duration)); } [Fact] @@ -165,7 +165,7 @@ public void LogWithoutConsumerGroup_WithNegativeDuration_Fails() // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, eventHubsName, isSuccessful, startTime, duration)); } [Fact] @@ -269,7 +269,7 @@ public void LogWithConsumerGroup_WithValidArguments_Succeeds() var context = new Dictionary { [key] = value }; // Act - logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, duration, startTime, context); + logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, startTime, duration, context); // Assert RequestLogEntry entry = logger.GetMessageAsRequest(); @@ -299,7 +299,7 @@ public void LogWithConsumerGroup_WithoutEventHubsNamespace_Fails(string @namespa // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, startTime, duration)); } [Theory] @@ -317,7 +317,7 @@ public void LogWithConsumerGroup_WithoutEventHubsName_Fails(string eventHubsName // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, startTime, duration)); } [Fact] @@ -335,7 +335,7 @@ public void LogWithConsumerGroup_WithNegativeDuration_Fails() // Act / Assert Assert.ThrowsAny( - () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, duration, startTime)); + () => logger.LogEventHubsRequest(@namespace, consumerGroup, eventHubsName, operationName, isSuccessful, startTime, duration)); } } }