From 5f153bb68e7d37640ebf5d518d48b2d60651c69f Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Wed, 18 May 2022 15:10:57 +0200 Subject: [PATCH] feat: add dependency id to http dep tracking (#373) * feat: add dependency id to http dep tracking * pr-style: remove unn blank space --- .../ILoggerHttpDependencyExtensions.cs | 164 +++++++++ ...ensions.cs => ILoggerRequestExtensions.cs} | 2 +- .../ILoggerHttpDependencyExtensions.cs | 70 +++- .../HttpDependencyTests.cs | 124 +++---- .../Extensions/TestLoggerExtensions.cs | 2 +- .../Logging/HttpDependencyLoggingTests.cs | 320 ++++++++++++++++-- 6 files changed, 597 insertions(+), 85 deletions(-) create mode 100644 src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerHttpDependencyExtensions.cs rename src/Arcus.Observability.Telemetry.AspNetCore/Extensions/{ILoggerExtensions.cs => ILoggerRequestExtensions.cs} (99%) diff --git a/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerHttpDependencyExtensions.cs b/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerHttpDependencyExtensions.cs new file mode 100644 index 00000000..808936b8 --- /dev/null +++ b/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerHttpDependencyExtensions.cs @@ -0,0 +1,164 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Net; +using System.Net.Http; +using System.Text; +using System.Threading.Tasks; +using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; +using GuardNet; +using Microsoft.AspNetCore.Http; + +// 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 class ILoggerHttpDependencyExtensions + { + /// + /// Logs an HTTP dependency. + /// + /// The logger to track the telemetry. + /// The request that started the HTTP communication. + /// The status code that was returned by the service for this HTTP communication. + /// The measuring the latency of the HTTP dependency. + /// The context that provides more insights on the dependency that was measured. + /// Thrown when the , , or is null. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequest request, + HttpStatusCode statusCode, + DurationMeasurement measurement, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotNull(measurement, nameof(measurement), "Requires a dependency measurement instance to track the latency of the HTTP communication when tracking a HTTP dependency"); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + LogHttpDependency(logger, request, statusCode, measurement.StartTime, measurement.Elapsed, context); + } + + /// + /// Logs an HTTP dependency. + /// + /// The logger to track the telemetry. + /// The request that started the HTTP communication. + /// The status code that was returned by the service for this HTTP communication. + /// The measuring the latency of the HTTP dependency. + /// The ID of the dependency to link as parent ID. + /// The context that provides more insights on the dependency that was measured. + /// Thrown when the , , or is null. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequest request, + HttpStatusCode statusCode, + DurationMeasurement measurement, + string dependencyId, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotNull(measurement, nameof(measurement), "Requires a dependency measurement instance to track the latency of the HTTP communication when tracking a HTTP dependency"); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + LogHttpDependency(logger, request, statusCode, measurement.StartTime, measurement.Elapsed, dependencyId, context); + } + + /// + /// Logs an HTTP dependency + /// + /// The logger to track the telemetry. + /// Request that started the HTTP communication + /// Status code that was returned by the service for this HTTP communication + /// Point in time when the interaction with the HTTP dependency was started + /// Duration of the operation + /// Context that provides more insights on the dependency that was measured + /// Thrown when the or is null. + /// Thrown when the is a negative time range. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequest request, + HttpStatusCode statusCode, + DateTimeOffset startTime, + TimeSpan duration, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the HTTP dependency operation"); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + context = context ?? new Dictionary(); + + LogHttpDependency(logger, request, statusCode, startTime, duration, dependencyId: null, context); + } + + /// + /// Logs an HTTP dependency + /// + /// The logger to track the telemetry. + /// Request that started the HTTP communication + /// Status code that was returned by the service for this HTTP communication + /// Point in time when the interaction with the HTTP dependency was started + /// Duration of the operation + /// The ID of the dependency to link as parent ID. + /// Context that provides more insights on the dependency that was measured + /// Thrown when the or is null. + /// Thrown when the is a negative time range. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequest request, + HttpStatusCode statusCode, + DateTimeOffset startTime, + TimeSpan duration, + string dependencyId, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the HTTP dependency operation"); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + context = context ?? new Dictionary(); + + string requestUri = request.Path; + string targetName = request.Host.Host; + string requestMethod = request.Method; + string dependencyName = $"{requestMethod} {requestUri}"; + bool isSuccessful = (int)statusCode >= 200 && (int)statusCode < 300; + + logger.LogWarning(MessageFormats.HttpDependencyFormat, new DependencyLogEntry( + dependencyType: "Http", + dependencyName: dependencyName, + dependencyData: null, + targetName: targetName, + duration: duration, + startTime: startTime, + dependencyId: dependencyId, + resultCode: (int)statusCode, + isSuccessful: isSuccessful, + context: context)); + } + } +} diff --git a/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerExtensions.cs b/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerRequestExtensions.cs similarity index 99% rename from src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerExtensions.cs rename to src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerRequestExtensions.cs index 78baf6e3..3c2916f3 100644 --- a/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerExtensions.cs +++ b/src/Arcus.Observability.Telemetry.AspNetCore/Extensions/ILoggerRequestExtensions.cs @@ -12,7 +12,7 @@ namespace Microsoft.Extensions.Logging /// Telemetry extensions on the instance to write Application Insights compatible log messages. /// // ReSharper disable once InconsistentNaming - public static class ILoggerExtensions + public static class ILoggerRequestExtensions { /// /// Logs an HTTP request diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerHttpDependencyExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerHttpDependencyExtensions.cs index 7ff8dbf1..e9b06e66 100644 --- a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerHttpDependencyExtensions.cs +++ b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerHttpDependencyExtensions.cs @@ -72,6 +72,71 @@ public static partial class ILoggerExtensions LogHttpDependency(logger, request, statusCode, measurement.StartTime, measurement.Elapsed, context); } + /// + /// Logs an HTTP dependency. + /// + /// The logger to track the telemetry. + /// The request that started the HTTP communication. + /// The status code that was returned by the service for this HTTP communication. + /// The measuring the latency of the HTTP dependency. + /// The ID of the dependency to link as parent ID. + /// The context that provides more insights on the dependency that was measured. + /// Thrown when the , , or is null. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequestMessage request, + HttpStatusCode statusCode, + DurationMeasurement measurement, + string dependencyId, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotNull(measurement, nameof(measurement), "Requires a dependency measurement instance to track the latency of the HTTP communication when tracking a HTTP dependency"); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + LogHttpDependency(logger, request, statusCode, measurement.StartTime, measurement.Elapsed, dependencyId, context); + } + + /// + /// Logs an HTTP dependency + /// + /// The logger to track the telemetry. + /// Request that started the HTTP communication + /// Status code that was returned by the service for this HTTP communication + /// Point in time when the interaction with the HTTP dependency was started + /// Duration of the operation + /// Context that provides more insights on the dependency that was measured + /// Thrown when the or is null. + /// Thrown when the is a negative time range. + /// + /// Thrown when the doesn't have a request URI or HTTP method, the is outside the bounds of the enumeration. + /// + public static void LogHttpDependency( + this ILogger logger, + HttpRequestMessage request, + HttpStatusCode statusCode, + DateTimeOffset startTime, + TimeSpan duration, + Dictionary context = null) + { + Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); + Guard.NotNull(request, nameof(request), "Requires a HTTP request message to track a HTTP dependency"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the HTTP dependency operation"); + Guard.For(() => request.RequestUri is null, new ArgumentException("Requires a HTTP request URI to track a HTTP dependency", nameof(request))); + Guard.For(() => request.Method is null, new ArgumentException("Requires a HTTP request method to track a HTTP dependency", nameof(request))); + Guard.For(() => !Enum.IsDefined(typeof(HttpStatusCode), statusCode), + new ArgumentException("Requires a response HTTP status code that's within the bound of the enumeration to track a HTTP dependency")); + + context = context ?? new Dictionary(); + + LogHttpDependency(logger, request, statusCode, startTime, duration, dependencyId: null, context); + } + /// /// Logs an HTTP dependency /// @@ -80,6 +145,7 @@ public static partial class ILoggerExtensions /// Status code that was returned by the service for this HTTP communication /// Point in time when the interaction with the HTTP dependency was started /// Duration of the operation + /// The ID of the dependency to link as parent ID. /// Context that provides more insights on the dependency that was measured /// Thrown when the or is null. /// Thrown when the is a negative time range. @@ -92,6 +158,7 @@ public static partial class ILoggerExtensions HttpStatusCode statusCode, DateTimeOffset startTime, TimeSpan duration, + string dependencyId, Dictionary context = null) { Guard.NotNull(logger, nameof(logger), "Requires a logger instance to track telemetry"); @@ -117,7 +184,8 @@ public static partial class ILoggerExtensions targetName: targetName, duration: duration, startTime: startTime, - resultCode: (int)statusCode, + dependencyId: dependencyId, + resultCode: (int) statusCode, isSuccessful: isSuccessful, context: context)); } diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs index 9b3bb16c..5f46fc7f 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs @@ -1,14 +1,15 @@ using System; using System.Collections.Generic; -using System.Linq; using System.Net; using System.Net.Http; using System.Threading.Tasks; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; +using Microsoft.AspNetCore.Http; using Microsoft.Azure.ApplicationInsights.Query; using Microsoft.Azure.ApplicationInsights.Query.Models; using Microsoft.Extensions.Logging; +using Moq; using Serilog; using Serilog.Events; using Xunit; @@ -26,26 +27,29 @@ public HttpDependencyTests(ITestOutputHelper outputWriter) : base(outputWriter) } [Fact] - public async Task LogHttpDependency_SinksToApplicationInsights_ResultsInHttpDependencyTelemetry() + public async Task LogHttpDependencyWithRequestMessage_SinksToApplicationInsights_ResultsInHttpDependencyTelemetryWithComponentName() { // Arrange + string componentName = BogusGenerator.Commerce.ProductName(); HttpMethod httpMethod = GenerateHttpMethod(); string requestUrl = BogusGenerator.Image.LoremFlickrUrl(); - using (ILoggerFactory loggerFactory = CreateLoggerFactory()) + string dependencyId = BogusGenerator.Random.Word(); + + using (ILoggerFactory loggerFactory = CreateLoggerFactory(config => config.Enrich.WithComponentName(componentName))) { ILogger logger = loggerFactory.CreateLogger(); - + var request = new HttpRequestMessage(httpMethod, requestUrl) { Content = new StringContent(BogusGenerator.Lorem.Paragraph()) }; var statusCode = BogusGenerator.PickRandom(); - DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(days: 0); - var duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = DateTimeOffset.Now; + TimeSpan duration = BogusGenerator.Date.Timespan(); Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogHttpDependency(request, statusCode, startTime, duration, telemetryContext); + logger.LogHttpDependency(request, statusCode, startTime, duration, dependencyId, telemetryContext); } // Assert @@ -54,90 +58,59 @@ public async Task LogHttpDependency_SinksToApplicationInsights_ResultsInHttpDepe { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetDependencyEventsAsync(ApplicationId); + EventsResults results = await client.Events.GetDependencyEventsAsync(ApplicationId, PastHalfHourTimeSpan); Assert.NotEmpty(results.Value); - Assert.Contains(results.Value, result => + AssertX.Any(results.Value, result => { - return result.Dependency.Type == DependencyType - && result.Dependency.Target == requestUri.Host - && result.Dependency.Name == $"{httpMethod} {requestUri.AbsolutePath}"; + Assert.Equal(DependencyType, result.Dependency.Type); + Assert.Equal(requestUri.Host, result.Dependency.Target); + Assert.Equal($"{httpMethod} {requestUri.AbsolutePath}", result.Dependency.Name); + Assert.Equal(dependencyId, result.Dependency.Id); + Assert.Equal(componentName, result.Cloud.RoleName); }); }); } - - AssertX.Any(GetLogEventsFromMemory(), logEvent => { - StructureValue logEntry = logEvent.Properties.GetAsStructureValue(ContextProperties.DependencyTracking.DependencyLogEntry); - Assert.NotNull(logEntry); - - var actualDependencyType = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyType)); - Assert.Equal(DependencyType, actualDependencyType.Value.ToDecentString(), true); - - var actualDependencyName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyName)); - Assert.Equal($"{httpMethod} {requestUri.AbsolutePath}", actualDependencyName.Value.ToDecentString()); - - var actualTargetName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.TargetName)); - Assert.Equal(requestUri.Host, actualTargetName.Value.ToDecentString()); - - Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.Context)); - }); + + AssertSerilogLogProperties(httpMethod, requestUri.Host, requestUri.AbsolutePath); } [Fact] - public async Task LogHttpDependencyWithComponentName_SinksToApplicationInsights_ResultsInHttpDependencyTelemetryWithComponentName() + public async Task LogHttpDependencyWithRequest_SinksToApplicationInsights_ResultsInHttpDependencyTelemetry() { // Arrange - string componentName = BogusGenerator.Commerce.ProductName(); HttpMethod httpMethod = GenerateHttpMethod(); - string requestUrl = BogusGenerator.Image.LoremFlickrUrl(); - using (ILoggerFactory loggerFactory = CreateLoggerFactory(config => config.Enrich.WithComponentName(componentName))) + HttpRequest request = CreateStubRequest(httpMethod, "arcus.test", "/integration", "https"); + string dependencyId = BogusGenerator.Random.Guid().ToString(); + using (ILoggerFactory loggerFactory = CreateLoggerFactory()) { ILogger logger = loggerFactory.CreateLogger(); - - var request = new HttpRequestMessage(httpMethod, requestUrl) - { - Content = new StringContent(BogusGenerator.Lorem.Paragraph()) - }; var statusCode = BogusGenerator.PickRandom(); + DateTimeOffset startTime = DateTimeOffset.Now; var duration = BogusGenerator.Date.Timespan(); Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogHttpDependency(request, statusCode, DateTimeOffset.UtcNow, duration, telemetryContext); + logger.LogHttpDependency(request, statusCode, startTime, duration, dependencyId, telemetryContext); } // Assert - var requestUri = new Uri(requestUrl); using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetDependencyEventsAsync(ApplicationId); + EventsResults results = await client.Events.GetDependencyEventsAsync(ApplicationId, PastHalfHourTimeSpan); Assert.NotEmpty(results.Value); - Assert.Contains(results.Value, result => + AssertX.Any(results.Value, result => { - return result.Dependency.Type == DependencyType - && result.Dependency.Target == requestUri.Host - && result.Dependency.Name == $"{httpMethod} {requestUri.AbsolutePath}" - && result.Cloud.RoleName == componentName; + Assert.Equal(DependencyType, result.Dependency.Type); + Assert.Equal(request.Host.Host, result.Dependency.Target); + Assert.Equal($"{httpMethod} {request.Path}", result.Dependency.Name); + Assert.Equal(dependencyId, result.Dependency.Id); }); }); } - AssertX.Any(GetLogEventsFromMemory(), logEvent => { - StructureValue logEntry = logEvent.Properties.GetAsStructureValue(ContextProperties.DependencyTracking.DependencyLogEntry); - Assert.NotNull(logEntry); - - var actualDependencyType = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyType)); - Assert.Equal(DependencyType, actualDependencyType.Value.ToDecentString(), true); - - var actualDependencyName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyName)); - Assert.Equal($"{httpMethod} {requestUri.AbsolutePath}", actualDependencyName.Value.ToDecentString()); - - var actualTargetName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.TargetName)); - Assert.Equal(requestUri.Host, actualTargetName.Value.ToDecentString()); - - Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.Context)); - }); + AssertSerilogLogProperties(httpMethod, request.Host.Host, request.Path.Value); } private HttpMethod GenerateHttpMethod() @@ -152,5 +125,36 @@ private HttpMethod GenerateHttpMethod() HttpMethod.Put, HttpMethod.Trace); } + private static HttpRequest CreateStubRequest(HttpMethod method, string host, string path, string scheme) + { + var stubRequest = new Mock(); + stubRequest.Setup(request => request.Method).Returns(method.ToString()); + stubRequest.Setup(request => request.Host).Returns(new HostString(host)); + stubRequest.Setup(request => request.Path).Returns(path); + stubRequest.Setup(req => req.Scheme).Returns(scheme); + + return stubRequest.Object; + } + + private void AssertSerilogLogProperties(HttpMethod httpMethod, string host, string path) + { + IEnumerable logEvents = GetLogEventsFromMemory(); + AssertX.Any(logEvents, logEvent => + { + StructureValue logEntry = logEvent.Properties.GetAsStructureValue(ContextProperties.DependencyTracking.DependencyLogEntry); + Assert.NotNull(logEntry); + + LogEventProperty actualDependencyType = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyType)); + Assert.Equal(DependencyType, actualDependencyType.Value.ToDecentString(), true); + + LogEventProperty actualDependencyName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.DependencyName)); + Assert.Equal($"{httpMethod} {path}", actualDependencyName.Value.ToDecentString()); + + LogEventProperty actualTargetName = Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.TargetName)); + Assert.Equal(host, actualTargetName.Value.ToDecentString()); + + Assert.Single(logEntry.Properties, prop => prop.Name == nameof(DependencyLogEntry.Context)); + }); + } } } \ No newline at end of file diff --git a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs index fea6ac35..958959fc 100644 --- a/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs +++ b/src/Arcus.Observability.Tests.Unit/Extensions/TestLoggerExtensions.cs @@ -35,7 +35,7 @@ public static DependencyLogEntry GetMessageAsDependency(this TestLogger logger) "Cannot parse the written message as a telemetry dependency because no log message was written to this test logger"); } - const string pattern = @"^(?[\w\s]+) (?[\w\.\/\/:\-]+)? (?[\w\s\-\,\/]+)? named (?[\w\s\.\/\/:\-]+)? with ID (?[\w\s\-]*)? in (?(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(IsSuccessful: (?(True|False)) - ResultCode: (?\d*) - Context: \{(?((\[\w+, \w+\])(; \[[\w\-]+, \w+\])*))\}\)$"; + const string pattern = @"^(?[\w\s]+) (?[\w\s\.\/\/:\-]+)? (?[\w\s\-\,\/]+)? named (?[\w\s\.\/\/:\-]+)? with ID (?[\w\s\-]*)? in (?(\d{1}\.)?\d{2}:\d{2}:\d{2}\.\d{7}) at (?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{7} \+\d{2}:\d{2}) \(IsSuccessful: (?(True|False)) - ResultCode: (?\d*) - Context: \{(?((\[\w+, \w+\])(; \[[\w\-]+, \w+\])*))\}\)$"; Match match = Regex.Match(logger.WrittenMessage, pattern); string dependencyType = match.GetGroupValue("dependencytype"); diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpDependencyLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpDependencyLoggingTests.cs index 1ef8623c..02e150e6 100644 --- a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpDependencyLoggingTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpDependencyLoggingTests.cs @@ -2,8 +2,11 @@ using System.Net; using System.Net.Http; using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; using Bogus; +using Microsoft.AspNetCore.Http; using Microsoft.Extensions.Logging; +using Moq; using Xunit; namespace Arcus.Observability.Tests.Unit.Telemetry.Logging @@ -11,17 +14,17 @@ namespace Arcus.Observability.Tests.Unit.Telemetry.Logging [Trait("Category", "Unit")] public class HttpDependencyLoggingTests { - private readonly Faker _bogusGenerator = new Faker(); + private static readonly Faker BogusGenerator = new Faker(); [Fact] - public void LogHttpDependency_ValidArguments_Succeeds() + public void LogHttpDependencyWithRequestMessage_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.Url()); - var statusCode = _bogusGenerator.PickRandom(); - DateTimeOffset startTime = _bogusGenerator.Date.PastOffset(); - var duration = _bogusGenerator.Date.Timespan(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.Url()); + var statusCode = BogusGenerator.PickRandom(); + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); + var duration = BogusGenerator.Date.Timespan(); // Act logger.LogHttpDependency(request, statusCode, startTime, duration); @@ -42,14 +45,99 @@ public void LogHttpDependency_ValidArguments_Succeeds() Assert.Contains("Http " + dependencyName, logMessage); } + [Fact] + public void LogHttpDependencyWithRequestMessageWithDependencyId_ValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.Url()); + var statusCode = BogusGenerator.PickRandom(); + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); + var duration = BogusGenerator.Date.Timespan(); + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act + logger.LogHttpDependency(request, statusCode, startTime, duration, dependencyId); + + // Assert + var logMessage = logger.WrittenMessage; + Assert.Contains(TelemetryType.Dependency.ToString(), 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(FormatSpecifiers.InvariantTimestampFormat), logMessage); + var isSuccessful = (int)statusCode >= 200 && (int)statusCode < 300; + Assert.Contains($"Successful: {isSuccessful}", logMessage); + Uri requestUri = request.RequestUri; + HttpMethod requestMethod = request.Method; + string dependencyName = $"{requestMethod} {requestUri.AbsolutePath}"; + Assert.Contains("Http " + dependencyName, logMessage); + Assert.Contains(dependencyId, logMessage); + } + + [Fact] + public void LogHttpDependencyWithRequest_ValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var requestUri = new Uri("https://arcus.test/unit"); + HttpRequest request = CreateStubRequest(HttpMethod.Get, requestUri.Host, requestUri.AbsolutePath, requestUri.Scheme); + + var statusCode = HttpStatusCode.BadRequest; + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); + var duration = BogusGenerator.Date.Timespan(); + + // Act + logger.LogHttpDependency(request, statusCode, startTime, duration); + + // Assert + DependencyLogEntry dependency = logger.GetMessageAsDependency(); + Assert.Contains("Http", dependency.DependencyType); + Assert.Contains(request.Method, logger.WrittenMessage); + Assert.Contains(request.Path, dependency.DependencyName); + Assert.Equal(request.Host.Host, dependency.TargetName); + Assert.Equal(duration, dependency.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), dependency.StartTime); + Assert.False(dependency.IsSuccessful); + } + + [Fact] + public void LogHttpDependencyWithRequestWithDependencyId_ValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var requestUri = new Uri("https://arcus.test/unit"); + HttpRequest request = CreateStubRequest(HttpMethod.Get, requestUri.Host, requestUri.AbsolutePath, requestUri.Scheme); + + var statusCode = HttpStatusCode.OK; + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); + var duration = BogusGenerator.Date.Timespan(); + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act + logger.LogHttpDependency(request, statusCode, startTime, duration, dependencyId); + + // Assert + DependencyLogEntry dependency = logger.GetMessageAsDependency(); + Assert.Contains("Http", dependency.DependencyType); + Assert.Contains(request.Method, logger.WrittenMessage); + Assert.Contains(request.Path, dependency.DependencyName); + Assert.Equal(request.Host.Host, dependency.TargetName); + Assert.Equal(duration, dependency.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), dependency.StartTime); + Assert.True(dependency.IsSuccessful); + Assert.Equal(dependencyId, dependency.DependencyId); + } + [Fact] public void LogHttpDependency_WithNegativeDuration_Fails() { // Arrange var logger = new TestLogger(); - var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.Url()); - var statusCode = _bogusGenerator.PickRandom(); - DateTimeOffset startTime = _bogusGenerator.Date.PastOffset(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.Url()); + var statusCode = BogusGenerator.PickRandom(); + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); TimeSpan duration = TimeSpanGenerator.GeneratePositiveDuration().Negate(); // Act / Assert @@ -62,9 +150,9 @@ public void LogHttpDependency_NoRequestWasSpecified_ThrowsException() // Arrange var logger = new TestLogger(); HttpRequestMessage request = null; - var statusCode = _bogusGenerator.PickRandom(); - DateTimeOffset startTime = _bogusGenerator.Date.PastOffset(); - var duration = _bogusGenerator.Date.Timespan(); + var statusCode = BogusGenerator.PickRandom(); + DateTimeOffset startTime = BogusGenerator.Date.PastOffset(); + var duration = BogusGenerator.Date.Timespan(); // Act & Arrange Assert.Throws(() => logger.LogHttpDependency(request, statusCode, startTime, duration)); @@ -75,8 +163,8 @@ public void LogHttpDependencyWithDependencyMeasurement_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.UrlWithPath()); - var statusCode = _bogusGenerator.PickRandom(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.UrlWithPath()); + var statusCode = BogusGenerator.PickRandom(); var measurement = DependencyMeasurement.Start(); DateTimeOffset startTime = measurement.StartTime; measurement.Dispose(); @@ -107,8 +195,8 @@ public void LogHttpDependencyWithDurationMeasurement_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.UrlWithPath()); - var statusCode = _bogusGenerator.PickRandom(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.UrlWithPath()); + var statusCode = BogusGenerator.PickRandom(); var measurement = DurationMeasurement.Start(); DateTimeOffset startTime = measurement.StartTime; measurement.Dispose(); @@ -135,30 +223,218 @@ public void LogHttpDependencyWithDurationMeasurement_ValidArguments_Succeeds() } [Fact] - public void LogHttpDependencyWithDurationMeasurement_WithoutRequest_Fails() + public void LogHttpDependencyWithDurationMeasurementWithDependencyId_ValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.UrlWithPath()); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + DateTimeOffset startTime = measurement.StartTime; + measurement.Dispose(); + TimeSpan duration = measurement.Elapsed; + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act + logger.LogHttpDependency(request, statusCode, measurement, dependencyId); + + // Assert + string logMessage = logger.WrittenMessage; + Assert.Contains(TelemetryType.Dependency.ToString(), 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(FormatSpecifiers.InvariantTimestampFormat), logMessage); + Assert.Contains(duration.ToString(), logMessage); + bool isSuccessful = (int)statusCode >= 200 && (int)statusCode < 300; + Assert.Contains($"Successful: {isSuccessful}", logMessage); + Uri requestUri = request.RequestUri; + HttpMethod requestMethod = request.Method; + string dependencyName = $"{requestMethod} {requestUri?.AbsolutePath}"; + Assert.Contains("Http " + dependencyName, logMessage); + Assert.Contains(dependencyId, logMessage); + } + + [Fact] + public void LogHttpDependencyWithRequestWithDurationMeasurement_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - var statusCode = _bogusGenerator.PickRandom(); + var requestUri = new Uri("https://arcus.test/unit"); + HttpRequest request = CreateStubRequest(HttpMethod.Get, requestUri.Host, requestUri.AbsolutePath, requestUri.Scheme); + + var statusCode = HttpStatusCode.BadRequest; var measurement = DurationMeasurement.Start(); + DateTimeOffset startTime = measurement.StartTime; measurement.Dispose(); + TimeSpan duration = measurement.Elapsed; + + // Act + logger.LogHttpDependency(request, statusCode, measurement); + + // Assert + DependencyLogEntry dependency = logger.GetMessageAsDependency(); + Assert.Contains("Http", dependency.DependencyType); + Assert.Contains(request.Method, logger.WrittenMessage); + Assert.EndsWith(request.Path, dependency.DependencyName); + Assert.Equal(request.Host.Host, dependency.TargetName); + Assert.Equal(duration, dependency.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), dependency.StartTime); + Assert.False(dependency.IsSuccessful); + } + + [Fact] + public void LogHttpDependencyWithRequestWithDurationMeasurementWithDependencyId_ValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var requestUri = new Uri("https://arcus.test/unit"); + HttpRequest request = CreateStubRequest(HttpMethod.Get, requestUri.Host, requestUri.AbsolutePath, requestUri.Scheme); + + var statusCode = HttpStatusCode.BadRequest; + var measurement = DurationMeasurement.Start(); + DateTimeOffset startTime = measurement.StartTime; + measurement.Dispose(); + TimeSpan duration = measurement.Elapsed; + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act + logger.LogHttpDependency(request, statusCode, measurement, dependencyId); + + // Assert + DependencyLogEntry dependency = logger.GetMessageAsDependency(); + Assert.Contains("Http", dependency.DependencyType); + Assert.Equal(dependencyId, dependency.DependencyId); + Assert.Contains(request.Method, logger.WrittenMessage); + Assert.Contains(request.Path, dependency.DependencyName); + Assert.Equal(request.Host.Host, dependency.TargetName); + Assert.Equal(duration, dependency.Duration); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), dependency.StartTime); + Assert.False(dependency.IsSuccessful); + } + + [Fact] + public void LogHttpDependencyWithRequestMessageWithDurationMeasurement_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request: (HttpRequestMessage) null, statusCode, measurement)); + } + + [Fact] + public void LogHttpDependencyWithRequestMessageWithDurationMeasurementWithDependencyId_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request: (HttpRequestMessage) null, statusCode, measurement, dependencyId)); + } + + [Fact] + public void LogHttpDependencyWithRequestWithDurationMeasurement_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request: (HttpRequest) null, statusCode, measurement)); + } + + [Fact] + public void LogHttpDependencyWithRequestWithDurationMeasurementWithDependencyId_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request: (HttpRequest) null, statusCode, measurement, dependencyId)); + } + + [Fact] + public void LogHttpDependencyWithRequestMessageWithDurationMeasurement_WithoutMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.UrlWithPath()); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request, statusCode, measurement: (DurationMeasurement)null)); + } + + [Fact] + public void LogHttpDependencyWithRequestMessageWithDurationMeasurementWithDependencyId_WithoutMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + var request = new HttpRequestMessage(HttpMethod.Get, BogusGenerator.Internet.UrlWithPath()); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string dependencyId = BogusGenerator.Lorem.Word(); // Act / Assert - Assert.ThrowsAny(() => logger.LogHttpDependency(request: null, statusCode, measurement)); + Assert.ThrowsAny(() => logger.LogHttpDependency(request, statusCode, measurement: null, dependencyId)); } [Fact] - public void LogHttpDependencyWithDurationMeasurement_WithoutMeasurement_Fails() + public void LogHttpDependencyWithRequestWithDurationMeasurement_WithoutMeasurement_Fails() { // Arrange var logger = new TestLogger(); - var request = new HttpRequestMessage(HttpMethod.Get, _bogusGenerator.Internet.UrlWithPath()); - var statusCode = _bogusGenerator.PickRandom(); + HttpRequest request = CreateStubRequest(HttpMethod.Get, "host", "/path", "http"); + var statusCode = BogusGenerator.PickRandom(); var measurement = DurationMeasurement.Start(); measurement.Dispose(); // Act / Assert Assert.ThrowsAny(() => logger.LogHttpDependency(request, statusCode, measurement: (DurationMeasurement)null)); } + + [Fact] + public void LogHttpDependencyWithRequestWithDurationMeasurementWithDependencyId_WithoutMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + HttpRequest request = CreateStubRequest(HttpMethod.Get, "host", "/path", "http"); + var statusCode = BogusGenerator.PickRandom(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string dependencyId = BogusGenerator.Lorem.Word(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogHttpDependency(request, statusCode, measurement: null, dependencyId)); + } + + private static HttpRequest CreateStubRequest(HttpMethod method, string host, string path, string scheme) + { + var stubRequest = new Mock(); + stubRequest.Setup(request => request.Method).Returns(method.ToString()); + stubRequest.Setup(request => request.Host).Returns(new HostString(host)); + stubRequest.Setup(request => request.Path).Returns(path); + stubRequest.Setup(req => req.Scheme).Returns(scheme); + + return stubRequest.Object; + } } }