From af6f4bd9ad1c41868a587f52960ca2124e41a78b Mon Sep 17 00:00:00 2001 From: Stijn Moreels <9039753+stijnmoreels@users.noreply.github.com> Date: Thu, 6 Jan 2022 11:29:27 +0100 Subject: [PATCH] fix: use serilog scalar value when serializing string values (#262) * bug: use serilog scalar value when serializing string values * pr-del: remove comment-out code --- .../LogEventPropertyValueExtensions.cs | 26 +++--- .../Fixture/Order.cs | 17 ++++ .../Fixture/OrderGenerator.cs | 22 +++++ ...licationInsightsTelemetryConverterTests.cs | 81 ++++++++++++++++++- 4 files changed, 135 insertions(+), 11 deletions(-) create mode 100644 src/Arcus.Observability.Tests.Unit/Fixture/Order.cs create mode 100644 src/Arcus.Observability.Tests.Unit/Fixture/OrderGenerator.cs diff --git a/src/Arcus.Observability.Telemetry.Serilog.Enrichers/Extensions/LogEventPropertyValueExtensions.cs b/src/Arcus.Observability.Telemetry.Serilog.Enrichers/Extensions/LogEventPropertyValueExtensions.cs index 5b3a0d85..d2684711 100644 --- a/src/Arcus.Observability.Telemetry.Serilog.Enrichers/Extensions/LogEventPropertyValueExtensions.cs +++ b/src/Arcus.Observability.Telemetry.Serilog.Enrichers/Extensions/LogEventPropertyValueExtensions.cs @@ -1,6 +1,7 @@ using System; using System.Collections.Generic; using System.Globalization; +using System.IO; using System.Linq; using GuardNet; @@ -211,19 +212,26 @@ public static string ToDecentString(this LogEventPropertyValue logEventPropertyV { Guard.NotNull(logEventPropertyValue, nameof(logEventPropertyValue)); - var propertyValueAsString = logEventPropertyValue.ToString().Trim(); - - if (propertyValueAsString.StartsWith("\"")) + if (logEventPropertyValue is ScalarValue scalar) { - propertyValueAsString = propertyValueAsString.Remove(0, 1); + var result = scalar.Value.ToString(); + return result; } - - if (propertyValueAsString.EndsWith("\"")) + else { - propertyValueAsString = propertyValueAsString.Remove(propertyValueAsString.Length - 1); - } + string propertyValueAsString = logEventPropertyValue.ToString().Trim(); + if (propertyValueAsString.StartsWith("\"")) + { + propertyValueAsString = propertyValueAsString.Remove(0, 1); + } - return propertyValueAsString; + if (propertyValueAsString.EndsWith("\"")) + { + propertyValueAsString = propertyValueAsString.Remove(propertyValueAsString.Length - 1); + } + + return propertyValueAsString; + } } } } \ No newline at end of file diff --git a/src/Arcus.Observability.Tests.Unit/Fixture/Order.cs b/src/Arcus.Observability.Tests.Unit/Fixture/Order.cs new file mode 100644 index 00000000..a2572905 --- /dev/null +++ b/src/Arcus.Observability.Tests.Unit/Fixture/Order.cs @@ -0,0 +1,17 @@ +using System; +using System.Text.Json.Serialization; + +namespace Arcus.Observability.Tests.Unit.Fixture +{ + public class Order + { + [JsonPropertyName("id")] + public string Id { get; set; } + + [JsonPropertyName("orderNumber")] + public int OrderNumber { get; set; } + + [JsonPropertyName("scheduled")] + public DateTimeOffset Scheduled { get; set; } + } +} diff --git a/src/Arcus.Observability.Tests.Unit/Fixture/OrderGenerator.cs b/src/Arcus.Observability.Tests.Unit/Fixture/OrderGenerator.cs new file mode 100644 index 00000000..789d4f75 --- /dev/null +++ b/src/Arcus.Observability.Tests.Unit/Fixture/OrderGenerator.cs @@ -0,0 +1,22 @@ +using System; +using System.Collections.Generic; +using System.Text; +using Bogus; +using Moq; + +namespace Arcus.Observability.Tests.Unit.Fixture +{ + public static class OrderGenerator + { + public static Order Generate() + { + Order order = new Faker() + .RuleFor(model => model.Id, bogus => bogus.Random.Guid().ToString()) + .RuleFor(model => model.OrderNumber, bogus => bogus.Random.Int()) + .RuleFor(model => model.Scheduled, bogus => bogus.Date.RecentOffset()) + .Generate(); + + return order; + } + } +} diff --git a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs index fbd3edeb..ad6705e2 100644 --- a/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs +++ b/src/Arcus.Observability.Tests.Unit/Serilog/ApplicationInsightsTelemetryConverterTests.cs @@ -1,11 +1,15 @@ using System; using System.Collections.Generic; +using System.IO; +using System.Linq; using System.Net; using System.Net.Http; +using System.Xml.Serialization; using Arcus.Observability.Telemetry.Core; using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights; using Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights.Converters; using Arcus.Observability.Tests.Core; +using Arcus.Observability.Tests.Unit.Fixture; using Bogus; using Bogus.DataSets; using Microsoft.ApplicationInsights.Channel; @@ -21,6 +25,7 @@ using static Arcus.Observability.Telemetry.Core.ContextProperties; using HttpMethod = Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpMethod; using ILogger = Microsoft.Extensions.Logging.ILogger; +using JsonSerializer = System.Text.Json.JsonSerializer; namespace Arcus.Observability.Tests.Unit.Serilog { @@ -38,10 +43,13 @@ public void LogRequestMessage_WithRequestAndResponse_CreatesRequestTelemetry() ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var request = new HttpRequestMessage(System.Net.Http.HttpMethod.Get, new Uri("https://" + "localhost" + "/api/v1/health")); var statusCode = HttpStatusCode.OK; @@ -72,6 +80,7 @@ public void LogRequestMessage_WithRequestAndResponse_CreatesRequestTelemetry() AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); + AssertContainsTelemetryProperty(requestTelemetry, "RequestBody", json); }); } @@ -84,10 +93,13 @@ public void LogRequestMessage_WithRequestAndResponseStatusCode_CreatesRequestTel ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var request = new HttpRequestMessage(System.Net.Http.HttpMethod.Get, new Uri("https://" + "localhost" + "/api/v1/health")); var statusCode = HttpStatusCode.OK; @@ -117,6 +129,7 @@ public void LogRequestMessage_WithRequestAndResponseStatusCode_CreatesRequestTel AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); + AssertContainsTelemetryProperty(requestTelemetry, "RequestBody", json); }); } @@ -129,10 +142,13 @@ public void LogRequest_WithRequestAndResponse_CreatesRequestTelemetry() ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var statusCode = HttpStatusCode.OK; HttpRequest request = CreateStubRequest(HttpMethod.Get, "https", "localhost", "/api/v1/health"); @@ -163,6 +179,7 @@ public void LogRequest_WithRequestAndResponse_CreatesRequestTelemetry() AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); + AssertContainsTelemetryProperty(requestTelemetry, "RequestBody", json); }); } @@ -175,10 +192,13 @@ public void LogRequest_WithRequestAndResponseStatusCode_CreatesRequestTelemetry( ILogger logger = CreateLogger( spySink, config => config.Enrich.WithProperty(ContextProperties.Correlation.OperationId, operationId)); + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); var telemetryContext = new Dictionary { ["Client"] = "https://localhost", ["ContentType"] = "application/json", + ["RequestBody"] = json }; var statusCode = (int)HttpStatusCode.OK; HttpRequest request = CreateStubRequest(HttpMethod.Get, "https", "localhost", "/api/v1/health"); @@ -208,6 +228,7 @@ public void LogRequest_WithRequestAndResponseStatusCode_CreatesRequestTelemetry( AssertContainsTelemetryProperty(requestTelemetry, "Client", "https://localhost"); AssertContainsTelemetryProperty(requestTelemetry, "ContentType", "application/json"); + AssertContainsTelemetryProperty(requestTelemetry, "RequestBody", json); }); } @@ -222,9 +243,13 @@ public void LogDependency_WithDependency_CreatesDependencyTelemetry() const int dependencyData = 10; var startTime = DateTimeOffset.UtcNow; var duration = TimeSpan.FromSeconds(5); + + Order order = OrderGenerator.Generate(); + string xml = SerializeXml(order); var telemetryContext = new Dictionary { - ["CustomSetting"] = "Approved" + ["CustomSetting"] = "Approved", + ["CustomXml"] = xml }; logger.LogDependency(dependencyType, dependencyData, isSuccessful: true, startTime: startTime, duration: duration, context: telemetryContext); LogEvent logEvent = Assert.Single(spySink.CurrentLogEmits); @@ -247,9 +272,21 @@ public void LogDependency_WithDependency_CreatesDependencyTelemetry() Assert.True(dependencyTelemetry.Success); AssertContainsTelemetryProperty(dependencyTelemetry, "CustomSetting", "Approved"); + AssertContainsTelemetryProperty(dependencyTelemetry, "CustomXml", xml); }); } + private static string SerializeXml(Order order) + { + using (var writer = new StringWriter()) + { + var serializer = new XmlSerializer(typeof(Order)); + serializer.Serialize(writer, order); + + return writer.ToString(); + } + } + [Fact] public void LogServiceBusDependency_WithServiceBusDependency_CreatesDependencyTelemetry() { @@ -688,6 +725,44 @@ public void LogEvent_WithEvent_CreatesEventTelemetry() }); } + [Fact] + public void LogEvent_WithJsonTelemetryValue_CreatesEventTelemetry() + { + // Arrange + 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)); + + Order order = OrderGenerator.Generate(); + string json = JsonSerializer.Serialize(order); + var context = new Dictionary + { + ["Value"] = json, + ["OrderId"] = "ABC", + ["Vendor"] = "Contoso" + }; + logger.LogEvent(eventName, context); + LogEvent logEvent = Assert.Single(spySink.CurrentLogEmits); + Assert.NotNull(logEvent); + + var converter = ApplicationInsightsTelemetryConverter.Create(); + + // Act + IEnumerable telemetries = converter.Convert(logEvent, formatProvider: null); + + // Assert + Assert.Collection(telemetries, telemetry => + { + var eventTelemetry = Assert.IsType(telemetry); + Assert.Equal(eventName, eventTelemetry.Name); + AssertOperationContext(eventTelemetry, operationId); + AssertContainsTelemetryProperty(eventTelemetry, "Value", json); + AssertContainsTelemetryProperty(eventTelemetry, "OrderId", "ABC"); + AssertContainsTelemetryProperty(eventTelemetry, "Vendor", "Contoso"); + }); + } + [Fact] public void LogException_WithException_CreatesExceptionTelemetry() { @@ -869,7 +944,9 @@ private static void AssertDoesContainLogProperty(LogEvent logEvent, string name) private static void AssertContainsTelemetryProperty(ISupportProperties telemetry, string key, string value) { - Assert.Contains(telemetry.Properties, prop => prop.Equals(new KeyValuePair(key, value))); + Assert.True( + telemetry.Properties.Contains(new KeyValuePair(key, value)), + $"Value ({value}) not in telemetry context ({String.Join(", ", telemetry.Properties.Select(item => $"[{item.Key}] = {item.Value}"))})"); } } }