From e192925f10be88f51d2151eacac9b2fd3df47303 Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Fri, 26 Aug 2022 07:54:12 +0200 Subject: [PATCH] feat: track http request data in http trigger (#448) * feat: track http request data in http trigger * pr-fix: better defect detection * pr-fix: timeout * Update docs/preview/03-Features/writing-different-telemetry-types.md Co-authored-by: Frederik Gheysels * pr-fix: more stable metric telemetry unit tests Co-authored-by: Frederik Gheysels --- .../writing-different-telemetry-types.md | 46 +- ...ervability.Telemetry.AzureFunctions.csproj | 5 + .../ILoggerHttpRequestDataExtensions.cs | 139 ++++++ .../Extensions/ILoggerRequestExtensions.cs | 5 +- ...cus.Observability.Tests.Integration.csproj | 1 + .../ApplicationInsightsSinkTests.cs | 24 +- .../HttpRequestDataTests.cs | 87 ++++ .../Sinks/ApplicationInsights/RequestTests.cs | 2 +- .../Logging/HttpRequestDataLoggingTests.cs | 413 ++++++++++++++++++ .../Logging/HttpRequestLoggingTests.cs | 8 +- .../Telemetry/Logging/MetricLoggingTests.cs | 8 +- 11 files changed, 721 insertions(+), 17 deletions(-) create mode 100644 src/Arcus.Observability.Telemetry.AzureFunctions/Extensions/ILoggerHttpRequestDataExtensions.cs create mode 100644 src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpRequestDataTests.cs create mode 100644 src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestDataLoggingTests.cs diff --git a/docs/preview/03-Features/writing-different-telemetry-types.md b/docs/preview/03-Features/writing-different-telemetry-types.md index a749312e..aaca6c1b 100644 --- a/docs/preview/03-Features/writing-different-telemetry-types.md +++ b/docs/preview/03-Features/writing-different-telemetry-types.md @@ -555,7 +555,7 @@ using (var measurement = DurationMeasurement.Start()) We provide overloads to configure the Azure EventHubs consumer group (default: `$Default`) and a functional operation name (default: `Process`). -### Incoming HTTP requests +### Incoming HTTP requests in API's 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** @@ -593,6 +593,50 @@ 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 HTTP requests in Azure Function HTTP trigger +Requests allow you to keep track of the HTTP requests that are performed against your Azure Function HTTP trigger and what the response was that was sent out. + +**Installation** + +For isolated Azure Functions, you'll have to install an additional package if you want to track the `HttpRequestData`: + +```shell +PM > Install-Package Arcus.Observability.Telemetry.AzureFunctions +``` + +**Example** + +Here is how you can keep track of requests: + +```csharp +using Sytem.Net; +using Microsoft.Extensions.Logging; + +public async Task Run( + [HttpTrigger(AuthorizationLevel.Function, "post", Route = "v1/order")] HttpRequestData request, + FunctionContext executionContext) +{ + var statusCode = default(HttpStatusCode); + + // Start tracking request. + using (var measurement = DurationMeasurement.Start()) + { + try + { + // Processing... + + statusCode = HttpStatusCode.Ok; + return request.CreateResponse(statusCode) + } + finally + { + logger.LogRequest(request, statusCode, measurement); + // Output: {"RequestMethod": "POST", "RequestHost": "http://localhost:5000/", "RequestUri": "http://localhost:5000/v1/order", "ResponseStatusCode": 200, "RequestDuration": "00:00:00.0191554", "RequestTime": "03/23/2020 10:12:55 +00:00", "Context": {}} + } + } +} +``` + ### 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. diff --git a/src/Arcus.Observability.Telemetry.AzureFunctions/Arcus.Observability.Telemetry.AzureFunctions.csproj b/src/Arcus.Observability.Telemetry.AzureFunctions/Arcus.Observability.Telemetry.AzureFunctions.csproj index 8568ecc8..99f4120f 100644 --- a/src/Arcus.Observability.Telemetry.AzureFunctions/Arcus.Observability.Telemetry.AzureFunctions.csproj +++ b/src/Arcus.Observability.Telemetry.AzureFunctions/Arcus.Observability.Telemetry.AzureFunctions.csproj @@ -26,6 +26,7 @@ + @@ -33,4 +34,8 @@ + + + + \ No newline at end of file diff --git a/src/Arcus.Observability.Telemetry.AzureFunctions/Extensions/ILoggerHttpRequestDataExtensions.cs b/src/Arcus.Observability.Telemetry.AzureFunctions/Extensions/ILoggerHttpRequestDataExtensions.cs new file mode 100644 index 00000000..ee6a88f8 --- /dev/null +++ b/src/Arcus.Observability.Telemetry.AzureFunctions/Extensions/ILoggerHttpRequestDataExtensions.cs @@ -0,0 +1,139 @@ +using System; +using System.Collections.Generic; +using System.Net; +using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; +using GuardNet; +#if NET6_0 +using Microsoft.Azure.Functions.Worker.Http; +#endif + +// ReSharper disable once CheckNamespace +namespace Microsoft.Extensions.Logging +{ +#if NET6_0 + /// + /// Telemetry extensions on the instance to write Application Insights compatible log messages. + /// + // ReSharper disable once InconsistentNaming + public static class ILoggerRequestExtensions + { + /// + /// Logs an HTTP request. + /// + /// The logger to track the telemetry. + /// The incoming HTTP request that was processed. + /// The HTTP status code returned by the service. + /// The instance to measure the duration of the HTTP request. + /// The context that provides more insights on the tracked HTTP request. + /// + /// Thrown when the , , or the is null. + /// + public static void LogRequest( + this ILogger logger, + HttpRequestData request, + HttpStatusCode responseStatusCode, + 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 instance to track a HTTP request"); + Guard.NotNull(measurement, nameof(measurement), "Requires an measurement instance to time the duration of the HTTP request"); + + LogRequest(logger, request, responseStatusCode, measurement.StartTime, measurement.Elapsed, context); + } + + /// + /// Logs an HTTP request. + /// + /// The logger to track the telemetry. + /// The incoming HTTP request that was processed. + /// The HTTP status code returned by the service. + /// The time when the HTTP request was received. + /// The duration of the HTTP request processing operation. + /// The context that provides more insights on the tracked HTTP request. + /// Thrown when the or the is null. + /// Thrown when the is a negative time range. + public static void LogRequest( + this ILogger logger, + HttpRequestData request, + HttpStatusCode responseStatusCode, + 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 instance to track a HTTP request"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation"); + + LogRequest(logger, request, responseStatusCode, operationName: null, startTime, duration, context); + } + + /// + /// Logs an HTTP request. + /// + /// The logger to track the telemetry. + /// The incoming HTTP request that was processed. + /// The HTTP status code returned by the service. + /// The name of the operation of the request. + /// The instance to measure the duration of the HTTP request. + /// The context that provides more insights on the tracked HTTP request. + /// + /// Thrown when the , , or the is null. + /// + public static void LogRequest( + this ILogger logger, + HttpRequestData request, + HttpStatusCode responseStatusCode, + string operationName, + 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 instance to track a HTTP request"); + Guard.NotNull(measurement, nameof(measurement), "Requires an measurement instance to time the duration of the HTTP request"); + + LogRequest(logger, request, responseStatusCode, operationName, measurement.StartTime, measurement.Elapsed, context); + } + + /// + /// Logs an HTTP request. + /// + /// The logger to track the telemetry. + /// The incoming HTTP request that was processed. + /// The HTTP status code returned by the service. + /// The name of the operation of the request. + /// The time when the HTTP request was received. + /// The duration of the HTTP request processing operation. + /// The context that provides more insights on the tracked HTTP request. + /// Thrown when the or the is null. + /// Thrown when the is a negative time range. + public static void LogRequest( + this ILogger logger, + HttpRequestData request, + HttpStatusCode responseStatusCode, + string operationName, + 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 instance to track a HTTP request"); + Guard.NotLessThan(duration, TimeSpan.Zero, nameof(duration), "Requires a positive time duration of the request operation"); + + context = context ?? new Dictionary(); + + logger.LogWarning(MessageFormats.RequestFormat, + RequestLogEntry.CreateForHttpRequest(request.Method, + request.Url.Scheme, + request.Url.Host, + request.Url.AbsolutePath, + operationName, + (int) responseStatusCode, + startTime, + duration, + context)); + } + } +#endif +} diff --git a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerRequestExtensions.cs b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerRequestExtensions.cs index c6c4b22a..a414c417 100644 --- a/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerRequestExtensions.cs +++ b/src/Arcus.Observability.Telemetry.Core/Extensions/ILoggerRequestExtensions.cs @@ -327,10 +327,7 @@ public static partial class ILoggerExtensions /// the 's scheme contains whitespace, /// the 's host contains whitespace, /// - /// - /// Thrown when the 's status code is outside the 0-999 inclusively, - /// the is a negative time range. - /// + /// Thrown when the is a negative time range. public static void LogRequest( this ILogger logger, HttpRequestMessage request, diff --git a/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj b/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj index 9e609977..302553a9 100644 --- a/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj +++ b/src/Arcus.Observability.Tests.Integration/Arcus.Observability.Tests.Integration.csproj @@ -23,6 +23,7 @@ + diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs index 4a331734..bae1bd00 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs @@ -138,7 +138,7 @@ protected async Task RetryAssertUntilTelemetryShouldBeAvailableAsync(Func assertion, TimeSpan timeout) { + Exception lastException = null; PolicyResult result = await Policy.TimeoutAsync(timeout) .WrapAsync(Policy.Handle() .WaitAndRetryForeverAsync(index => TimeSpan.FromSeconds(1))) - .ExecuteAndCaptureAsync(assertion); + .ExecuteAndCaptureAsync(async () => + { + try + { + await assertion(); + } + catch (Exception exception) + { + lastException = exception; + throw; + } + }); if (result.Outcome is OutcomeType.Failure) { if (result.FinalException is TimeoutRejectedException - && result.FinalException.InnerException != null) + && result.FinalException.InnerException != null + && result.FinalException.InnerException is not TaskCanceledException) { throw result.FinalException.InnerException; } + if (lastException != null) + { + throw lastException; + } + throw result.FinalException; } } diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpRequestDataTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpRequestDataTests.cs new file mode 100644 index 00000000..231ea95f --- /dev/null +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpRequestDataTests.cs @@ -0,0 +1,87 @@ +using System; +using System.Collections.Generic; +using System.Net; +using System.Net.Http; +using System.Threading.Tasks; +using Arcus.Observability.Correlation; +using Microsoft.Azure.ApplicationInsights.Query.Models; +using Microsoft.Azure.Functions.Worker; +using Microsoft.Azure.Functions.Worker.Http; +using Microsoft.Extensions.Logging; +using Moq; +using Serilog; +using Xunit; +using Xunit.Abstractions; + +namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights +{ + public class HttpRequestDataTests : ApplicationInsightsSinkTests + { + public HttpRequestDataTests(ITestOutputHelper outputWriter) : base(outputWriter) + { + } + + [Fact] + public async Task LogRequest_SinksToApplicationInsightsWithCorrelation_ResultsInRequestTelemetry() + { + // Arrange + var correlation = new CorrelationInfo($"operation-{Guid.NewGuid()}", $"transaction-{Guid.NewGuid()}", $"parent-{Guid.NewGuid()}"); + var accessor = new DefaultCorrelationInfoAccessor(); + accessor.SetCorrelationInfo(correlation); + LoggerConfiguration.Enrich.WithCorrelationInfo(accessor); + + var operationName = "sampleoperation"; + HttpMethod httpMethod = GenerateHttpMethod(); + var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); + HttpRequestData request = CreateStubRequest(httpMethod, requestUri); + var statusCode = BogusGenerator.PickRandom(); + + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = DateTimeOffset.Now; + Dictionary telemetryContext = CreateTestTelemetryContext(); + + // Act + Logger.LogRequest(request, statusCode, operationName, startTime, duration, telemetryContext); + + // Assert + await RetryAssertUntilTelemetryShouldBeAvailableAsync(async client => + { + EventsRequestResult[] results = await client.GetRequestsAsync(); + AssertX.Any(results, result => + { + Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url); + Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode); + Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); + + Assert.Equal(correlation.OperationId, result.Request.Id); + Assert.Equal(correlation.TransactionId, result.Operation.Id); + Assert.Equal(correlation.OperationParentId, result.Operation.ParentId); + }); + }); + } + + private HttpMethod GenerateHttpMethod() + { + return BogusGenerator.PickRandom( + HttpMethod.Get, + HttpMethod.Delete, + HttpMethod.Head, + HttpMethod.Options, + HttpMethod.Patch, + HttpMethod.Post, + HttpMethod.Put, + HttpMethod.Trace); + } + + private static HttpRequestData CreateStubRequest(HttpMethod method, Uri requestUri) + { + var context = Mock.Of(); + + var stub = new Mock(context); + stub.Setup(s => s.Method).Returns(method.Method); + stub.Setup(s => s.Url).Returns(requestUri); + + return stub.Object; + } + } +} diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs index 05adb81b..6f4b153e 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs @@ -21,7 +21,7 @@ public RequestTests(ITestOutputHelper outputWriter) : base(outputWriter) { } - [Fact] + [Fact] public async Task LogRequest_SinksToApplicationInsightsWithCorrelation_ResultsInRequestTelemetry() { // Arrange diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestDataLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestDataLoggingTests.cs new file mode 100644 index 00000000..967e5722 --- /dev/null +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestDataLoggingTests.cs @@ -0,0 +1,413 @@ +using System; +using System.Collections.Generic; +using System.Net; +using System.Net.Http; +using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Core.Logging; +using Bogus; +#if NET6_0 +using Microsoft.Azure.Functions.Worker; +using Microsoft.Azure.Functions.Worker.Http; +#endif +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Arcus.Observability.Tests.Unit.Telemetry.Logging +{ +#if NET6_0 + public class HttpRequestDataDataLoggingTests + { + private static readonly Faker BogusGenerator = new Faker(); + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_ValidArgumentsIncludingResponse_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogRequest(stubRequest, statusCode, measurement, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.StartsWith(scheme, entry.RequestHost); + Assert.EndsWith(host, entry.RequestHost); + Assert.Equal(path, entry.RequestUri); + Assert.Equal($"{method} {path}", entry.OperationName); + Assert.Equal((int) statusCode, entry.ResponseStatusCode); + Assert.Equal(measurement.Elapsed, entry.RequestDuration); + Assert.Equal(measurement.StartTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(value, Assert.Contains(key, entry.Context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = (int)BogusGenerator.PickRandom(); + + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(request: null, statusCode, measurement)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithoutMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, measurement: null)); + } + + [Theory] + [InlineData(int.MinValue, 0)] + [InlineData(999, int.MaxValue)] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithInvalidStatusCode_Fails(int min, int max) + { + // Arrange + var logger = new TestLogger(); + var statusCode = (HttpStatusCode) BogusGenerator.Random.Int(min, max); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, measurement)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationStartTime_WithValidArgumentsWithResponse_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogRequest(stubRequest, statusCode, startTime, duration, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.StartsWith(scheme, entry.RequestHost); + Assert.EndsWith(host, entry.RequestHost); + Assert.Equal(path, entry.RequestUri); + Assert.Equal($"{method} {path}", entry.OperationName); + Assert.Equal(duration, entry.RequestDuration); + Assert.Equal((int) statusCode, entry.ResponseStatusCode); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(value, Assert.Contains(key, entry.Context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationStartTime_WithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestData) null, statusCode, startTime, duration, context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationStartTime_WithNegativeDuration_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + TimeSpan duration = TimeSpanGenerator.GeneratePositiveDuration().Negate(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, startTime, duration, context)); + } + + [Theory] + [InlineData(int.MinValue, 0)] + [InlineData(999, int.MaxValue)] + public void LogRequestWithStatusCodeWithDurationStartTime_WithInvalidStatusCode_Fails(int min, int max) + { + // Arrange + var logger = new TestLogger(); + var statusCode = (HttpStatusCode) BogusGenerator.Random.Int(min, max); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + TimeSpan duration = TimeSpanGenerator.GeneratePositiveDuration().Negate(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, startTime, duration, context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithOperationNameValidArgumentsIncludingResponse_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + string operationName = BogusGenerator.Lorem.Word(); + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogRequest(stubRequest, statusCode, operationName, measurement, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.StartsWith(scheme, entry.RequestHost); + Assert.EndsWith(host, entry.RequestHost); + Assert.Equal(path, entry.RequestUri); + Assert.Equal(operationName, entry.OperationName); + Assert.Equal(measurement.Elapsed, entry.RequestDuration); + Assert.Equal(measurement.StartTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(value, Assert.Contains(key, entry.Context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithOperationNameWithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = (int)BogusGenerator.PickRandom(); + + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + string operationName = BogusGenerator.Lorem.Word(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(request: null, statusCode, operationName, measurement)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithOperationNameWithoutMeasurement_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + string operationName = BogusGenerator.Lorem.Word(); + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, operationName, measurement: null)); + } + + [Theory] + [InlineData(int.MinValue, 0)] + [InlineData(999, int.MaxValue)] + public void LogRequestWithStatusCodeWithDurationMeasurement_WithOperationNameWithInvalidStatusCode_Fails(int min, int max) + { + // Arrange + var logger = new TestLogger(); + var statusCode = (HttpStatusCode) BogusGenerator.Random.Int(min, max); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + + string operationName = BogusGenerator.Lorem.Word(); + var measurement = DurationMeasurement.Start(); + measurement.Dispose(); + + // Act / Assert + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, operationName, measurement)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationStartTime_WithOperationNameWithValidArguments_Succeeds() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + string operationName = BogusGenerator.Lorem.Word(); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + logger.LogRequest(stubRequest, statusCode, operationName, startTime, duration, context); + + // Assert + RequestLogEntry entry = logger.GetMessageAsRequest(); + Assert.StartsWith(scheme, entry.RequestHost); + Assert.EndsWith(host, entry.RequestHost); + Assert.Equal(path, entry.RequestUri); + Assert.Equal(operationName, entry.OperationName); + Assert.Equal(duration, entry.RequestDuration); + Assert.Equal((int) statusCode, entry.ResponseStatusCode); + Assert.Equal(startTime.ToString(FormatSpecifiers.InvariantTimestampFormat), entry.RequestTime); + Assert.Equal(value, Assert.Contains(key, entry.Context)); + } + + [Fact] + public void LogRequestWithStatusCodeWithDurationStartTime_WithOperationNameWithoutRequest_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + string operationName = BogusGenerator.Lorem.Word(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestData) null, statusCode, operationName, startTime, duration, context)); + } + + [Theory] + [InlineData(int.MinValue, 0)] + [InlineData(999, int.MaxValue)] + public void LogRequestWithStatusCodeWithDurationStartTime_WithOperationNameWithInvalidStatusCode_Fails(int min, int max) + { + // Arrange + var logger = new TestLogger(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + HttpMethod method = HttpMethod.Post; + string operationName = BogusGenerator.Lorem.Word(); + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + var statusCode = (HttpStatusCode) BogusGenerator.Random.Int(min, max); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, operationName, startTime, duration, context)); + } + + [Fact] + public void LogRequestWithStatusCodeDurationStartTime_WithOperationNameWithNegativeDuration_Fails() + { + // Arrange + var logger = new TestLogger(); + var statusCode = BogusGenerator.PickRandom(); + var path = $"/{BogusGenerator.Lorem.Word()}"; + string host = BogusGenerator.Lorem.Word(); + var scheme = "https"; + string operationName = BogusGenerator.Lorem.Word(); + HttpMethod method = HttpMethod.Post; + + HttpRequestData stubRequest = CreateStubRequest(method, host, path, scheme); + TimeSpan duration = TimeSpanGenerator.GeneratePositiveDuration().Negate(); + DateTimeOffset startTime = BogusGenerator.Date.RecentOffset(); + + string key = BogusGenerator.Lorem.Word(); + string value = BogusGenerator.Lorem.Word(); + var context = new Dictionary { [key] = value }; + + // Act + Assert.ThrowsAny(() => logger.LogRequest(stubRequest, statusCode, operationName, startTime, duration, context)); + } + + private static HttpRequestData CreateStubRequest(HttpMethod method, string host, string path, string scheme) + { + var context = Mock.Of(); + + var stub = new Mock(context); + stub.Setup(s => s.Method).Returns(method.Method); + stub.Setup(s => s.Url).Returns(new Uri(scheme + "://" + host + path)); + + return stub.Object; + } + } +#endif +} diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestLoggingTests.cs index eaf91703..89526832 100644 --- a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestLoggingTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/HttpRequestLoggingTests.cs @@ -1158,7 +1158,7 @@ public void LogRequestMessageWithStatusCodeWithDurationMeasurement_WithoutReques measurement.Dispose(); // Act / Assert - Assert.ThrowsAny(() => logger.LogRequest(request: null, statusCode, measurement)); + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestMessage) null, statusCode, measurement)); } [Fact] @@ -1220,7 +1220,7 @@ public void LogRequestMessageWithStatusCodeWithStartTime_WithoutRequest_Fails() DateTimeOffset startTime = _bogusGenerator.Date.RecentOffset(); // Act / Assert - Assert.ThrowsAny(() => logger.LogRequest(request: null, responseStatusCode: statusCode, startTime: startTime, duration: duration)); + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestMessage) null, responseStatusCode: statusCode, startTime: startTime, duration: duration)); } [Fact] @@ -1287,7 +1287,7 @@ public void LogRequestMessageWithStatusCodeWithOperationNameWithDurationMeasurem measurement.Dispose(); // Act / Assert - Assert.ThrowsAny(() => logger.LogRequest(request: null, statusCode, operationName, measurement)); + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestMessage) null, statusCode, operationName, measurement)); } [Fact] @@ -1352,7 +1352,7 @@ public void LogRequestMessageWithStatusCodeWithOperationNameWithStartTime_Withou DateTimeOffset startTime = _bogusGenerator.Date.RecentOffset(); // Act / Assert - Assert.ThrowsAny(() => logger.LogRequest(request: null, responseStatusCode: statusCode, operationName: operationName, startTime: startTime, duration: duration)); + Assert.ThrowsAny(() => logger.LogRequest(request: (HttpRequestMessage) null, responseStatusCode: statusCode, operationName: operationName, startTime: startTime, duration: duration)); } [Fact] diff --git a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/MetricLoggingTests.cs b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/MetricLoggingTests.cs index 32b8012a..28125b2e 100644 --- a/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/MetricLoggingTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Telemetry/Logging/MetricLoggingTests.cs @@ -18,11 +18,11 @@ public void LogMetric_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - string metricName = _bogusGenerator.Name.FullName(); + string metricName = _bogusGenerator.Lorem.Word(); double metricValue = _bogusGenerator.Random.Double(); // Act - logger.LogMetric(metricName, metricValue); + logger.LogMetric(metricName, metricValue, context: null); // Assert MetricLogEntry metric = logger.GetMessageAsMetric(); @@ -40,7 +40,7 @@ public void LogCustomMetric_ValidArguments_Succeeds() { // Arrange var logger = new TestLogger(); - string metricName = _bogusGenerator.Name.FullName(); + string metricName = _bogusGenerator.Lorem.Word(); double metricValue = _bogusGenerator.Random.Double(); // Act @@ -182,7 +182,7 @@ public void LogMetric_NoMetricNameWasSpecified_ThrowsException() double metricValue = _bogusGenerator.Random.Double(); // Act & Arrange - Assert.Throws(() => logger.LogMetric(metricName, metricValue)); + Assert.Throws(() => logger.LogMetric(metricName, metricValue, context: null)); } [Fact]