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
arcus-azure · Jan 6, 2022 · af6f4bd · af6f4bd
1 parent e315bac
commit af6f4bd
Show file tree

Hide file tree

Showing 4 changed files with 135 additions and 11 deletions.
diff --git a/...s.Observability.Telemetry.Serilog.Enrichers/Extensions/LogEventPropertyValueExtensions.cs b/...s.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;
+            }
         }
     }
 }
diff --git a/src/Arcus.Observability.Tests.Unit/Fixture/Order.cs 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
@@ -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<Order>()
+                .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
@@ -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<string, object>
             {
                 ["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<string, object>
             {
                 ["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<string, object>
             {
                 ["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<string, object>
             {
                 ["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<string, object>
             {
-                ["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<string, object>
+            {
+                ["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<ITelemetry> telemetries = converter.Convert(logEvent, formatProvider: null);
+
+            // Assert
+            Assert.Collection(telemetries, telemetry =>
+            {
+                var eventTelemetry = Assert.IsType<EventTelemetry>(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<string, string>(key, value)));
+            Assert.True(
+                telemetry.Properties.Contains(new KeyValuePair<string, string>(key, value)), 
+                $"Value ({value}) not in telemetry context ({String.Join(", ", telemetry.Properties.Select(item => $"[{item.Key}] = {item.Value}"))})");
         }
     }
 }