From 3b9c3a340b7e35a5b3174fc5cf90c792cd2d25bd Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Wed, 22 Jun 2022 09:41:56 +0200 Subject: [PATCH] feat: diff request & other correlation assignments (#411) * feat: diff request & other correlation assignments * pr-fix: revert unn test changes * pr-fix: update with correct correlation assertions * pr-fix: update with more stable exception integration tests * pr-fix: rm req id assert in az func docker test * pr-fix: exceptoin property format determination with both options --- .../ApplicationInsightsTelemetryConverter.cs | 17 +- .../Converters/CustomTelemetryConverter.cs | 29 +- .../DependencyTelemetryConverter.cs | 18 ++ .../Converters/EventTelemetryConverter.cs | 18 ++ .../Converters/ExceptionTelemetryConverter.cs | 32 ++- .../Converters/MetricTelemetryConverter.cs | 18 ++ .../Converters/OperationContextConverter.cs | 58 +++- .../Converters/RequestTelemetryConverter.cs | 21 +- .../Converters/TraceTelemetryConverter.cs | 23 +- .../ApplicationInsightsSinkTests.cs | 10 +- .../AzureFunctionsDockerTests.cs | 1 - .../Sinks/ApplicationInsights/EventTests.cs | 4 +- .../ApplicationInsights/ExceptionTests.cs | 14 +- .../HttpDependencyTests.cs | 58 ++++ .../Sinks/ApplicationInsights/RequestTests.cs | 181 +++--------- .../ServiceBusDependencyTests.cs | 57 ++++ .../ServiceBusRequestTests.cs | 57 ++++ ...licationInsightsTelemetryConverterTests.cs | 148 +++++++--- .../Serilog/CustomTelemetryConverterTests.cs | 47 ++++ .../Serilog/OperationContextConverterTests.cs | 264 ++++-------------- 20 files changed, 642 insertions(+), 433 deletions(-) create mode 100644 src/Arcus.Observability.Tests.Unit/Serilog/CustomTelemetryConverterTests.cs diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ApplicationInsightsTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ApplicationInsightsTelemetryConverter.cs index ea48dc88..55b3fa71 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ApplicationInsightsTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ApplicationInsightsTelemetryConverter.cs @@ -17,16 +17,21 @@ public class ApplicationInsightsTelemetryConverter : TelemetryConverterBase { private readonly RequestTelemetryConverter _requestTelemetryConverter; private readonly ExceptionTelemetryConverter _exceptionTelemetryConverter; - private readonly TraceTelemetryConverter _traceTelemetryConverter = new TraceTelemetryConverter(); - private readonly EventTelemetryConverter _eventTelemetryConverter = new EventTelemetryConverter(); - private readonly MetricTelemetryConverter _metricTelemetryConverter = new MetricTelemetryConverter(); - private readonly DependencyTelemetryConverter _dependencyTelemetryConverter = new DependencyTelemetryConverter(); + private readonly TraceTelemetryConverter _traceTelemetryConverter; + private readonly EventTelemetryConverter _eventTelemetryConverter; + private readonly MetricTelemetryConverter _metricTelemetryConverter; + private readonly DependencyTelemetryConverter _dependencyTelemetryConverter; private ApplicationInsightsTelemetryConverter(ApplicationInsightsSinkOptions options) { Guard.NotNull(options, nameof(options), "Requires a set of options to influence how to track to Application Insights"); - _requestTelemetryConverter = new RequestTelemetryConverter(options.Request); - _exceptionTelemetryConverter = new ExceptionTelemetryConverter(options.Exception); + + _requestTelemetryConverter = new RequestTelemetryConverter(options); + _exceptionTelemetryConverter = new ExceptionTelemetryConverter(options); + _traceTelemetryConverter = new TraceTelemetryConverter(options); + _eventTelemetryConverter = new EventTelemetryConverter(options); + _metricTelemetryConverter = new MetricTelemetryConverter(options); + _dependencyTelemetryConverter = new DependencyTelemetryConverter(options); } /// diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/CustomTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/CustomTelemetryConverter.cs index 1fbdb746..4d0473ad 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/CustomTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/CustomTelemetryConverter.cs @@ -1,6 +1,7 @@ using System; using System.Collections.Generic; using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using GuardNet; using Microsoft.ApplicationInsights.Channel; using Microsoft.ApplicationInsights.DataContracts; @@ -16,9 +17,35 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver public abstract class CustomTelemetryConverter : TelemetryConverterBase where TEntry : ITelemetry, ISupportProperties { - private readonly OperationContextConverter _operationContextConverter = new OperationContextConverter(); + private readonly OperationContextConverter _operationContextConverter; private readonly CloudContextConverter _cloudContextConverter = new CloudContextConverter(); + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + protected CustomTelemetryConverter() : this(new ApplicationInsightsSinkOptions()) + { + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + protected CustomTelemetryConverter(ApplicationInsightsSinkOptions options) + { + Guard.NotNull(options, nameof(options), "Requires a set of options to influence the behavior of the Application Insights Serilog sink"); + + _operationContextConverter = new OperationContextConverter(options); + Options = options; + } + + /// + /// Gets the user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// + protected ApplicationInsightsSinkOptions Options { get; } + /// /// Convert the given to a series of instances. /// diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs index d9fc5473..69d9879a 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/DependencyTelemetryConverter.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using GuardNet; using Microsoft.ApplicationInsights.DataContracts; using Serilog.Events; @@ -13,6 +14,23 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver /// public class DependencyTelemetryConverter : CustomTelemetryConverter { + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + public DependencyTelemetryConverter() + { + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public DependencyTelemetryConverter(ApplicationInsightsSinkOptions options) : base(options) + { + } + /// /// Creates a telemetry entry for a given log event /// diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/EventTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/EventTelemetryConverter.cs index a2e86ffb..c4923516 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/EventTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/EventTelemetryConverter.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using GuardNet; using Microsoft.ApplicationInsights.DataContracts; using Serilog.Events; @@ -13,6 +14,23 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver /// public class EventTelemetryConverter : CustomTelemetryConverter { + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + public EventTelemetryConverter() + { + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public EventTelemetryConverter(ApplicationInsightsSinkOptions options) : base(options) + { + } + /// /// Creates a telemetry entry for a given log event /// diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ExceptionTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ExceptionTelemetryConverter.cs index b50f652c..27ccf57a 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ExceptionTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/ExceptionTelemetryConverter.cs @@ -20,11 +20,21 @@ public class ExceptionTelemetryConverter : CustomTelemetryConverter /// The consumer-configurable options to influence how the exception should be tracked. /// Thrown when the is null. + [Obsolete("Use the constructor overload with the Application Insights options instead")] public ExceptionTelemetryConverter(ApplicationInsightsSinkExceptionOptions options) { Guard.NotNull(options, nameof(options), "Requires a set of user-configurable options to influence the behavior of how exceptions are tracked"); _options = options; } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public ExceptionTelemetryConverter(ApplicationInsightsSinkOptions options) : base(options) + { + } /// /// Creates a telemetry entry for a given log event @@ -40,7 +50,7 @@ protected override ExceptionTelemetry CreateTelemetryEntry(LogEvent logEvent, IF var exceptionTelemetry = new ExceptionTelemetry(logEvent.Exception); - if (_options.IncludeProperties) + if (Options?.Exception.IncludeProperties == true || _options?.IncludeProperties == true) { EnrichWithExceptionProperties(logEvent, exceptionTelemetry); } @@ -55,10 +65,28 @@ private void EnrichWithExceptionProperties(LogEvent logEvent, ExceptionTelemetry foreach (PropertyInfo exceptionProperty in exceptionProperties) { - string key = String.Format(_options.PropertyFormat, exceptionProperty.Name); + string propertyFormat = DeterminePropertyFormat(); + + string key = String.Format(propertyFormat, exceptionProperty.Name); var value = exceptionProperty.GetValue(logEvent.Exception)?.ToString(); exceptionTelemetry.Properties[key] = value; } } + + private string DeterminePropertyFormat() + { + if (Options != null) + { + return Options.Exception.PropertyFormat; + } + + if (_options != null) + { + return _options.PropertyFormat; + } + + throw new InvalidOperationException( + "Could not determine exception property format because the Application Insights exception converter was not initialized with any options"); + } } } diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/MetricTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/MetricTelemetryConverter.cs index 22199e52..bea4a291 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/MetricTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/MetricTelemetryConverter.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using GuardNet; using Microsoft.ApplicationInsights.DataContracts; using Serilog.Events; @@ -13,6 +14,23 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver /// public class MetricTelemetryConverter : CustomTelemetryConverter { + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + public MetricTelemetryConverter() + { + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public MetricTelemetryConverter(ApplicationInsightsSinkOptions options) : base(options) + { + } + /// /// Creates a telemetry entry for a given log event /// diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/OperationContextConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/OperationContextConverter.cs index a8e33351..2943c817 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/OperationContextConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/OperationContextConverter.cs @@ -3,6 +3,8 @@ using Microsoft.ApplicationInsights.DataContracts; using Microsoft.ApplicationInsights.Extensibility.Implementation; using System; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; +using GuardNet; namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Converters { @@ -11,6 +13,27 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver /// public class OperationContextConverter { + private readonly ApplicationInsightsSinkOptions _options; + + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + public OperationContextConverter() + { + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public OperationContextConverter(ApplicationInsightsSinkOptions options) + { + Guard.NotNull(options, nameof(options), "Requires a set of options to influence the behavior of the Application Insights Serilog sink"); + _options = options; + } + /// /// Enrich the given with the Operation-related information. /// @@ -22,14 +45,39 @@ public void EnrichWithCorrelationInfo(TEntry telemetryEntry) where TEntr return; } - if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.OperationId, out string operationId)) + if (telemetryEntry is RequestTelemetry requestTelemetry) { - telemetryEntry.Context.Operation.Id = operationId; - } + if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.OperationId, out string operationId)) + { + if (operationId is null || operationId is "null") + { + operationId = _options.Request.GenerateId(); + } - if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.OperationParentId, out string operationParentId)) + requestTelemetry.Id = operationId; + } + + if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.TransactionId, out string transactionId)) + { + telemetryEntry.Context.Operation.Id = transactionId; + } + + if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.OperationParentId, out string operationParentId)) + { + telemetryEntry.Context.Operation.ParentId = operationParentId; + } + } + else { - telemetryEntry.Context.Operation.ParentId = operationParentId; + if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.TransactionId, out string transactionId)) + { + telemetryEntry.Context.Operation.Id = transactionId; + } + + if (telemetryEntry.Properties.TryGetValue(ContextProperties.Correlation.OperationId, out string operationId)) + { + telemetryEntry.Context.Operation.ParentId = operationId; + } } } diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs index 9eb5d8a1..ddb3c887 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/RequestTelemetryConverter.cs @@ -19,6 +19,7 @@ public class RequestTelemetryConverter : CustomTelemetryConverter /// Initializes a new instance of the class. /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] public RequestTelemetryConverter() : this(new ApplicationInsightsSinkRequestOptions()) { @@ -29,12 +30,22 @@ public RequestTelemetryConverter() /// /// The user-defined configuration options to tracking requests. /// Thrown when the is null. + [Obsolete("Use the constructor overload with the Application Insights options instead")] public RequestTelemetryConverter(ApplicationInsightsSinkRequestOptions options) { Guard.NotNull(options, nameof(options), "Requires a set of user-configurable options to influence the behavior of how requests are tracked"); _options = options; } - + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public RequestTelemetryConverter(ApplicationInsightsSinkOptions options) : base(options) + { + } + /// /// Creates a telemetry entry for a given log event /// @@ -57,8 +68,6 @@ protected override RequestTelemetry CreateTelemetryEntry(LogEvent logEvent, IFor IDictionary context = logEntry.Properties.GetAsDictionary(nameof(RequestLogEntry.Context)); var sourceSystem = logEntry.Properties.GetAsObject(nameof(RequestLogEntry.SourceSystem)); - string id = _options.GenerateId(); - string sourceName = DetermineSourceName(sourceSystem, requestMethod, requestUri, operationName); bool isSuccessfulRequest = DetermineRequestOutcome(responseStatusCode); Uri url = DetermineUrl(sourceSystem, requestHost, requestUri); @@ -67,12 +76,16 @@ protected override RequestTelemetry CreateTelemetryEntry(LogEvent logEvent, IFor var requestTelemetry = new RequestTelemetry(sourceName, requestTime, requestDuration, responseStatusCode, isSuccessfulRequest) { - Id = id, Url = url, Source = source, Context = { Operation = { Name = requestOperationName } } }; + if (_options != null) + { + requestTelemetry.Id = _options.GenerateId(); + } + requestTelemetry.Properties.AddRange(context); return requestTelemetry; } diff --git a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/TraceTelemetryConverter.cs b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/TraceTelemetryConverter.cs index d74df85c..af20c156 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/TraceTelemetryConverter.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights/Converters/TraceTelemetryConverter.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using GuardNet; using Microsoft.ApplicationInsights.Channel; using Microsoft.ApplicationInsights.DataContracts; @@ -13,9 +14,29 @@ namespace Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Conver /// public class TraceTelemetryConverter : ApplicationInsightsSink.TelemetryConverters.TraceTelemetryConverter { - private readonly OperationContextConverter _operationContextConverter = new OperationContextConverter(); + private readonly OperationContextConverter _operationContextConverter; private readonly CloudContextConverter _cloudContextConverter = new CloudContextConverter(); + /// + /// Initializes a new instance of the class. + /// + [Obsolete("Use the constructor overload with the Application Insights options instead")] + public TraceTelemetryConverter() + { + _operationContextConverter = new OperationContextConverter(); + } + + /// + /// Initializes a new instance of the class. + /// + /// The user-defined configuration options to influence the behavior of the Application Insights Serilog sink. + /// Thrown when the is null. + public TraceTelemetryConverter(ApplicationInsightsSinkOptions options) + { + Guard.NotNull(options, nameof(options), "Requires a set of options to influence the behavior of the Application Insights Serilog sink"); + _operationContextConverter = new OperationContextConverter(options); + } + /// /// Convert the given to a series of instances. /// 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 b524e787..71ed6a37 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ApplicationInsightsSinkTests.cs @@ -6,6 +6,7 @@ using Arcus.Observability.Tests.Core; using Bogus; using Microsoft.Azure.ApplicationInsights.Query; +using Microsoft.Azure.ApplicationInsights.Query.Models; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.Logging; using Polly; @@ -61,7 +62,7 @@ protected ILoggerFactory CreateLoggerFactory( { var configuration = new LoggerConfiguration() .WriteTo.Sink(new XunitLogEventSink(_outputWriter)) - .WriteTo.AzureApplicationInsights(InstrumentationKey, configureOptions) + .WriteTo.AzureApplicationInsightsWithInstrumentationKey(InstrumentationKey, configureOptions) .WriteTo.Sink(_memoryLogSink); configureLogging?.Invoke(configuration); @@ -80,12 +81,12 @@ protected ILoggerFactory CreateLoggerFactory( protected Dictionary CreateTestTelemetryContext([CallerMemberName] string memberName = "") { - var operationId = Guid.NewGuid(); - Logger.LogInformation("Testing '{TestName}' using {OperationId}", memberName, operationId); + var testId = Guid.NewGuid(); + Logger.LogInformation("Testing '{TestName}' using {TestId}", memberName, testId); return new Dictionary { - ["OperationId"] = operationId, + ["TestId"] = testId, ["TestName"] = memberName }; } @@ -102,7 +103,6 @@ await Policy.TimeoutAsync(timeout) .WaitAndRetryForeverAsync(index => TimeSpan.FromSeconds(1))) .ExecuteAsync(assertion); } - protected ApplicationInsightsDataClient CreateApplicationInsightsClient() { var clientCredentials = new ApiKeyClientCredentials(Configuration.GetValue("ApplicationInsights:ApiKey")); diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureFunctionsDockerTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureFunctionsDockerTests.cs index a5e91931..fbd15828 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureFunctionsDockerTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/AzureFunctionsDockerTests.cs @@ -48,7 +48,6 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { Assert.Contains("order", result.Request.Url); Assert.Equal("200", result.Request.ResultCode); - Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); Assert.Equal(HttpMethod.Get.Method + " /api/order", result.Operation.Name); }); }); diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventTests.cs index 74390b02..ce4369c2 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/EventTests.cs @@ -161,8 +161,8 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => Assert.Equal(operationId, actualOperationId); Assert.Equal(transactionId, actualTransactionId); Assert.Equal(operationParentId, actualOperationParentId); - Assert.Equal(operationId, trace.Operation.Id); - Assert.Equal(operationParentId, trace.Operation.ParentId); + Assert.Equal(transactionId, trace.Operation.Id); + Assert.Equal(operationId, trace.Operation.ParentId); }); }); } diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ExceptionTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ExceptionTests.cs index 3c7b6f56..03f334b8 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ExceptionTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ExceptionTests.cs @@ -39,7 +39,7 @@ public async Task LogException_SinksToApplicationInsights_ResultsInExceptionTele { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, filter: OnlyLastHourFilter); + EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); Assert.Contains(results.Value, result => { return result.Exception.OuterMessage == exception.Message @@ -69,7 +69,7 @@ public async Task LogException_SinksToApplicationInsightsWithIncludedProperties_ { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, filter: OnlyLastHourFilter); + EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); Assert.Contains(results.Value, result => { return result.Exception.OuterMessage == exception.Message @@ -105,7 +105,7 @@ public async Task LogExceptionWithCustomPropertyFormat_SinksToApplicationInsight { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, filter: OnlyLastHourFilter); + EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); Assert.Contains(results.Value, result => { string propertyName = String.Format(propertyFormat, nameof(TestException.SpyProperty)); @@ -137,7 +137,7 @@ public async Task LogExceptionWithComponentName_SinksToApplicationInsights_Resul { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, filter: OnlyLastHourFilter); + EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); Assert.NotEmpty(results.Value); Assert.Contains(results.Value, result => result.Exception.OuterMessage == exception.Message && result.Cloud.RoleName == componentName); }); @@ -171,14 +171,14 @@ public async Task LogExceptionWithCorrelationInfo_SinksToApplicationInsights_Res { await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { - EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, filter: OnlyLastHourFilter); + EventsResults results = await client.Events.GetExceptionEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); Assert.NotEmpty(results.Value); AssertX.Any(results.Value, result => { Assert.Equal(exception.Message, result.Exception.OuterMessage); - Assert.Equal(operationId, result.Operation.Id); - Assert.Equal(operationParentId, result.Operation.ParentId); + Assert.Equal(transactionId, result.Operation.Id); + Assert.Equal(operationId, result.Operation.ParentId); }); }); } 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 5f46fc7f..f3f37a61 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/HttpDependencyTests.cs @@ -3,6 +3,7 @@ using System.Net; using System.Net.Http; using System.Threading.Tasks; +using Arcus.Observability.Correlation; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; using Microsoft.AspNetCore.Http; @@ -26,6 +27,63 @@ public HttpDependencyTests(ITestOutputHelper outputWriter) : base(outputWriter) { } + [Fact] + public async Task LogHttpDependencyWithRequestMessageWithCorrelation_SinksToApplicationInsights_ResultsInHttpDependencyTelemetryWithComponentName() + { + // Arrange + var correlation = new CorrelationInfo($"operation-{Guid.NewGuid()}", $"transaction-{Guid.NewGuid()}", $"parent-{Guid.NewGuid()}"); + var accessor = new DefaultCorrelationInfoAccessor(); + accessor.SetCorrelationInfo(correlation); + + string componentName = BogusGenerator.Commerce.ProductName(); + HttpMethod httpMethod = GenerateHttpMethod(); + string requestUrl = BogusGenerator.Image.LoremFlickrUrl(); + string dependencyId = BogusGenerator.Random.Word(); + + using (ILoggerFactory loggerFactory = CreateLoggerFactory( + config => config.Enrich.WithCorrelationInfo(accessor) + .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 = DateTimeOffset.Now; + TimeSpan duration = BogusGenerator.Date.Timespan(); + Dictionary telemetryContext = CreateTestTelemetryContext(); + + // Act + 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, PastHalfHourTimeSpan); + Assert.NotEmpty(results.Value); + AssertX.Any(results.Value, result => + { + 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); + + Assert.Equal(correlation.OperationId, result.Operation.ParentId); + Assert.Equal(correlation.TransactionId, result.Operation.Id); + }); + }); + } + + AssertSerilogLogProperties(httpMethod, requestUri.Host, requestUri.AbsolutePath); + } + [Fact] public async Task LogHttpDependencyWithRequestMessage_SinksToApplicationInsights_ResultsInHttpDependencyTelemetryWithComponentName() { 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 80931476..dfb4ea6c 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/RequestTests.cs @@ -3,6 +3,7 @@ using System.Net; using System.Net.Http; using System.Threading.Tasks; +using Arcus.Observability.Correlation; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; using Microsoft.AspNetCore.Http; @@ -10,9 +11,11 @@ using Microsoft.Azure.ApplicationInsights.Query.Models; using Microsoft.Extensions.Logging; using Moq; +using Serilog; using Serilog.Events; using Xunit; using Xunit.Abstractions; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights { @@ -22,16 +25,21 @@ public RequestTests(ITestOutputHelper outputWriter) : base(outputWriter) { } - [Fact] - public async Task LogRequest_SinksToApplicationInsightsWithoutOperationNameAndCustomId_ResultsInRequestTelemetry() + [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); + + var operationName = "sampleoperation"; HttpMethod httpMethod = GenerateHttpMethod(); var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); HttpRequest request = CreateStubRequest(httpMethod, requestUri.Scheme, requestUri.Host, requestUri.AbsolutePath); var statusCode = BogusGenerator.PickRandom(); - using (ILoggerFactory loggerFactory = CreateLoggerFactory()) + using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureLogging: config => config.Enrich.WithCorrelationInfo(accessor))) { ILogger logger = loggerFactory.CreateLogger(); @@ -41,7 +49,7 @@ public async Task LogRequest_SinksToApplicationInsightsWithoutOperationNameAndCu Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogRequest(request, response, startTime, duration, telemetryContext); + logger.LogRequest(request, response, operationName, startTime, duration, telemetryContext); } // Assert @@ -55,8 +63,11 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url); Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode); - Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); - Assert.StartsWith(httpMethod.Method, result.Operation.Name); + 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); }); }); } @@ -65,10 +76,10 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => } [Fact] - public async Task LogRequest_SinksToApplicationInsightsWithOperationNameWithoutCustomId_ResultsInRequestTelemetry() + public async Task LogRequest_SinksToApplicationInsightsWithoutCustomId_ResultsInRequestTelemetry() { // Arrange - string operationName = "sampleoperation"; + var operationName = "sampleoperation"; HttpMethod httpMethod = GenerateHttpMethod(); var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); HttpRequest request = CreateStubRequest(httpMethod, requestUri.Scheme, requestUri.Host, requestUri.AbsolutePath); @@ -98,7 +109,6 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url); Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode); - Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); }); }); @@ -108,16 +118,19 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => } [Fact] - public async Task LogRequest_SinksToApplicationInsightsWithResponseStatusCodeWithoutOperationNameWithCustomId_ResultsInRequestTelemetry() + public async Task LogRequest_SinksToApplicationInsightsWithResponseWithCustomId_ResultsInRequestTelemetry() { // Arrange + var operationName = "sampleoperation"; HttpMethod httpMethod = GenerateHttpMethod(); var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); HttpRequest request = CreateStubRequest(httpMethod, requestUri.Scheme, requestUri.Host, requestUri.AbsolutePath); var statusCode = BogusGenerator.PickRandom(); var requestId = Guid.NewGuid().ToString(); - using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureOptions: options => options.Request.GenerateId = () => requestId)) + using (ILoggerFactory loggerFactory = CreateLoggerFactory( + configureLogging: config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null), + configureOptions: options => options.Request.GenerateId = () => requestId)) { ILogger logger = loggerFactory.CreateLogger(); @@ -127,7 +140,7 @@ public async Task LogRequest_SinksToApplicationInsightsWithResponseStatusCodeWit Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogRequest(request, response, startTime, duration, telemetryContext); + logger.LogRequest(request, response, operationName, startTime, duration, telemetryContext); } // Assert @@ -142,50 +155,8 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url); Assert.Equal(((int)statusCode).ToString(), result.Request.ResultCode); Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); - Assert.StartsWith(httpMethod.Method, result.Operation.Name); - }); - }); - } - - VerifyLogEventProperties(requestUri); - } - - [Fact] - public async Task LogRequest_SinksToApplicationInsightsWithResponseStatusCodeWithOperationNameAndCustomId_ResultsInRequestTelemetry() - { - // Arrange - string operationName = "sampleoperation"; - HttpMethod httpMethod = GenerateHttpMethod(); - var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); - HttpRequest request = CreateStubRequest(httpMethod, requestUri.Scheme, requestUri.Host, requestUri.AbsolutePath); - var statusCode = BogusGenerator.PickRandom(); - var requestId = Guid.NewGuid().ToString(); - - using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureOptions: options => options.Request.GenerateId = () => requestId)) - { - ILogger logger = loggerFactory.CreateLogger(); - - TimeSpan duration = BogusGenerator.Date.Timespan(); - DateTimeOffset startTime = DateTimeOffset.Now; - Dictionary telemetryContext = CreateTestTelemetryContext(); - - // Act - logger.LogRequest(request, (int) statusCode, operationName, startTime, duration, telemetryContext); - } - - // Assert - using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) - { - await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => - { - EventsResults results = await client.Events.GetRequestEventsAsync(ApplicationId, PastHalfHourTimeSpan); - Assert.NotEmpty(results.Value); - AssertX.Any(results.Value, result => - { - Assert.Equal($"{requestUri.Scheme}://{requestUri.Host}{requestUri.AbsolutePath}", result.Request.Url); - Assert.Equal(((int)statusCode).ToString(), result.Request.ResultCode); - Assert.Equal(requestId, result.Request.Id); Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); + Assert.Equal(requestId, result.Request.Id); }); }); } @@ -194,25 +165,29 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => } [Fact] - public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseWithoutOperationNameWithCustomId_ResultsInRequestTelemetry() + public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseWithCustomId_ResultsInRequestTelemetry() { // Arrange + var operationName = "sampleoperation"; HttpMethod httpMethod = GenerateHttpMethod(); var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); var statusCode = BogusGenerator.PickRandom(); var requestId = Guid.NewGuid().ToString(); - using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureOptions: options => options.Request.GenerateId = () => requestId)) + using (ILoggerFactory loggerFactory = CreateLoggerFactory( + configureLogging: config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null), + configureOptions: options => options.Request.GenerateId = () => requestId)) { ILogger logger = loggerFactory.CreateLogger(); var request = new HttpRequestMessage(httpMethod, requestUri); + var response = new HttpResponseMessage(statusCode); TimeSpan duration = BogusGenerator.Date.Timespan(); DateTimeOffset startTime = DateTimeOffset.Now; Dictionary telemetryContext = CreateTestTelemetryContext(); // Act - logger.LogRequest(request, statusCode, startTime, duration, telemetryContext); + logger.LogRequest(request, response, operationName, startTime, duration, telemetryContext); } // Assert @@ -227,7 +202,8 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => Assert.Equal(requestUri.ToString(), result.Request.Url); Assert.Equal(((int)statusCode).ToString(), result.Request.ResultCode); Assert.Equal(requestId, result.Request.Id); - Assert.StartsWith(httpMethod.Method, result.Operation.Name); + Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); + Assert.Equal(requestId, result.Request.Id); }); }); } @@ -236,7 +212,7 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => } [Fact] - public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseWithOperationNameWithoutCustomId_ResultsInRequestTelemetry() + public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseWithoutCustomId_ResultsInRequestTelemetry() { // Arrange string operationName = "sampleoperation"; @@ -270,91 +246,6 @@ await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => { Assert.Equal(requestUri.ToString(), result.Request.Url); Assert.Equal(((int)statusCode).ToString(), result.Request.ResultCode); - Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); - Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); - }); - }); - } - - VerifyLogEventProperties(requestUri); - } - - [Fact] - public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseStatusCodeWithoutOperationNameAndCustomId_ResultsInRequestTelemetry() - { - // Arrange - HttpMethod httpMethod = GenerateHttpMethod(); - var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); - var statusCode = BogusGenerator.PickRandom(); - - using (ILoggerFactory loggerFactory = CreateLoggerFactory()) - { - ILogger logger = loggerFactory.CreateLogger(); - - var request = new HttpRequestMessage(httpMethod, requestUri); - TimeSpan duration = BogusGenerator.Date.Timespan(); - DateTimeOffset startTime = DateTimeOffset.Now; - Dictionary telemetryContext = CreateTestTelemetryContext(); - - // Act - logger.LogRequest(request, statusCode, startTime, duration, telemetryContext); - } - - // Assert - using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) - { - await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => - { - EventsResults results = await client.Events.GetRequestEventsAsync(ApplicationId, PastHalfHourTimeSpan); - Assert.NotEmpty(results.Value); - AssertX.Any(results.Value, result => - { - Assert.Equal(requestUri.ToString(), result.Request.Url); - Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode); - Assert.True(Guid.TryParse(result.Request.Id, out Guid _)); - Assert.StartsWith(httpMethod.Method, result.Operation.Name); - }); - }); - } - - VerifyLogEventProperties(requestUri); - } - - [Fact] - public async Task LogRequestMessage_SinksToApplicationInsightsWithResponseStatusCodeWithOperationNameAndCustomId_ResultsInRequestTelemetry() - { - // Arrange - string operationName = "sampleoperation"; - HttpMethod httpMethod = GenerateHttpMethod(); - var requestUri = new Uri(BogusGenerator.Internet.UrlWithPath()); - var statusCode = BogusGenerator.PickRandom(); - var requestId = Guid.NewGuid().ToString(); - - using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureOptions: options => options.Request.GenerateId = () => requestId)) - { - ILogger logger = loggerFactory.CreateLogger(); - - var request = new HttpRequestMessage(httpMethod, requestUri); - TimeSpan duration = BogusGenerator.Date.Timespan(); - DateTimeOffset startTime = DateTimeOffset.Now; - Dictionary telemetryContext = CreateTestTelemetryContext(); - - // Act - logger.LogRequest(request, statusCode, operationName, startTime, duration, telemetryContext); - } - - // Assert - using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) - { - await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => - { - EventsResults results = await client.Events.GetRequestEventsAsync(ApplicationId, PastHalfHourTimeSpan); - Assert.NotEmpty(results.Value); - AssertX.Any(results.Value, result => - { - Assert.Equal(requestUri.ToString(), result.Request.Url); - Assert.Equal(((int) statusCode).ToString(), result.Request.ResultCode); - Assert.Equal(requestId, result.Request.Id); Assert.Equal($"{httpMethod.Method} {operationName}", result.Operation.Name); }); }); diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusDependencyTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusDependencyTests.cs index 03da31ae..d16a3729 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusDependencyTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusDependencyTests.cs @@ -1,14 +1,17 @@ using System; using System.Collections.Generic; using System.Threading.Tasks; +using Arcus.Observability.Correlation; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Core.Logging; using Microsoft.Azure.ApplicationInsights.Query; using Microsoft.Azure.ApplicationInsights.Query.Models; using Microsoft.Extensions.Logging; +using Serilog; using Serilog.Events; using Xunit; using Xunit.Abstractions; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights { @@ -18,6 +21,60 @@ public ServiceBusDependencyTests(ITestOutputHelper outputWriter) : base(outputWr { } + [Fact] + public async Task LogServiceBusDependencyWithCorrelation_SinksToApplicationInsights_ResultsInServiceBusDependencyTelemetry() + { + // Arrange + var correlation = new CorrelationInfo($"operation-{Guid.NewGuid()}", $"transaction-{Guid.NewGuid()}", $"parent-{Guid.NewGuid()}"); + var accessor = new DefaultCorrelationInfoAccessor(); + accessor.SetCorrelationInfo(correlation); + + string dependencyType = "Azure Service Bus"; + string namespaceEndpoint = BogusGenerator.Commerce.Product(); + string entityName = BogusGenerator.Commerce.Product(); + string dependencyName = entityName; + string dependencyId = BogusGenerator.Lorem.Word(); + var entityType = ServiceBusEntityType.Queue; + + using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureLogging: config => config.Enrich.WithCorrelationInfo(accessor))) + { + ILogger logger = loggerFactory.CreateLogger(); + + bool isSuccessful = BogusGenerator.PickRandom(true, false); + DateTimeOffset startTime = DateTimeOffset.Now; + TimeSpan duration = BogusGenerator.Date.Timespan(); + Dictionary telemetryContext = CreateTestTelemetryContext(); + + // Act + logger.LogServiceBusDependency(namespaceEndpoint, entityName, isSuccessful, startTime, duration, dependencyId, entityType, telemetryContext); + } + + // Assert + using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) + { + await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => + { + EventsResults results = await client.Events.GetDependencyEventsAsync(ApplicationId, timespan: "PT30M"); + Assert.NotEmpty(results.Value); + AssertX.Any(results.Value, result => + { + Assert.Equal(dependencyType, result.Dependency.Type); + Assert.Contains(namespaceEndpoint, result.Dependency.Target); + Assert.Contains(entityName, result.Dependency.Target); + Assert.Equal(dependencyName, result.Dependency.Name); + Assert.Equal(dependencyId, result.Dependency.Id); + + AssertContainsCustomDimension(result.CustomDimensions, ContextProperties.DependencyTracking.ServiceBus.EntityType, entityType.ToString()); + + Assert.Equal(correlation.OperationId, result.Operation.ParentId); + Assert.Equal(correlation.TransactionId, result.Operation.Id); + }); + }); + } + + AssertSerilogLogProperties(dependencyType, namespaceEndpoint, entityName, dependencyName); + } + [Fact] public async Task LogServiceBusDependency_SinksToApplicationInsights_ResultsInServiceBusDependencyTelemetry() { diff --git a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusRequestTests.cs b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusRequestTests.cs index 7c28548b..c95d7a99 100644 --- a/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusRequestTests.cs +++ b/src/Arcus.Observability.Tests.Integration/Serilog/Sinks/ApplicationInsights/ServiceBusRequestTests.cs @@ -3,12 +3,15 @@ using System.Linq; using System.Text; using System.Threading.Tasks; +using Arcus.Observability.Correlation; using Arcus.Observability.Telemetry.Core; using Microsoft.Azure.ApplicationInsights.Query; using Microsoft.Azure.ApplicationInsights.Query.Models; using Microsoft.Extensions.Logging; +using Serilog; using Xunit; using Xunit.Abstractions; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace Arcus.Observability.Tests.Integration.Serilog.Sinks.ApplicationInsights { @@ -18,6 +21,60 @@ public ServiceBusRequestTests(ITestOutputHelper outputWriter) : base(outputWrite { } + [Fact] + public async Task LogServiceBusQueueRequestWithCorrelation_SinksToApplicationInsights_ResultsInRequestTelemetry() + { + // Arrange + var correlation = new CorrelationInfo($"operation-{Guid.NewGuid()}", $"transaction-{Guid.NewGuid()}", $"parent-{Guid.NewGuid()}"); + var accessor = new DefaultCorrelationInfoAccessor(); + accessor.SetCorrelationInfo(correlation); + + string queueName = BogusGenerator.Lorem.Word(); + string serviceBusNamespace = $"{BogusGenerator.Lorem.Word()}.servicebus.windows.net"; + string operationName = BogusGenerator.Lorem.Sentence(); + bool isSuccessful = BogusGenerator.Random.Bool(); + TimeSpan duration = BogusGenerator.Date.Timespan(); + DateTimeOffset startTime = DateTimeOffset.Now; + Dictionary telemetryContext = CreateTestTelemetryContext(); + + using (ILoggerFactory loggerFactory = CreateLoggerFactory(configureLogging: config => config.Enrich.WithCorrelationInfo(accessor))) + { + ILogger logger = loggerFactory.CreateLogger(); + + // Act + logger.LogServiceBusQueueRequest(serviceBusNamespace, queueName, operationName, isSuccessful, duration, startTime, telemetryContext); + } + + // Assert + using (ApplicationInsightsDataClient client = CreateApplicationInsightsClient()) + { + await RetryAssertUntilTelemetryShouldBeAvailableAsync(async () => + { + EventsResults results = await client.Events.GetRequestEventsAsync(ApplicationId, timespan: PastHalfHourTimeSpan); + Assert.NotNull(results.Value); + Assert.NotEmpty(results.Value); + AssertX.Any(results.Value, result => + { + Assert.Equal(operationName, result.Request.Name); + Assert.Contains(queueName, result.Request.Source); + Assert.Contains(serviceBusNamespace, result.Request.Source); + Assert.Empty(result.Request.Url); + Assert.Equal(operationName, result.Operation.Name); + Assert.True(bool.TryParse(result.Request.Success, out bool success)); + Assert.Equal(isSuccessful, success); + + AssertContainsCustomDimension(result.CustomDimensions, ContextProperties.RequestTracking.ServiceBus.EntityType, ServiceBusEntityType.Queue.ToString()); + AssertContainsCustomDimension(result.CustomDimensions, ContextProperties.RequestTracking.ServiceBus.EntityName, queueName); + AssertContainsCustomDimension(result.CustomDimensions, ContextProperties.RequestTracking.ServiceBus.Endpoint, serviceBusNamespace); + + Assert.Equal(correlation.OperationId, result.Request.Id); + Assert.Equal(correlation.TransactionId, result.Operation.Id); + Assert.Equal(correlation.OperationParentId, result.Operation.ParentId); + }); + }); + } + } + [Fact] public async Task LogServiceBusQueueRequest_SinksToApplicationInsights_ResultsInRequestTelemetry() { diff --git a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs index a033e32e..7366ef23 100644 --- a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs @@ -41,8 +41,12 @@ public void LogRequestMessage_WithRequestAndResponse_CreatesRequestTelemetry() // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -75,9 +79,8 @@ public void LogRequestMessage_WithRequestAndResponse_CreatesRequestTelemetry() Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int)statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.True(Guid.TryParse(requestTelemetry.Id, out Guid _)); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, operationId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -89,9 +92,12 @@ public void LogRequestMessage_WithRequestAndResponseWithCustomId_CreatesRequestT { // Arrange var spySink = new InMemoryLogSink(); - string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -128,9 +134,8 @@ public void LogRequestMessage_WithRequestAndResponseWithCustomId_CreatesRequestT Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int) statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.Equal(requestId, requestTelemetry.Id); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, requestId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -144,8 +149,12 @@ public void LogRequestMessage_WithRequestAndResponseStatusCode_CreatesRequestTel // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -177,9 +186,8 @@ public void LogRequestMessage_WithRequestAndResponseStatusCode_CreatesRequestTel Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int) statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.True(Guid.TryParse(requestTelemetry.Id, out Guid _)); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, operationId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -191,9 +199,12 @@ public void LogRequestMessage_WithRequestAndResponseStatusCodeWithCustomId_Creat { // Arrange var spySink = new InMemoryLogSink(); - string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -229,9 +240,8 @@ public void LogRequestMessage_WithRequestAndResponseStatusCodeWithCustomId_Creat Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int) statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.Equal(requestId, requestTelemetry.Id); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, requestId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -245,8 +255,12 @@ public void LogRequest_WithRequestAndResponse_CreatesRequestTelemetry() // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction={Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -279,9 +293,8 @@ public void LogRequest_WithRequestAndResponse_CreatesRequestTelemetry() Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int) statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.True(Guid.TryParse(requestTelemetry.Id, out Guid _)); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, operationId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -293,9 +306,12 @@ public void LogRequest_WithRequestAndResponseWithCustomId_CreatesRequestTelemetr { // Arrange var spySink = new InMemoryLogSink(); - string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction={Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -332,9 +348,8 @@ public void LogRequest_WithRequestAndResponseWithCustomId_CreatesRequestTelemetr Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(((int) statusCode).ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.Equal(requestId, requestTelemetry.Id); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, requestId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -348,8 +363,12 @@ public void LogRequest_WithRequestAndResponseStatusCode_CreatesRequestTelemetry( // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction={Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -381,9 +400,8 @@ public void LogRequest_WithRequestAndResponseStatusCode_CreatesRequestTelemetry( Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(statusCode.ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.True(Guid.TryParse(requestTelemetry.Id, out Guid _)); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, operationId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -395,9 +413,12 @@ public void LogRequest_WithRequestAndResponseStatusCodeWithCustomId_CreatesReque { // Arrange var spySink = new InMemoryLogSink(); - string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction={Guid.NewGuid()}"; + string operationParentId = $"parent-{Guid.NewGuid()}"; ILogger logger = CreateLogger( - spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, null) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) + .Enrich.WithProperty(ContextProperties.Correlation.OperationParentId, operationParentId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -433,9 +454,8 @@ public void LogRequest_WithRequestAndResponseStatusCodeWithCustomId_CreatesReque Assert.Equal(duration, requestTelemetry.Duration); Assert.Equal(statusCode.ToString(), requestTelemetry.ResponseCode); Assert.True(requestTelemetry.Success); - Assert.Equal(requestId, requestTelemetry.Id); Assert.Equal(new Uri("https://localhost/api/v1/health"), requestTelemetry.Url); - AssertOperationContext(requestTelemetry, operationId); + AssertOperationContextForRequest(requestTelemetry, requestId, transactionId, operationParentId); AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); @@ -821,7 +841,10 @@ public void LogHttpDependency_WithHttpDependency_CreatesHttpDependencyTelemetry( // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); var request = new HttpRequestMessage(System.Net.Http.HttpMethod.Get, "https://localhost/api/v1/health"); var startTime = DateTimeOffset.UtcNow; @@ -853,7 +876,7 @@ public void LogHttpDependency_WithHttpDependency_CreatesHttpDependencyTelemetry( Assert.Equal(duration, dependencyTelemetry.Duration); Assert.Equal("200", dependencyTelemetry.ResultCode); Assert.True(dependencyTelemetry.Success); - AssertOperationContext(dependencyTelemetry, operationId); + AssertOperationContextForNonRequest(dependencyTelemetry, operationId, transactionId); AssertContainsTelemetryProperty(dependencyTelemetry, "Port", "4000"); }); @@ -865,7 +888,11 @@ public void LogSqlDependency_WithSqlDependency_CreatesSqlDependencyTelemetry() // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); + var startTime = DateTimeOffset.UtcNow; var duration = TimeSpan.FromSeconds(5); var telemetryContext = new Dictionary @@ -894,7 +921,7 @@ public void LogSqlDependency_WithSqlDependency_CreatesSqlDependencyTelemetry() Assert.Equal(duration, dependencyTelemetry.Duration); Assert.Null(dependencyTelemetry.ResultCode); Assert.True(dependencyTelemetry.Success); - AssertOperationContext(dependencyTelemetry, operationId); + AssertOperationContextForNonRequest(dependencyTelemetry, operationId, transactionId); AssertContainsTelemetryProperty(dependencyTelemetry, "Statement", "Query"); }); @@ -907,7 +934,10 @@ public void LogEvent_WithEvent_CreatesEventTelemetry() const string eventName = "Order Invoiced"; var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); var telemetryContext = new Dictionary { @@ -930,7 +960,7 @@ public void LogEvent_WithEvent_CreatesEventTelemetry() { var eventTelemetry = Assert.IsType(telemetry); Assert.Equal(eventName, eventTelemetry.Name); - AssertOperationContext(eventTelemetry, operationId); + AssertOperationContextForNonRequest(eventTelemetry, operationId, transactionId); AssertContainsTelemetryProperty(eventTelemetry, "OrderId", "ABC"); AssertContainsTelemetryProperty(eventTelemetry, "Vendor", "Contoso"); }); @@ -943,7 +973,10 @@ public void LogEvent_WithJsonTelemetryValue_CreatesEventTelemetry() const string eventName = "Order Invoiced"; var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); Order order = OrderGenerator.Generate(); string json = JsonSerializer.Serialize(order); @@ -967,7 +1000,7 @@ public void LogEvent_WithJsonTelemetryValue_CreatesEventTelemetry() { var eventTelemetry = Assert.IsType(telemetry); Assert.Equal(eventName, eventTelemetry.Name); - AssertOperationContext(eventTelemetry, operationId); + AssertOperationContextForNonRequest(eventTelemetry, operationId, transactionId); AssertContainsTelemetryProperty(eventTelemetry, "Value", json); AssertContainsTelemetryProperty(eventTelemetry, "OrderId", "ABC"); AssertContainsTelemetryProperty(eventTelemetry, "Vendor", "Contoso"); @@ -982,7 +1015,10 @@ public void LogException_WithException_CreatesExceptionTelemetry() var exception = new PlatformNotSupportedException(platform); var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); logger.LogCritical(exception, exception.Message); LogEvent logEvent = Assert.Single(spySink.CurrentLogEmits); @@ -1000,7 +1036,7 @@ public void LogException_WithException_CreatesExceptionTelemetry() Assert.NotNull(exceptionTelemetryType); Assert.NotNull(exceptionTelemetryType.Exception); Assert.Equal(exception.Message, exceptionTelemetryType.Exception.Message); - AssertOperationContext(exceptionTelemetryType, operationId); + AssertOperationContextForNonRequest(exceptionTelemetryType, operationId, transactionId); }); } @@ -1013,7 +1049,10 @@ public void LogMetric_WithMetric_CreatesMetricTelemetry() var timestamp = DateTimeOffset.UtcNow; var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; - ILogger logger = CreateLogger(spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + string transactionId = $"transaction-{Guid.NewGuid()}"; + ILogger logger = CreateLogger(spySink, + config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId)); var telemetryContext = new Dictionary { @@ -1036,7 +1075,7 @@ public void LogMetric_WithMetric_CreatesMetricTelemetry() Assert.Equal(metricName, metricTelemetry.Name); Assert.Equal(metricValue, metricTelemetry.Sum); Assert.Equal(timestamp, metricTelemetry.Timestamp); - AssertOperationContext(metricTelemetry, operationId); + AssertOperationContextForNonRequest(metricTelemetry, operationId, transactionId); AssertContainsTelemetryProperty(metricTelemetry, "Capacity", "0.45"); }); @@ -1048,9 +1087,11 @@ public void LogInformationWithPodName_Without_CreatesTraceTelemetryWithPodNameAs // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; ILogger logger = CreateLogger(spySink, config => { return config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) .Enrich.WithProperty(General.ComponentName, "component") .Enrich.WithProperty(Kubernetes.PodName, "pod"); }); @@ -1073,7 +1114,7 @@ public void LogInformationWithPodName_Without_CreatesTraceTelemetryWithPodNameAs Assert.Equal(SeverityLevel.Information, traceTelemetry.SeverityLevel); Assert.Equal("component", traceTelemetry.Context.Cloud.RoleName); Assert.Equal("pod", traceTelemetry.Context.Cloud.RoleInstance); - AssertOperationContext(traceTelemetry, operationId); + AssertOperationContextForNonRequest(traceTelemetry, operationId, transactionId); }); } @@ -1083,9 +1124,11 @@ public void LogInformationWithMachineName_Without_CreatesTraceTelemetryWithPodNa // Arrange var spySink = new InMemoryLogSink(); string operationId = $"operation-id-{Guid.NewGuid()}"; + string transactionId = $"transaction-{Guid.NewGuid()}"; ILogger logger = CreateLogger(spySink, config => { return config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId) + .Enrich.WithProperty(ContextProperties.Correlation.TransactionId, transactionId) .Enrich.WithProperty(General.ComponentName, "component") .Enrich.WithProperty(General.MachineName, "machine"); }); @@ -1108,15 +1151,32 @@ public void LogInformationWithMachineName_Without_CreatesTraceTelemetryWithPodNa Assert.Equal(SeverityLevel.Information, traceTelemetry.SeverityLevel); Assert.Equal("component", traceTelemetry.Context.Cloud.RoleName); Assert.Equal("machine", traceTelemetry.Context.Cloud.RoleInstance); - AssertOperationContext(traceTelemetry, operationId); + AssertOperationContextForNonRequest(traceTelemetry, operationId, transactionId); }); } - private static void AssertOperationContext(TTelemetry telemetry, string operationId) where TTelemetry : ITelemetry + private static void AssertOperationContextForNonRequest( + TTelemetry telemetry, + string operationId, + string transactionId) where TTelemetry : ITelemetry + { + Assert.NotNull(telemetry.Context); + Assert.NotNull(telemetry.Context.Operation); + Assert.Equal(operationId, telemetry.Context.Operation.ParentId); + Assert.Equal(transactionId, telemetry.Context.Operation.Id); + } + + private static void AssertOperationContextForRequest( + RequestTelemetry telemetry, + string operationId, + string transactionId, + string operationParentId) { Assert.NotNull(telemetry.Context); Assert.NotNull(telemetry.Context.Operation); - Assert.Equal(operationId, telemetry.Context.Operation.Id); + Assert.Equal(operationId, telemetry.Id); + Assert.Equal(transactionId, telemetry.Context.Operation.Id); + Assert.Equal(operationParentId, telemetry.Context.Operation.ParentId); } private static ILogger CreateLogger(ILogEventSink sink, Func configureLoggerConfiguration = null) diff --git a/src/Arcus.Observability.Tests.Unit/Serilog/CustomTelemetryConverterTests.cs b/src/Arcus.Observability.Tests.Unit/Serilog/CustomTelemetryConverterTests.cs new file mode 100644 index 00000000..8fc7406a --- /dev/null +++ b/src/Arcus.Observability.Tests.Unit/Serilog/CustomTelemetryConverterTests.cs @@ -0,0 +1,47 @@ +using System; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Converters; +using Xunit; + +namespace Arcus.Observability.Tests.Unit.Serilog +{ + [Trait("Category", "Unit")] + public class CustomTelemetryConverterTests + { + [Fact] + public void CreateTraceConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new TraceTelemetryConverter(options: null)); + } + + [Fact] + public void CreateMetricConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new MetricTelemetryConverter(options: null)); + } + + [Fact] + public void CreateDependencyConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new DependencyTelemetryConverter(options: null)); + } + + [Fact] + public void CreateEventConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new EventTelemetryConverter(options: null)); + } + + [Fact] + public void CreateRequestConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new RequestTelemetryConverter(options: (ApplicationInsightsSinkOptions) null)); + } + + [Fact] + public void CreateExceptionConverter_WithoutOptions_Fails() + { + Assert.ThrowsAny(() => new ExceptionTelemetryConverter(options: (ApplicationInsightsSinkOptions) null)); + } + } +} diff --git a/src/Arcus.Observability.Tests.Unit/Serilog/OperationContextConverterTests.cs b/src/Arcus.Observability.Tests.Unit/Serilog/OperationContextConverterTests.cs index 787ab76d..9d96ce21 100644 --- a/src/Arcus.Observability.Tests.Unit/Serilog/OperationContextConverterTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Serilog/OperationContextConverterTests.cs @@ -1,7 +1,10 @@ using System; +using System.Collections.Generic; using Arcus.Observability.Telemetry.Core; +using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Configuration; using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Converters; using Bogus; +using Microsoft.ApplicationInsights.Channel; using Microsoft.ApplicationInsights.DataContracts; using Xunit; @@ -10,237 +13,83 @@ namespace Arcus.Observability.Tests.Unit.Serilog [Trait("Category", "Unit")] public class OperationContextConverterTests { - private readonly Faker _bogusGenerator = new Faker(); + private static readonly Faker BogusGenerator = new Faker(); + private static readonly OperationContextConverter DefaultConverter = new OperationContextConverter(new ApplicationInsightsSinkOptions()); - [Fact] - public void EnrichWithCorrelationInfo_TraceWithOperationId_OperationIdSetOnContext() - { - // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new TraceTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_TraceWithoutOperationId_NoOperationIdSetOnContext() - { - // Arrange - var traceTelemetry = new TraceTelemetry(); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_EventWithOperationId_OperationIdSetOnContext() - { - // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new EventTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_EventWithoutOperationId_NoOperationIdSetOnContext() + public static IEnumerable NonRequestTelemetry => new[] { - // Arrange - var traceTelemetry = new EventTelemetry(); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); - } + new object[] { new TraceTelemetry() }, + new object[] { new ExceptionTelemetry() }, + new object[] { new DependencyTelemetry() }, + new object[] { new MetricTelemetry() }, + new object[] { new EventTelemetry() } + }; - [Fact] - public void EnrichWithCorrelationInfo_MetricWithOperationId_OperationIdSetOnContext() + [Theory] + [MemberData(nameof(NonRequestTelemetry))] + public void EnrichWithCorrelationInfo_WithNonRequestTelemetry_Succeeds(TEntry telemetry) + where TEntry : ITelemetry, ISupportProperties { // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new MetricTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); + var operationId = $"operation-{Guid.NewGuid()}"; + var transactionId = $"transaction-{Guid.NewGuid()}"; + telemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); + telemetry.Properties.Add(ContextProperties.Correlation.TransactionId, transactionId); // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); + DefaultConverter.EnrichWithCorrelationInfo(telemetry); // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); + Assert.Equal(operationId, telemetry.Context.Operation.ParentId); + Assert.Equal(transactionId, telemetry.Context.Operation.Id); } - [Fact] - public void EnrichWithCorrelationInfo_MetricWithoutOperationId_NoOperationIdSetOnContext() + [Theory] + [MemberData(nameof(NonRequestTelemetry))] + public void EnrichWithCorrelationInfo_WithNonRequestTelemetry_IgnoresCorrelation(TEntry telemetry) + where TEntry : ITelemetry, ISupportProperties { - // Arrange - var traceTelemetry = new MetricTelemetry(); - var converter = new OperationContextConverter(); - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); + DefaultConverter.EnrichWithCorrelationInfo(telemetry); // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_DependencyWithOperationId_OperationIdSetOnContext() - { - // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new DependencyTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_DependencyWithoutOperationId_NoOperationIdSetOnContext() - { - // Arrange - var traceTelemetry = new DependencyTelemetry(); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); + Assert.Null(telemetry.Context.Operation.ParentId); + Assert.Null(telemetry.Context.Operation.Id); } [Fact] public void EnrichWithCorrelationInfo_RequestWithOperationId_OperationIdSetOnContext() { // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new RequestTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); + var operationId = $"operation-{Guid.NewGuid()}"; + var transactionId = $"transaction-{Guid.NewGuid()}"; + var operationParentId = $"parent-{Guid.NewGuid()}"; + var telemetry = new RequestTelemetry(); + telemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); + telemetry.Properties.Add(ContextProperties.Correlation.TransactionId, transactionId); + telemetry.Properties.Add(ContextProperties.Correlation.OperationParentId, operationParentId); // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); + DefaultConverter.EnrichWithCorrelationInfo(telemetry); // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_RequestWithoutOperationId_NoOperationIdSetOnContext() - { - // Arrange - var traceTelemetry = new RequestTelemetry(); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_ExceptionWithOperationId_OperationIdSetOnContext() - { - // Arrange - var operationId = Guid.NewGuid().ToString(); - var traceTelemetry = new ExceptionTelemetry(); - traceTelemetry.Properties.Add(ContextProperties.Correlation.OperationId, operationId); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Equal(operationId, traceTelemetry.Context.Operation.Id); - } - - [Fact] - public void EnrichWithCorrelationInfo_ExceptionWithoutOperationId_NoOperationIdSetOnContext() - { - // Arrange - var traceTelemetry = new ExceptionTelemetry(); - var converter = new OperationContextConverter(); - - // Act - converter.EnrichWithCorrelationInfo(traceTelemetry); - - // Assert - Assert.NotNull(traceTelemetry); - Assert.NotNull(traceTelemetry.Context); - Assert.NotNull(traceTelemetry.Context.Operation); - Assert.Null(traceTelemetry.Context.Operation.Id); + Assert.Equal(operationId, telemetry.Id); + Assert.Equal(transactionId, telemetry.Context.Operation.Id); + Assert.Equal(operationParentId, telemetry.Context.Operation.ParentId); } [Fact] public void EnrichWithOperationName_RequestWithRequestNameAndOperationName_OperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); - var operationName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); + var operationName = BogusGenerator.Random.Word(); var traceTelemetry = new RequestTelemetry(); traceTelemetry.Name = telemetryName; traceTelemetry.Context.Operation.Name = operationName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry); @@ -253,13 +102,12 @@ public void EnrichWithOperationName_RequestWithRequestNameAndOperationName_Opera public void EnrichWithOperationName_RequestWithRequestNameWithoutOperationName_NoOperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); var traceTelemetry = new RequestTelemetry(); traceTelemetry.Name = telemetryName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry); @@ -272,13 +120,12 @@ public void EnrichWithOperationName_RequestWithRequestNameWithoutOperationName_N public void EnrichWithOperationName_DependencyWithRequestName_NoOperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); var traceTelemetry = new DependencyTelemetry(); traceTelemetry.Name = telemetryName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry); @@ -291,13 +138,12 @@ public void EnrichWithOperationName_DependencyWithRequestName_NoOperationNameSet public void EnrichWithOperationName_EventWithRequestName_NoOperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); var traceTelemetry = new EventTelemetry(); traceTelemetry.Name = telemetryName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry); @@ -310,13 +156,12 @@ public void EnrichWithOperationName_EventWithRequestName_NoOperationNameSetOnCon public void EnrichWithOperationName_AvailabilityWithRequestName_NoOperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); var traceTelemetry = new AvailabilityTelemetry(); traceTelemetry.Name = telemetryName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry); @@ -329,13 +174,12 @@ public void EnrichWithOperationName_AvailabilityWithRequestName_NoOperationNameS public void EnrichWithOperationName_MetricWithRequestName_NoOperationNameSetOnContext() { // Arrange - var telemetryName = _bogusGenerator.Random.Word(); + var telemetryName = BogusGenerator.Random.Word(); var traceTelemetry = new MetricTelemetry(); traceTelemetry.Name = telemetryName; - var converter = new OperationContextConverter(); // Act - converter.EnrichWithOperationName(traceTelemetry); + DefaultConverter.EnrichWithOperationName(traceTelemetry); // Assert Assert.NotNull(traceTelemetry);