EcsJsonConfiguration - With converters to protect against bad types

src/Elastic.CommonSchema/Serialization/JsonConfiguration.cs

@@ -14,18 +14,42 @@ public static class EcsJsonConfiguration
 		public static JsonSerializerOptions SerializerOptions { get; } = new ()
 		{
 			DefaultIgnoreCondition = JsonIgnoreCondition.WhenWritingDefault,
+
 			Encoder = JavaScriptEncoder.UnsafeRelaxedJsonEscaping,
 			PropertyNamingPolicy = new SnakeCaseJsonNamingPolicy(),
 			Converters =
 			{
-				new EcsDocumentJsonConverterFactory()
+				new EcsDocumentJsonConverterFactory(),
+				// System.Text.Json got significantly better at not tripping over BCL types with .NET 7.0.
+				// ECS should fallback from serialization failures in metadata however this list catches the most
+				// common offenders. This to ensure better interop with older ASP.NET version out of the box see:
+				// https://github.com/elastic/ecs-dotnet/issues/219
+				new EcsJsonStringConverter<System.Reflection.Assembly>(),
+				new EcsJsonStringConverter<System.Reflection.Module>(),
+				new EcsJsonStringConverter<System.Reflection.MemberInfo>(),
+				new EcsJsonStringConverter<System.Delegate>(),
+				new EcsJsonStringConverter<System.IO.Stream>(),
 			},
-
 		};
 
 		internal static readonly JsonConverter<DateTimeOffset> DateTimeOffsetConverter =
 			(JsonConverter<DateTimeOffset>)SerializerOptions.GetConverter(typeof(DateTimeOffset));
 
 		public static readonly EcsDocumentJsonConverter DefaultEcsDocumentJsonConverter = new();
+
+		private sealed class EcsJsonStringConverter<T> : JsonConverter<T>
+		{
+			public override bool CanConvert(Type typeToConvert) => typeof(T).IsAssignableFrom(typeToConvert);
+
+			public override T Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options) => default;
+
+			public override void Write(Utf8JsonWriter writer, T value, JsonSerializerOptions options)
+			{
+				if (value is null)
+					writer.WriteNullValue();
+				else
+					writer.WriteStringValue(value.ToString());
+			}
+		}
 	}
 }

src/Elastic.CommonSchema/Serialization/MetadataDictionaryConverter.cs

@@ -5,13 +5,23 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using System.Runtime.Serialization;
 using System.Text.Json;
 using System.Text.Json.Serialization;
 
 namespace Elastic.CommonSchema.Serialization
 {
 	internal class MetadataDictionaryConverter : JsonConverter<MetadataDictionary>
 	{
+		internal class MetaDataSerializationFailure
+		{
+			[JsonPropertyName("reason"), DataMember(Name = "reason")]
+			public string SerializationFailure { get; set; }
+
+			[JsonPropertyName("key"), DataMember(Name = "key")]
+			public string Property { get; set; }
+		}
+
 		public override MetadataDictionary Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options)
 		{
 			if (reader.TokenType != JsonTokenType.StartObject)
@@ -43,19 +53,41 @@ public override void Write(Utf8JsonWriter writer, MetadataDictionary value, Json
 		{
 			writer.WriteStartObject();
 
+			List<MetaDataSerializationFailure> failures = null;
+
 			foreach (var kvp in value)
 			{
 				var propertyName = kvp.Key;
-				writer.WritePropertyName(propertyName);
 
 				if (kvp.Value == null)
+				{
+					writer.WritePropertyName(propertyName);
 					writer.WriteNullValue();
+				}
 				else
 				{
-					var inputType = kvp.Value.GetType();
-					JsonSerializer.Serialize(writer, kvp.Value, inputType, options);
+					try
+					{
+						// The following is not safe
+						// JsonSerializer.Serialize(writer, kvp.Value, inputType, options);
+						// If a getter throws an exception we risk not logging anything
+
+						var bytes = JsonSerializer.SerializeToUtf8Bytes(kvp.Value, options);
+						writer.WritePropertyName(propertyName);
+						writer.WriteRawValue(bytes);
+					}
+					catch (Exception e)
+					{
+						failures ??= new List<MetaDataSerializationFailure>();
+						failures.Add(new MetaDataSerializationFailure { Property = propertyName, SerializationFailure = e.Message });
+					}
 				}
 			}
+			if (failures != null)
+			{
+				writer.WritePropertyName("__failures__");
+				JsonSerializer.Serialize(writer, failures, typeof(List<MetaDataSerializationFailure>), options);
+			}
 			writer.WriteEndObject();
 		}
 
@@ -68,7 +100,8 @@ private object ExtractValue(ref Utf8JsonReader reader, JsonSerializerOptions opt
 				case JsonTokenType.False: return false;
 				case JsonTokenType.True: return true;
 				case JsonTokenType.Null: return null;
-				case JsonTokenType.Number: return reader.TryGetInt64(out var result) ? result : reader.TryGetDouble(out var d) ? d : reader.GetDecimal();
+				case JsonTokenType.Number:
+					return reader.TryGetInt64(out var result) ? result : reader.TryGetDouble(out var d) ? d : reader.GetDecimal();
 				case JsonTokenType.StartObject:
 					return Read(ref reader, null, options);
 				case JsonTokenType.StartArray:

tests/Elastic.CommonSchema.NLog.Tests/ApmTests.cs

@@ -8,13 +8,13 @@
 using Elastic.Apm.Test.Common;
 using FluentAssertions;
 using Xunit;
+using Xunit.Abstractions;
 
 namespace Elastic.CommonSchema.NLog.Tests
 {
 	public class ApmTests : LogTestsBase
 	{
-
-		public ApmTests()
+		public ApmTests(ITestOutputHelper output) : base(output)
 		{
 			var configuration = new MockConfiguration("my-service", "my-service-node-name", "0.2.1");
 			if (!Apm.Agent.IsConfigured)

tests/Elastic.CommonSchema.NLog.Tests/EcsFieldsInTemplateTests.cs

@@ -7,11 +7,14 @@
 using FluentAssertions;
 using Xunit;
 using NLog;
+using Xunit.Abstractions;
 
 namespace Elastic.CommonSchema.NLog.Tests
 {
 	public class EcsFieldsInTemplateTests : LogTestsBase
 	{
+		public EcsFieldsInTemplateTests(ITestOutputHelper output) : base(output) { }
+
 		[Fact]
 		public void CanUseEcsFieldNamesAsTemplateProperty() => TestLogger((logger, getLogEvents) =>
 		{

tests/Elastic.CommonSchema.NLog.Tests/LogTestsBase.cs

@@ -12,16 +12,21 @@
 using NLog.Layouts;
 using Config=NLog.Config;
 using NLog.Targets;
+using Xunit.Abstractions;
 
 namespace Elastic.CommonSchema.NLog.Tests
 {
 	public abstract class LogTestsBase
 	{
+		protected LogTestsBase(ITestOutputHelper output) => TestOut = output;
+
+		private ITestOutputHelper TestOut { get; }
+
 		protected List<(string Json, EcsDocument Base)> ToEcsEvents(List<string> logEvents) =>
 			logEvents.Select(s => (s, EcsDocument.Deserialize(s)))
 				.ToList();
 
-		protected static void TestLogger(Action<ILogger, Func<List<string>>> act)
+		protected void TestLogger(Action<ILogger, Func<List<string>>> act)
 		{
 			// These layout renderers need to registered statically as ultimately ConfigurationItemFactory.Default is called in the call stack.
 			LayoutRenderer.Register<ApmTraceIdLayoutRenderer>(ApmTraceIdLayoutRenderer.Name); //generic
@@ -43,8 +48,12 @@ protected static void TestLogger(Action<ILogger, Func<List<string>>> act)
 			List<string> GetAndValidateLogEvents()
 			{
 				foreach (var log in memoryTarget.Logs)
+				{
+					TestOut.WriteLine(log);
 					Spec.Validate(log);
 
+				}
+
 				return memoryTarget.Logs.ToList();
 			}
 

tests/Elastic.CommonSchema.NLog.Tests/MessageTests.cs

@@ -3,15 +3,19 @@
 // See the LICENSE file in the project root for more information
 
 using System;
+using System.Collections.Generic;
 using System.Linq;
 using FluentAssertions;
 using Xunit;
 using NLog;
+using Xunit.Abstractions;
 
 namespace Elastic.CommonSchema.NLog.Tests
 {
 	public class MessageTests : LogTestsBase
 	{
+		public MessageTests(ITestOutputHelper output) : base(output) { }
+
 		[Fact]
 		public void SeesMessage() => TestLogger((logger, getLogEvents) =>
 		{
@@ -96,6 +100,105 @@ public class NiceObject
 			public override string ToString() => $"X={ValueX}";
 		}
 
+		[Fact]
+		public void SeesMessageWithStructuredProperty() => TestLogger((logger, getLogEvents) =>
+		{
+			logger.Info("Info {@SafeValue}", new NiceObject() { ValueX = "X", SomeY = 2.2 });
+
+			var logEvents = getLogEvents();
+			logEvents.Should().HaveCount(1);
+
+			var ecsEvents = ToEcsEvents(logEvents);
+
+			var (_, info) = ecsEvents.First();
+			info.Message.Should().Be("Info {\"ValueX\":\"X\", \"SomeY\":2.2}");
+			info.Metadata.Should().ContainKey("SafeValue");
+
+			var x = info.Metadata["SafeValue"] as System.Collections.Generic.Dictionary<string, object>;
+			x.Should().NotBeNull().And.NotBeEmpty();
+		});
+
+		[Fact]
+		public void SeesMessageWithStructuredPropAsString() => TestLogger((logger, getLogEvents) =>
+		{
+			logger.Info("Info {StructuredValue}", new NiceObject() { ValueX = "X", SomeY = 2.2 });
+
+			var logEvents = getLogEvents();
+			logEvents.Should().HaveCount(1);
+
+			var ecsEvents = ToEcsEvents(logEvents);
+
+			var (_, info) = ecsEvents.First();
+			info.Message.Should().Be("Info X=X");
+			info.Metadata.Should().BeNull();
+			info.Labels.Should().NotBeNull();
+			info.Labels.Should().ContainKey("StructuredValue");
+
+			var x = info.Labels["StructuredValue"];
+			x.Should().NotBeNull().And.Be("X=X");
+		});
+
+		[Fact]
+		public void SerializesKnownBadObject() => TestLogger((logger, getLogEvents) =>
+		{
+			logger.Info("Info {@EvilValue}", new BadObject());
+
+			var logEvents = getLogEvents();
+			logEvents.Should().HaveCount(1);
+
+			var ecsEvents = ToEcsEvents(logEvents);
+
+			var (_, info) = ecsEvents.First();
+			info.Message.Should().StartWith("Info {\"MethodInfoProperty");
+			info.Metadata.Should().ContainKey("EvilValue");
+
+			var x = info.Metadata["EvilValue"] as System.Collections.Generic.Dictionary<string, object>;
+			x.Should().NotBeNull().And.NotBeEmpty();
+		});
+
+		[Fact]
+		public void SerializesObjectThatThrowsOnGetter() => TestLogger((logger, getLogEvents) =>
+		{
+			logger.Info("Info {@EvilValue}", new BadObject(true));
+
+			var logEvents = getLogEvents();
+			logEvents.Should().HaveCount(1);
+
+			var ecsEvents = ToEcsEvents(logEvents);
+
+			var (_, info) = ecsEvents.First();
+			info.Message.Should().StartWith("Info {\"MethodInfoProperty");
+			info.Metadata.Should().NotContainKey("EvilValue");
+			info.Metadata.Should().ContainKey("__failures__");
+
+			var failures = info.Metadata["__failures__"] as List<object>;
+			failures.Should().NotBeNull().And.HaveCount(1);
+			var failure = failures[0] as MetadataDictionary;
+			failure["reason"].Should().NotBeNull();
+			failure["key"].Should().Be("EvilValue");
+		});
+
+		private class BadObject
+		{
+			private readonly bool _throws;
+			// public IEnumerable<object> Recursive => new List<object>(new[] { "Hello", (object)this })
+
+			public BadObject() => _throws = false;
+			public BadObject(bool @throw) => _throws = @throw;
+
+			public System.Type TypeProperty { get; } = typeof(BadObject);
+
+			public System.Reflection.MethodInfo MethodInfoProperty { get; } = typeof(BadObject).GetProperty(nameof(MethodInfoProperty)).GetMethod;
+
+			public System.Action DelegateProperty { get; } = new System.Action(() => throw new NotSupportedException());
+
+			public System.Collections.IEqualityComparer ComparerProperty { get; } = StringComparer.OrdinalIgnoreCase;
+
+			public System.IFormatProvider CultureProperty { get; } = System.Globalization.CultureInfo.InvariantCulture;
+
+			public string EvilProperty => _throws ? throw new NotSupportedException() : "EvilProperty";
+		}
+
 		[Fact]
 		public void SeesMessageWithException() => TestLogger((logger, getLogEvents) =>
 		{
@@ -146,5 +249,6 @@ public void MetadataWithSameKeys() => TestLogger((logger, getLogEvents) =>
 				y.Should().NotBeNull().And.Be("Mdlc");
 			}
 		});
+
 	}
 }

tests/Elastic.CommonSchema.NLog.Tests/OutputTests.cs

@@ -6,11 +6,14 @@
 using System.Linq;
 using FluentAssertions;
 using Xunit;
+using Xunit.Abstractions;
 
 namespace Elastic.CommonSchema.NLog.Tests
 {
 	public class OutputTests : LogTestsBase
 	{
+		public OutputTests(ITestOutputHelper output) : base(output) { }
+
 		[Fact]
 		public void LogMultiple() => TestLogger((logger, getLogEvents) =>
 		{