feat: track custom request (#447)

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("<my-request-source>", "<operation-name>", isSuccessful, measurement);
+        // Output: Custom <my-request-source> from Process completed in 0.00:12:20.8290760 at 2021-10-26T05:36:03.6067975 +02:00 - (IsSuccessful: True, Context: {[TelemetryType, Request]})
+    }
+}
+```
+
+The `<my-request-source>` 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.

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";

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);
         }
 
         /// <summary>
@@ -47,26 +47,27 @@ public static void LogEventHubsRequest(
         /// <param name="eventHubsNamespace">The namespace in which the Azure EventHUbs is located.</param>
         /// <param name="eventHubsName">The name of the Event Hub that the processor is connected to, specific to the EventHubs namespace that contains it.</param>
         /// <param name="isSuccessful">The indication whether or not the Azure EventHubs request was successfully processed.</param>
-        /// <param name="duration">The duration it took to process the Azure EventHubs request.</param>
         /// <param name="startTime">The time when the request was received.</param>
+        /// <param name="duration">The duration it took to process the Azure EventHubs request.</param>
         /// <param name="context">The telemetry context that provides more insights on the Azure EventHubs request.</param>
         /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
         /// <exception cref="ArgumentException">Thrown when the <paramref name="eventHubsNamespace"/>, <paramref name="eventHubsName"/> is blank.</exception>
+        /// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
         public static void LogEventHubsRequest(
             this ILogger logger,
             string eventHubsNamespace,
             string eventHubsName,
             bool isSuccessful,
-            TimeSpan duration,
             DateTimeOffset startTime,
+            TimeSpan duration,
             Dictionary<string, object> context = null)
         {
             Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry");
             Guard.NotNullOrWhitespace(eventHubsNamespace, nameof(eventHubsNamespace), "Requires an Azure EventHubs namespace to track the request");
             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);
         }
 
         /// <summary>
@@ -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);
         }
 
         /// <summary>
@@ -112,22 +113,23 @@ public static void LogEventHubsRequest(
         /// <param name="eventHubsName">The name of the Event Hub that the processor is connected to, specific to the EventHubs namespace that contains it.</param>
         /// <param name="operationName">The optional logical name that can be used to identify the operation that consumes the message.</param>
         /// <param name="isSuccessful">The indication whether or not the Azure EventHubs request was successfully processed.</param>
-        /// <param name="duration">The duration it took to process the Azure EventHubs request.</param>
         /// <param name="startTime">The time when the request was received.</param>
+        /// <param name="duration">The duration it took to process the Azure EventHubs request.</param>
         /// <param name="context">The telemetry context that provides more insights on the Azure EventHubs request.</param>
         /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
         /// <exception cref="ArgumentException">
         ///     Thrown when the <paramref name="eventHubsNamespace"/>, <paramref name="consumerGroup"/>, <paramref name="eventHubsName"/> is blank.
         /// </exception>
+        /// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
         public static void LogEventHubsRequest(
             this ILogger logger,
             string eventHubsNamespace,
             string consumerGroup,
             string eventHubsName,
             string operationName,
             bool isSuccessful,
-            TimeSpan duration,
             DateTimeOffset startTime,
+            TimeSpan duration,
             Dictionary<string, object> context = null)
         {
             Guard.NotNull(logger, nameof(logger), "Requires an logger instance to track telemetry");

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
+{
+    /// <summary>
+    /// Telemetry extensions on the <see cref="ILogger"/> instance to write Application Insights compatible log messages.
+    /// </summary>
+    // ReSharper disable once InconsistentNaming
+    public static partial class ILoggerExtensions
+    {
+        /// <summary>
+        /// Logs a custom request.
+        /// </summary>
+        /// <param name="logger">The logger instance to track the telemetry.</param>
+        /// <param name="requestSource">The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus).</param>
+        /// <param name="isSuccessful">The indication whether or not the custom request was successfully processed.</param>
+        /// <param name="measurement">The instance to measure the duration of the custom request.</param>
+        /// <param name="context">The telemetry context that provides more insights on the custom request.</param>
+        /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> or the <paramref name="measurement"/> is <c>null</c>.</exception>
+        /// <exception cref="ArgumentException">Thrown when the <paramref name="requestSource"/> is blank.</exception>
+        public static void LogCustomRequest(
+            this ILogger logger,
+            string requestSource,
+            bool isSuccessful,
+            DurationMeasurement measurement,
+            Dictionary<string, object> 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);
+        }
+
+        /// <summary>
+        /// Logs a custom request.
+        /// </summary>
+        /// <param name="logger">The logger instance to track the telemetry.</param>
+        /// <param name="requestSource">The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus).</param>
+        /// <param name="isSuccessful">The indication whether or not the custom request was successfully processed.</param>
+        /// <param name="startTime">The time when the request was received.</param>
+        /// <param name="duration">The duration it took to process the custom request.</param>
+        /// <param name="context">The telemetry context that provides more insights on the custom request.</param>
+        /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
+        /// <exception cref="ArgumentException">Thrown when the <paramref name="requestSource"/> is blank.</exception>
+        /// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
+        public static void LogCustomRequest(
+            this ILogger logger,
+            string requestSource,
+            bool isSuccessful,
+            DateTimeOffset startTime,
+            TimeSpan duration,
+            Dictionary<string, object> 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);
+        }
+
+        /// <summary>
+        /// Logs a custom request.
+        /// </summary>
+        /// <param name="logger">The logger instance to track the telemetry.</param>
+        /// <param name="requestSource">The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus).</param>
+        /// <param name="operationName">The optional logical name that can be used to identify the operation that consumes the message.</param>
+        /// <param name="isSuccessful">The indication whether or not the custom request was successfully processed.</param>
+        /// <param name="measurement">The instance to measure the duration of the custom request.</param>
+        /// <param name="context">The telemetry context that provides more insights on the custom request.</param>
+        /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> or the <paramref name="measurement"/> is <c>null</c>.</exception>
+        /// <exception cref="ArgumentException">Thrown when the <paramref name="requestSource"/> is blank.</exception>
+        public static void LogCustomRequest(
+            this ILogger logger,
+            string requestSource,
+            string operationName,
+            bool isSuccessful,
+            DurationMeasurement measurement,
+            Dictionary<string, object> 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);
+        }
+
+        /// <summary>
+        /// Logs a custom request.
+        /// </summary>
+        /// <param name="logger">The logger instance to track the telemetry.</param>
+        /// <param name="requestSource">The source for the request telemetry to identifying the caller (ex. entity name of Azure Service Bus).</param>
+        /// <param name="operationName">The optional logical name that can be used to identify the operation that consumes the message.</param>
+        /// <param name="isSuccessful">The indication whether or not the custom request was successfully processed.</param>
+        /// <param name="startTime">The time when the request was received.</param>
+        /// <param name="duration">The duration it took to process the custom request.</param>
+        /// <param name="context">The telemetry context that provides more insights on the custom request.</param>
+        /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
+        /// <exception cref="ArgumentException">Thrown when the <paramref name="requestSource"/> is blank.</exception>
+        /// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
+        public static void LogCustomRequest(
+            this ILogger logger, 
+            string requestSource,
+            string operationName,
+            bool isSuccessful,
+            DateTimeOffset startTime,
+            TimeSpan duration,
+            Dictionary<string, object> 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<string, object>();
+
+            logger.LogWarning(MessageFormats.RequestFormat, RequestLogEntry.CreateForCustomRequest(requestSource, operationName, isSuccessful, duration, startTime, context));
+        }
+    }
+}