feat: add az servicebus request tracking (w/o ai support) (#250)

* feat: add az servicebus request tracking (w/o ai support) * pr-style: remove blank lines * Update docs/preview/02-Features/writing-different-telemetry-types.md Co-authored-by: Tom Kerkhove <[email protected]> * temp commit * Update docs/preview/02-Features/writing-different-telemetry-types.md Co-authored-by: Frederik Gheysels <[email protected]> * Update docs/preview/02-Features/writing-different-telemetry-types.md Co-authored-by: Frederik Gheysels <[email protected]> * pr-sug: update with az servicebus namespace prefix overloads * Update docs/preview/02-Features/writing-different-telemetry-types.md Co-authored-by: Frederik Gheysels <[email protected]> * Update src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs Co-authored-by: Frederik Gheysels <[email protected]> * Update src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs Co-authored-by: Frederik Gheysels <[email protected]> * pr-sug: use suffix and full io prefix and full * pr-sug: update with topic subscription * Merge 'master' into 'feature/add-servicebus-reques-tracking' # <type>: (If applied, this commit will...) <subject> (Max 50 char) * pr-fix: more stable testing * pr-fix: only net6.0 support when running integration tests * pr-sug: add explicit suffix example in xml and feature docs * pr-sug: add germany example to suffix examples * pr-sug: use more descriptive operation name in xml docs Co-authored-by: Tom Kerkhove <[email protected]> Co-authored-by: Frederik Gheysels <[email protected]>
arcus-azure · Jan 20, 2022 · 1e363b7 · 1e363b7
1 parent 20dfe4f
commit 1e363b7
Show file tree

Hide file tree

Showing 10 changed files with 2,405 additions and 20 deletions.
diff --git a/docs/preview/02-Features/writing-different-telemetry-types.md b/docs/preview/02-Features/writing-different-telemetry-types.md
@@ -460,6 +460,63 @@ logger.LogMetric("Invoice Received", 133.37, telemetryContext);
 
 ## Requests
 
+### Incoming Azure Service Bus requests
+Requests allow you to keep track of incoming Azure Service Bus messages on a queue or topic.
+
+Here is how you can log an Azure Service Bus queue request on a message that's being processed:
+
+```csharp
+using Microsoft.Extensions.Logging;
+
+bool isSuccessful = false;
+
+// Start measuring.
+using (var measurement = DependencyMeasurement.Start())
+{
+    try
+    {
+        // Processing message.
+
+        // End processing.
+        
+        isSuccessful = true;
+    }
+    finally
+    {
+        logger.LogServiceBusQueueRequest("<my-queue-namespace>.servicebus.windows.net", "<my-queue-name>", "<operation-name>", isSuccessful, measurement);
+        // Output: Azure Service Bus from <operation-name> completed in 0.00:12:20.8290760 at 2021-10-26T05:36:03.6067975 +02:00 - (IsSuccessful: True, Context: {[ServiceBus-Endpoint, <my-queue-namespace>.servicebus.windows.net]; [ServiceBus-Entity, <my-queue-name>]; [ServiceBus-EntityType, Queue]; [TelemetryType, Request]})
+    }
+}
+```
+
+We provide support for all Azure Service Bus entity types such as queues, topics and subscriptions. 
+All these types can be tracked by passing allong the full Azure Service namespace, or with providing the namespace name and the Azure cloud separately.
+
+```csharp
+
+DependencyMeasurement measurement = ...
+
+// Tracking Azure Service Bus topics.
+// ----------------------------------
+
+// Providing the full Azure Service Bus topic namespace.
+logger.LogServiceBusTopicRequest("<my-topic-namespace>.servicebus.windows.net", "<my-topic-name>", "<subscription-name>", "<operation-name>", isSuccessful: true, measurement);
+
+// Providing the Azure Service Bus topic name and Azure cloud separately.
+logger.LogServiceBusTopicRequestWithSuffix("<my-topic-namespace-name>", serviceBusNamespaceSuffix: ".servicebus.windows.net", "<my-topic-name>", "<subscription-name>", "<operation-name>", isSuccessful: true, measurement);
+
+
+// Tracking general Azure Service Bus requests.
+// --------------------------------------------
+
+// Providing the full Azure Service Bus topic namespace.
+logger.LogServiceBusRequest("<my-topic-namespace>.servicebus.windows.net", "<my-topic-name>", "<subscription-name>", "<operation-name>", isSuccessful: true, measurement, ServiceBusEntityType.Topic);
+
+// Providing the Azure Service Bus queue namespace name and Azure cloud separately.
+logger.LogServiceBusQueueRequestWithSuffix("<my-queue-namespace-name>", serviceBusNamespaceSuffix: ".servicebus.windows.net", "<my-queue-name>", "<operation-name>", isSuccessful: true, measurement, ServiceBusEntityType.Queue);
+```
+
+### Incoming HTTP requests
 Requests allow you to keep track of the HTTP requests that are performed against your API and what the response was that was sent out.
 
 **Installation**

diff --git a/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs b/src/Arcus.Observability.Telemetry.Core/ContextProperties.cs
@@ -1,4 +1,5 @@
 using System;
+using System.Runtime.InteropServices;
 
 #pragma warning disable 1591
 namespace Arcus.Observability.Telemetry.Core
@@ -65,6 +66,20 @@ public static class RequestTracking
             public const string ResponseStatusCode = "ResponseStatusCode";
             public const string RequestDuration = "RequestDuration";
             public const string RequestTime = "RequestTime";
+
+            public static class ServiceBus
+            {
+                public const string Endpoint = "ServiceBus-Endpoint";
+                public const string EntityName = "ServiceBus-Entity";
+                public const string EntityType = "ServiceBus-EntityType";
+
+                public static class Topic
+                {
+                    public const string SubscriptionName = "ServiceBus-TopicSubscription";
+                }
+
+                public const string DefaultOperationName = "Process";
+            }
         }
 
         public static class MetricTracking

diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs
diff --git a/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs b/src/Arcus.Observability.Telemetry.Core/Logging/RequestLogEntry.cs
@@ -34,8 +34,14 @@ public RequestLogEntry(
             string uri,
             int statusCode,
             TimeSpan duration,
-            IDictionary<string, object> context) : this (method, host, uri, $"{method} {uri}", statusCode, duration, context)
-        { }
+            IDictionary<string, object> context) 
+            : this(method, host, uri, operationName: $"{method} {uri}", statusCode, duration, context)
+        {
+            Guard.For<ArgumentException>(() => host?.Contains(" ") is true, "Requires a HTTP request host name without whitespace");
+            Guard.NotLessThan(statusCode, 100, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
+            Guard.NotGreaterThan(statusCode, 599, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
+            Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation");
+        }
 
         /// <summary>
         /// Initializes a new instance of the <see cref="RequestLogEntry"/> class.
@@ -64,24 +70,74 @@ public RequestLogEntry(
             int statusCode,
             TimeSpan duration,
             IDictionary<string, object> context)
+            : this(method, host, uri, operationName, statusCode, sourceSystem: RequestSourceSystem.Http, duration, requestTime: DateTimeOffset.UtcNow.ToString(FormatSpecifiers.InvariantTimestampFormat), context)
         {
-            Guard.For<ArgumentException>(() => host?.Contains(" ") == true, "Requires a HTTP request host name without whitespace");
+            Guard.For<ArgumentException>(() => host?.Contains(" ") is true, "Requires a HTTP request host name without whitespace");
             Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires an operation name that is not null or whitespace");
             Guard.NotLessThan(statusCode, 100, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
             Guard.NotGreaterThan(statusCode, 599, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
             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,
+            RequestSourceSystem sourceSystem,
+            TimeSpan duration,
+            string requestTime,
+            IDictionary<string, object> context)
+        {
+            Guard.For<ArgumentException>(() => host?.Contains(" ") is true, "Requires a HTTP request host name without whitespace");
+            Guard.NotNullOrWhitespace(operationName, nameof(operationName), "Requires a non-blank operation name");
+            Guard.NotLessThan(statusCode, 100, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
+            Guard.NotGreaterThan(statusCode, 599, nameof(statusCode), "Requires a HTTP response status code that's within the 100-599 range to track a HTTP request");
+            Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation");
+
             RequestMethod = method;
             RequestHost = host;
             RequestUri = uri;
             ResponseStatusCode = statusCode;
             RequestDuration = duration;
             OperationName = operationName;
-            RequestTime = DateTimeOffset.UtcNow.ToString(FormatSpecifiers.InvariantTimestampFormat);
+            SourceSystem = sourceSystem;
+            RequestTime = requestTime;
             Context = context;
             Context[ContextProperties.General.TelemetryType] = TelemetryType.Request;
         }
 
+        /// <summary>
+        /// Creates an <see cref="RequestLogEntry"/> instance for Azure Service Bus requests.
+        /// </summary>
+        /// <param name="operationName">The name of the operation of the request.</param>
+        /// <param name="isSuccessful">The indication whether or not the Azure Service Bus request was successfully processed.</param>
+        /// <param name="duration">The duration it took to process the Azure Service Bus request.</param>
+        /// <param name="startTime">The time when the request was received.</param>
+        /// <param name="context">The telemetry context that provides more insights on the Azure Service Bus request.</param>
+        /// <exception cref="ArgumentOutOfRangeException">Thrown when the <paramref name="duration"/> is a negative time range.</exception>
+        public static RequestLogEntry CreateForServiceBus(
+            string operationName,
+            bool isSuccessful,
+            TimeSpan duration,
+            DateTimeOffset startTime,
+            IDictionary<string, object> context)
+        {
+            Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation");
+
+            return new RequestLogEntry(
+                method: "<not-applicable>",
+                host: "<not-applicable>",
+                uri: "<not-applicable>",
+                operationName,
+                statusCode: isSuccessful ? 200 : 500,
+                sourceSystem: RequestSourceSystem.AzureServiceBus,
+                duration,
+                startTime.ToString(FormatSpecifiers.InvariantTimestampFormat),
+                context);
+        }
+
         /// <summary>
         /// Gets the HTTP method of the request.
         /// </summary>
@@ -113,7 +169,12 @@ public RequestLogEntry(
         public string RequestTime { get; }
 
         /// <summary>
-        /// Gets the name of the operation.
+        /// Gets the type of source system from where the request came from.
+        /// </summary>
+        public RequestSourceSystem SourceSystem { get; set; }
+
+        /// <summary>
+        /// Gets the name of the operation of the source system from where the request came from.
         /// </summary>
         public string OperationName { get; }
 
@@ -128,8 +189,17 @@ public RequestLogEntry(
         /// <returns>A string that represents the current object.</returns>
         public override string ToString()
         {
-            string contextFormatted = $"{{{String.Join("; ", Context.Select(item => $"[{item.Key}, {item.Value}]"))}}}";
-            return $"{RequestMethod} {RequestHost}/{RequestUri} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {contextFormatted})";
+            var contextFormatted = $"{{{String.Join("; ", Context.Select(item => $"[{item.Key}, {item.Value}]"))}}}";
+            switch (SourceSystem)
+            {
+                case RequestSourceSystem.AzureServiceBus:
+                    bool isSuccessful = ResponseStatusCode is 200;
+                    return $"Azure Service Bus from {OperationName} completed in {RequestDuration} at {RequestTime} - (IsSuccessful: {isSuccessful}, Context: {contextFormatted})";
+                case RequestSourceSystem.Http:
+                    return $"{RequestMethod} {RequestHost}/{RequestUri} from {OperationName} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {contextFormatted})";
+                default:
+                    throw new ArgumentOutOfRangeException(nameof(SourceSystem), SourceSystem, "Unknown request source system");
+            }
         }
     }
 }
diff --git a/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs b/src/Arcus.Observability.Telemetry.Core/Logging/RequestSourceSystem.cs
@@ -0,0 +1,18 @@
+namespace Arcus.Observability.Telemetry.Core.Logging
+{
+    /// <summary>
+    /// Represents the system from where the request came from.
+    /// </summary>
+    public enum RequestSourceSystem
+    {
+        /// <summary>
+        /// Specifies that the request-source is an Azure Service Bus queue or topic.
+        /// </summary>
+        AzureServiceBus, 
+
+        /// <summary>
+        /// Specifies that the request-source is a HTTP request
+        /// </summary>
+        Http
+    }
+}
diff --git a/...lity.Telemetry.Serilog.Sinks.ApplicationInsights/Extensions/LogEventPropertyExtensions.cs b/...lity.Telemetry.Serilog.Sinks.ApplicationInsights/Extensions/LogEventPropertyExtensions.cs
@@ -144,14 +144,18 @@ internal static double GetAsDouble(this IReadOnlyList<LogEventProperty> properti
             Guard.NotNullOrWhitespace(propertyKey, nameof(propertyKey), "Requires a non-blank property key to retrieve a Serilog event property as a Double representation");
 
             LogEventProperty logEventPropertyValue = properties.FirstOrDefault(prop => prop.Name == propertyKey);
-            string rawDouble = logEventPropertyValue?.Value?.ToDecentString();
-
-            if (rawDouble is null)
+            if (logEventPropertyValue is null)
             {
                 return double.NaN;
             }
 
-            return double.Parse(rawDouble, CultureInfo.InvariantCulture);
+            if (logEventPropertyValue.Value is ScalarValue scalarValue 
+                && scalarValue.Value is double value)
+            {
+                return value;
+            }
+
+            return double.NaN;
         }
 
         /// <summary>

diff --git a/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj b/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj
@@ -1,7 +1,7 @@
 <Project Sdk="Microsoft.NET.Sdk">
 
   <PropertyGroup>
-    <TargetFrameworks>net6.0;netcoreapp3.1</TargetFrameworks>
+    <TargetFramework>net6.0</TargetFramework>
     <IsPackable>false</IsPackable>
   </PropertyGroup>
 

diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/TelemetryTypeFilterTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/TelemetryTypeFilterTests.cs
@@ -337,8 +337,8 @@ public void LogRequestMessage_WithTelemetryTypeFilter_DoesNotFilterOutEntry(Tele
         {
             // Arrange
             var statusCode = _bogusGenerator.PickRandom<HttpStatusCode>();
-            var path = $"/{_bogusGenerator.Name.FirstName().ToLower()}";
-            string host = _bogusGenerator.Name.FirstName().ToLower();
+            var path = $"/{_bogusGenerator.Lorem.Word().ToLower()}";
+            string host = _bogusGenerator.Lorem.Word().ToLower();
             HttpMethod method = HttpMethod.Head;
             var request = new HttpRequestMessage(method, new Uri("https://" + host + path));
             var response = new HttpResponseMessage(statusCode);

diff --git a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs
@@ -62,6 +62,36 @@ public static DependencyLogEntry GetMessageAsDependency(this TestLogger logger)
                 context);
         }
 
+        /// <summary>
+        /// Gets the written message to the <paramref name="logger"/> as a strongly-typed Request.
+        /// </summary>
+        /// <param name="logger">The test logger where a test message is written to.</param>
+        /// <returns>
+        ///     The strongly-typed Request containing the telemetry information.
+        /// </returns>
+        /// <exception cref="ArgumentNullException">Thrown when the <paramref name="logger"/> is <c>null</c>.</exception>
+        /// <exception cref="InvalidOperationException">Thrown when no test message was written to the test <paramref name="logger"/>.</exception>
+        public static RequestLogEntry GetMessageAsRequest(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 request because no log message was written to this test logger");
+            }
+            const string pattern = @"Azure Service Bus from (?<operationname>[\w\s]+) completed in (?<duration>(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?<timestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) - \(IsSuccessful: (?<issuccessful>(True|False)), Context: \{(?<context>((\[[\w\-]+, \w+\])(; \[[\w\-]+, [\w\.]+\])*))\}\)$";
+            Match match = Regex.Match(logger.WrittenMessage, pattern);
+
+            string operationName = match.GetGroupValue("operationname");
+            TimeSpan duration = match.GetGroupValueAsTimeSpan("duration");
+            DateTimeOffset startTime = match.GetGroupValueAsDateTimeOffset("timestamp");
+            bool isSuccessful = match.GetGroupValueAsBool("issuccessful");
+            IDictionary<string, object> context = match.GetGroupValueAsTelemetryContext("context", TelemetryType.Request);
+
+            return RequestLogEntry.CreateForServiceBus(operationName, isSuccessful, duration, startTime, context);
+        }
+
         /// <summary>
         /// Gets the written message to the <paramref name="logger"/> as a strongly-typed Metric.
         /// </summary>