Feature - introduce 'DependencyMeasurement' for tracking latencie… (#52)

* Feature - introduce 'DependencyMeasurement' for tracking latencies in dependencies

* pr-sug: use both approach on dependency measurement

* pr-sug: use overload with 'DependencyMeasurement'

* pr-fix: provide xml docs for dep data prop

* pr-sug: use const for dependency data test value

* pr-fix: use duration correctly

* pr-sug: use ctor for creating fields

* pr-docs: use measurement overload in docs

docs/features/writing-different-telemetry-types.md

@@ -43,23 +43,50 @@ var telemetryContext = new Dictionary<string, object>
     { "Tenant", "Contoso"},
 };
 
+var durationMeasurement = new Stopwatch();
+
 // Create request
 var request = new HttpRequestMessage(HttpMethod.Post, "http://requestbin.net/r/ujxglouj")
 {
     Content = new StringContent("{\"message\":\"Hello World!\"")
 };
 
 // Start measuring
-var startTime = DateTimeOffset.UtcNow;
 durationMeasurement.Start();
-
+var startTime = DateTimeOffset.UtcNow;
 // Send request to dependant service
 var response = await httpClient.SendAsync(request);
 
 _logger.LogHttpDependency(request, response.StatusCode, startTime, durationMeasurement.Elapsed, telemetryContext);
 // Output: "HTTP Dependency requestbin.net for POST /r/ujxglouj completed with 200 in 00:00:00.2521801 at 03/23/2020 09:56:31 +00:00 (Successful: True - Context: [Tenant, Contoso])"
 ```
 
+
+Or alternatively one can use our `DependencyMeasurement` model to manage the timing for you:
+
+```csharp
+var telemetryContext = new Dictionary<string, object>
+{
+    { "Tenant", "Contoso"},
+};
+
+// Create request
+var request = new HttpRequestMessage(HttpMethod.Post, "http://requestbin.net/r/ujxglouj")
+{
+    Content = new StringContent("{\"message\":\"Hello World!\"")
+};
+
+// Start measuring
+using (var measurement = DependencyMeasurement.Start())
+{
+    // Send request to dependant service
+    var response = await httpClient.SendAsync(request);
+
+    _logger.LogHttpDependency(request, response.StatusCode, measurement, telemetryContext);
+    // Output: "HTTP Dependency requestbin.net for POST /r/ujxglouj completed with 200 in 00:00:00.2521801 at 03/23/2020 09:56:31 +00:00 (Successful: True - Context: [Tenant, Contoso])"
+}
+```
+
 ### Measuring SQL dependencies
 
 Here is how you can report a SQL dependency:
@@ -71,6 +98,8 @@ var telemetryContext = new Dictionary<string, object>
     { "Tenant", "Contoso"},
 };
 
+var durationMeasurement = new Stopwatch();
+
 // Start measuring
 var startTime = DateTimeOffset.UtcNow;
 durationMeasurement.Start();
@@ -82,6 +111,26 @@ _logger.LogSqlDependency("sample-server", "sample-database", "my-table", "get-pr
 // Output: "SQL Dependency sample-server for sample-database/my-table for operation get-products in 00:00:01.2396312 at 03/23/2020 09:32:02 +00:00 (Successful: True - Context: [Catalog, Products], [Tenant, Contoso])"
 ```
 
+Or alternatively, one can use our `DependencyMeasurement` model to manage the timing for you:
+
+```csharp
+var telemetryContext = new Dictionary<string, object>
+{
+    { "Catalog", "Products"},
+    { "Tenant", "Contoso"},
+};
+
+// Start measuring
+using (var measurement = DependencyMeasurement.Start("get-products"))
+{
+    // Interact with database
+    var products = await _repository.GetProducts();
+
+    _logger.LogSqlDependency("sample-server", "sample-database", "my-table", "get-products", isSuccessful: true, measurement: measurement, context: telemetryContext);
+    // Output: "SQL Dependency sample-server for sample-database/my-table for operation get-products in 00:00:01.2396312 at 03/23/2020 09:32:02 +00:00 (Successful: True - Context: [Catalog, Products], [Tenant, Contoso])"
+}
+```
+
 ## Events
 
 Events allow you to report custom events which are a great way to track business-related events.

src/Arcus.Observability.Telemetry.Core/DependencyMeasurement.cs

@@ -0,0 +1,60 @@
+using System;
+using System.Diagnostics;
+
+namespace Arcus.Observability.Telemetry.Core
+{
+    /// <summary>
+    /// Represents an instance to measure easily dependencies in an application.
+    /// </summary>
+    public class DependencyMeasurement : IDisposable
+    {
+        private readonly Stopwatch _stopwatch;
+
+        private DependencyMeasurement(string dependencyData)
+        {
+            _stopwatch = Stopwatch.StartNew();
+            StartTime = DateTimeOffset.UtcNow;
+            DependencyData = dependencyData;
+        }
+
+        /// <summary>
+        /// Starts measuring a dependency until the measurement is disposed.
+        /// </summary>
+        public static DependencyMeasurement Start()
+        {
+            return Start(dependencyData: null);
+        }
+
+        /// <summary>
+        /// Starts measuring a dependency until the measurement is disposed.
+        /// </summary>
+        /// <param name="dependencyData">The additional data related to the dependency.</param>
+        public static DependencyMeasurement Start(string dependencyData)
+        {
+            return new DependencyMeasurement(dependencyData);
+        }
+
+        /// <summary>
+        /// Gets the time when the dependency measurement was started.
+        /// </summary>
+        public DateTimeOffset StartTime { get; } 
+
+        /// <summary>
+        /// Gets the total elapsed time measured for the dependency.
+        /// </summary>
+        public TimeSpan Elapsed => _stopwatch.Elapsed;
+
+        /// <summary>
+        /// Gets the additional data that corresponds with the measured dependency.
+        /// </summary>
+        public string DependencyData { get; }
+
+        /// <summary>
+        /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
+        /// </summary>
+        public void Dispose()
+        {
+            _stopwatch.Stop();
+        }
+    }
+}

src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerExtensions.cs

@@ -76,6 +76,23 @@ public static void LogRequest(this ILogger logger, HttpRequest request, HttpResp
             logger.LogInformation(RequestFormat, request.Method, host, resourcePath, statusCode, duration, DateTimeOffset.UtcNow.ToString(CultureInfo.InvariantCulture), context);
         }
 
+        /// <summary>
+        ///     Logs an HTTP dependency
+        /// </summary>
+        /// <param name="logger">Logger to use</param>
+        /// <param name="request">Request that started the HTTP communication</param>
+        /// <param name="statusCode">Status code that was returned by the service for this HTTP communication</param>
+        /// <param name="measurement">Measuring the latency of the HTTP dependency</param>
+        /// <param name="context">Context that provides more insights on the dependency that was measured</param>
+        public static void LogHttpDependency(this ILogger logger, HttpRequestMessage request, HttpStatusCode statusCode, DependencyMeasurement measurement, Dictionary<string, object> context = null)
+        {
+            Guard.NotNull(logger, nameof(logger));
+            Guard.NotNull(request, nameof(request));
+            Guard.NotNull(measurement, nameof(measurement));
+
+            LogHttpDependency(logger, request, statusCode, measurement.StartTime, measurement.Elapsed, context);
+        }
+
         /// <summary>
         ///     Logs an HTTP dependency
         /// </summary>
@@ -101,6 +118,27 @@ public static void LogHttpDependency(this ILogger logger, HttpRequestMessage req
             logger.LogInformation(HttpDependencyFormat, targetName, dependencyName, (int) statusCode, duration, startTime.ToString(CultureInfo.InvariantCulture), isSuccessful, context);
         }
 
+        /// <summary>
+        ///     Logs a SQL dependency
+        /// </summary>
+        /// <param name="logger">Logger to use</param>
+        /// <param name="serverName">Name of server hosting the database</param>
+        /// <param name="databaseName">Name of database</param>
+        /// <param name="tableName">Name of table</param>
+        /// <param name="isSuccessful">Indication whether or not the operation was successful</param>
+        /// <param name="measurement">Measuring the latency to call the SQL dependency</param>
+        /// <param name="context">Context that provides more insights on the dependency that was measured</param>
+        public static void LogSqlDependency(this ILogger logger, string serverName, string databaseName, string tableName, bool isSuccessful, DependencyMeasurement measurement, Dictionary<string, object> context = null)
+        {
+            Guard.NotNull(logger, nameof(logger));
+            Guard.NotNullOrWhitespace(serverName, nameof(serverName));
+            Guard.NotNullOrWhitespace(databaseName, nameof(databaseName));
+            Guard.NotNullOrWhitespace(tableName, nameof(tableName));
+            Guard.NotNull(measurement, nameof(measurement));
+
+            LogSqlDependency(logger, serverName, databaseName, tableName, measurement.DependencyData, isSuccessful, measurement.StartTime, measurement.Elapsed, context);
+        }
+
         /// <summary>
         ///     Logs a SQL dependency
         /// </summary>

src/Arcus.Observability.Tests.Unit/Telemetry/DependencyMeasurementTests.cs

@@ -0,0 +1,79 @@
+using System;
+using System.Threading.Tasks;
+using Arcus.Observability.Telemetry.Core;
+using Xunit;
+
+namespace Arcus.Observability.Tests.Unit.Telemetry
+{
+    [Trait("Category", "Unit")]
+    public class DependencyMeasurementTests
+    {
+        [Fact]
+        public async Task DependencyMeasurement_StartMeasuringAction_HoldsStartAndElapsedTime()
+        {
+            // Act
+            using (var measurement = DependencyMeasurement.Start()) 
+            {
+                // Assert
+                await Task.Delay(TimeSpan.FromMilliseconds(100));
+
+                Assert.NotNull(measurement);
+                Assert.True(DateTimeOffset.UtcNow > measurement.StartTime, "Measurement should have lesser start time");
+                Assert.True(TimeSpan.Zero < measurement.Elapsed, "Measurement should be running");
+            }
+        }
+
+        [Fact]
+        public async Task DependencyMeasurement_StopsMeasuringAction_WhenDisposed()
+        {
+            // Arrange
+            var measurement = DependencyMeasurement.Start();
+            await Task.Delay(TimeSpan.FromMilliseconds(100));
+            measurement.Dispose();
+            var elapsed = measurement.Elapsed;
+
+            // Act
+            await Task.Delay(TimeSpan.FromMilliseconds(100));
+
+            // Assert
+            Assert.NotNull(measurement);
+            Assert.Equal(elapsed, measurement.Elapsed);
+        }
+
+        [Fact]
+        public async Task DependencyMeasurementWithDependencyData_StartMeasuringAction_HoldsStartAndElapsedTime()
+        {
+            // Act
+            const string dependencyData = "Operation";
+            using (var measurement = DependencyMeasurement.Start(dependencyData)) 
+            {
+                // Assert
+                await Task.Delay(TimeSpan.FromMilliseconds(100));
+
+                Assert.NotNull(measurement);
+                Assert.Equal(dependencyData, measurement.DependencyData);
+                Assert.True(DateTimeOffset.UtcNow > measurement.StartTime, "Measurement should have lesser start time");
+                Assert.True(TimeSpan.Zero < measurement.Elapsed, "Measurement should be running");
+            }
+        }
+
+        [Fact]
+        public async Task DependencyMeasurementWithDependencyData_StopsMeasuringAction_WhenDisposed()
+        {
+            // Arrange
+            const string dependencyData = "Operation";
+            var measurement = DependencyMeasurement.Start(dependencyData);
+            await Task.Delay(TimeSpan.FromMilliseconds(100));
+            measurement.Dispose();
+            var elapsed = measurement.Elapsed;
+
+            // Act
+            await Task.Delay(TimeSpan.FromMilliseconds(100));
+
+            // Assert
+            Assert.NotNull(measurement);
+            Assert.Equal(dependencyData, measurement.DependencyData);
+            Assert.Equal(elapsed, measurement.Elapsed);
+        }
+    }
+}

src/Arcus.Observability.Tests.Unit/Telemetry/ILoggerExtensionsTests.cs

@@ -103,6 +103,38 @@ public void LogSqlDependency_ValidArguments_Succeeds()
             Assert.Contains(duration.ToString(), logMessage);
         }
 
+        [Fact]
+        public void LogSqlDependencyWithDependencyMeasurement_ValidArguments_Succeeds()
+        {
+            // Arrange
+            var logger = new TestLogger();
+            string serverName = _bogusGenerator.Name.FullName();
+            string databaseName = _bogusGenerator.Name.FullName();
+            string tableName = _bogusGenerator.Name.FullName();
+            string operationName = _bogusGenerator.Name.FullName();
+            bool isSuccessful = _bogusGenerator.Random.Bool();
+
+            var measurement = DependencyMeasurement.Start(operationName);
+            DateTimeOffset startTime = measurement.StartTime;
+            measurement.Dispose();
+            TimeSpan duration = measurement.Elapsed;
+
+            // Act
+            logger.LogSqlDependency(serverName, databaseName, tableName, isSuccessful, measurement);
+
+            // Assert
+
+            var logMessage = logger.WrittenMessage;
+            Assert.StartsWith(MessagePrefixes.DependencyViaSql, logMessage);
+            Assert.Contains(serverName, logMessage);
+            Assert.Contains(databaseName, logMessage);
+            Assert.Contains(tableName, logMessage);
+            Assert.Contains(operationName, logMessage);
+            Assert.Contains(isSuccessful.ToString(), logMessage);
+            Assert.Contains(startTime.ToString(CultureInfo.InvariantCulture), logMessage);
+            Assert.Contains(duration.ToString(), logMessage);
+        }
+
         [Fact]
         public void LogSqlDependency_NoServerNameWasSpecified_ThrowsException()
         {
@@ -181,7 +213,7 @@ public void LogHttpDependency_ValidArguments_Succeeds()
             DateTimeOffset startTime = _bogusGenerator.Date.PastOffset();
             var duration = _bogusGenerator.Date.Timespan();
 
-            // Act;
+            // Act
             logger.LogHttpDependency(request, statusCode, startTime, duration);
 
             // Assert
@@ -190,12 +222,40 @@ public void LogHttpDependency_ValidArguments_Succeeds()
             Assert.Contains(request.RequestUri.Host, logMessage);
             Assert.Contains(request.RequestUri.PathAndQuery, logMessage);
             Assert.Contains(request.Method.ToString(), logMessage);
-            Assert.Contains(((int)statusCode).ToString(), logMessage);
+            Assert.Contains(((int) statusCode).ToString(), logMessage);
             Assert.Contains(startTime.ToString(CultureInfo.InvariantCulture), logMessage);
-            var isSuccessful = (int)statusCode >= 200 && (int)statusCode < 300;
+            var isSuccessful = (int) statusCode >= 200 && (int) statusCode < 300;
             Assert.Contains($"Successful: {isSuccessful}", logMessage);
         }
 
+        [Fact]
+        public void LogHttpDependencyWithDependencyMeasurement_ValidArguments_Succeeds()
+        {
+            // Arrange
+            var logger = new TestLogger();
+            var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.Url());
+            var statusCode = _bogusGenerator.PickRandom<HttpStatusCode>();
+
+            using (var measurement = DependencyMeasurement.Start())
+            {
+                DateTimeOffset startTime = measurement.StartTime;
+
+                // Act
+                logger.LogHttpDependency(request, statusCode, measurement);
+
+                // Assert
+                var logMessage = logger.WrittenMessage;
+                Assert.StartsWith(MessagePrefixes.DependencyViaHttp, logMessage);
+                Assert.Contains(request.RequestUri.Host, logMessage);
+                Assert.Contains(request.RequestUri.PathAndQuery, logMessage);
+                Assert.Contains(request.Method.ToString(), logMessage);
+                Assert.Contains(((int)statusCode).ToString(), logMessage);
+                Assert.Contains(startTime.ToString(CultureInfo.InvariantCulture), logMessage);
+                var isSuccessful = (int)statusCode >= 200 && (int)statusCode < 300;
+                Assert.Contains($"Successful: {isSuccessful}", logMessage); 
+            }
+        }
+
         [Fact]
         public void LogHttpDependency_NoRequestWasSpecified_ThrowsException()
         {