log4net layout: log latest scope value (#367)

* Fix test by using case insensitive version of StartsWith(). * Adjust test names. * Put latest property value to metadata (requires latest log4net version). * Update readme to reflect the latest state of generated events.
elastic · Apr 4, 2024 · bd57c3b · bd57c3b
1 parent 7899022
commit bd57c3b
Show file tree

Hide file tree

Showing 6 changed files with 412 additions and 333 deletions.
diff --git a/src/Elastic.CommonSchema.Log4net/Elastic.CommonSchema.Log4net.csproj b/src/Elastic.CommonSchema.Log4net/Elastic.CommonSchema.Log4net.csproj
@@ -10,6 +10,6 @@
     <ProjectReference Include="..\Elastic.CommonSchema\Elastic.CommonSchema.csproj" />
   </ItemGroup>
   <ItemGroup>
-    <PackageReference Include="log4net" Version="2.0.15" />
+    <PackageReference Include="log4net" Version="2.0.17" />
   </ItemGroup>
 </Project>
diff --git a/src/Elastic.CommonSchema.Log4net/LoggingEventConverter.cs b/src/Elastic.CommonSchema.Log4net/LoggingEventConverter.cs
@@ -78,14 +78,17 @@ private static MetadataDictionary GetMetadata(LoggingEvent loggingEvent)
 
 			var value = properties[property];
 
-			// use string representation of stacks because:
-			// - if stack is empty then null is returned
-			// - if stack contains one item log4net anyway supports only string values
-			// - if stack contains several items then we need all of them
+			// use latest string representation of the value in the stack
 			if (value is ThreadContextStack tcs)
-				value = tcs.ToString();
+			{
+				var stackValue = tcs.Peek();
+				value = !string.IsNullOrEmpty(stackValue) ? stackValue : null;
+			}
 			else if (value is LogicalThreadContextStack ltcs)
-				value = ltcs.ToString();
+			{
+				var stackValue = ltcs.Peek();
+				value = !string.IsNullOrEmpty(stackValue) ? stackValue : null;
+			}
 
 			if (value != null)
 				metadata[property] = value;

diff --git a/src/Elastic.CommonSchema.Log4net/README.md b/src/Elastic.CommonSchema.Log4net/README.md
@@ -45,6 +45,7 @@ is supported and will directly set the appropriate ECS field.
 
 Apart from [mandatory fields](https://www.elastic.co/guide/en/ecs/current/ecs-guidelines.html#_general_guidelines), the output contains additional data:
 
+- `labels` is taken from `metadata` (string and boolean properties)
 - `log.origin.file.name` is taken from `LocationInformation`
 - `log.origin.file.line` is taken from `LocationInformation`
 - `log.origin.function` is taken from `LocationInformation`
@@ -67,21 +68,7 @@ Sample log event output (formatted for readability):
     "@timestamp": "2022-08-28T14:06:28.5121651+02:00",
     "log.level": "INFO",
     "message": "Hi! Welcome to example!",
-    "metadata": {
-        "global_property": "Example",
-        "message_template": "{0}! Welcome to example!"
-        "0": "Hi"
-    },
-    "ecs": {
-        "version": "8.3.1"
-    },
-    "event": {
-        "timezone": "Central European Time",
-        "created": "2022-08-28T14:06:28.5121651+02:00"
-    },
-    "host": {
-        "hostname": "HGU780D3"
-    },
+    "ecs.version": "8.6.0",
     "log": {
         "logger": "Elastic.CommonSchema.Log4net.Example.Program",
         "original": null,
@@ -93,14 +80,46 @@ Sample log event output (formatted for readability):
             "function": "Main"
         }
     },
+    "labels": {
+        "MessageTemplate": "{0}! Welcome to example!"
+        "0": "Hi"
+    },
+    "agent": {
+        "type": "Elastic.CommonSchema.Log4net.Example",
+        "version": "1.0.0.0"
+    },
+    "event": {
+        "created": "2024-04-02T17:43:55.3829964+02:00",
+        "timezone": "W. Europe Standard Time"
+    },
+    "host": {
+        "os": {
+            "full": "Microsoft Windows 10.0.22631",
+            "platform": "Win32NT",
+            "version": "10.0.22631.0"
+        },
+        "architecture": "X64",
+        "hostname": "HGU780D3",
+        "name": "HGU780D3"
+    },
     "process": {
-        "thread": {
-            "id": 1
-        }
+        "name": "Elastic.CommonSchema.Log4net.Example",
+        "pid": 39652,
+        "thread.id": 17,
+        "thread.name": ".NET Long Running Task",
+        "title": ""
     },
     "service": {
         "name": "Elastic.CommonSchema.Log4net.Example",
+        "type": "dotnet",
         "version": "1.0.0.0"
+    },
+    "user": {
+        "domain": "company",
+        "name": "user"
+    },
+    "metadata": {
+        "GlobalAmountProperty": 3.14
     }
 }
 ```

diff --git a/tests/Elastic.CommonSchema.Log4net.Tests/EcsFieldsAsPropertiesTests.cs b/tests/Elastic.CommonSchema.Log4net.Tests/EcsFieldsAsPropertiesTests.cs
@@ -10,95 +10,54 @@
 using log4net.Core;
 using Xunit;
 
-namespace Elastic.CommonSchema.Log4net.Tests
-{
-	[CollectionDefinition("EcsProperties", DisableParallelization = true)]
-	public class EcsFieldsAsPropertiesTests : LogTestsBase
-	{
-		private const string FixedTraceId = "my-trace-id";
-
-		[Fact]
-		public void EcsFieldInLogProperties()
-		{
-			void LogAndAssert(ILog log, Func<List<string>> getLogEvents)
-			{
-				log.Info("DummyText");
-
-				var logEvents = getLogEvents();
-				logEvents.Should().HaveCount(1);
-
-				var (_, info) = ToEcsEvents(logEvents).First();
-				info.TraceId.Should().Be(FixedTraceId);
-			}
-
-			// Testing these in one unit test because ThreadContext overwrites LogicalThreadContext which overwrites GlobalContext.
-			// Testing these in isolation introduces race issues when we remove the property
-
-			LogicalThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
-			try
-			{
-				TestLogger(LogAndAssert);
-			}
-			finally
-			{
-				LogicalThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
-			}
-
-			ThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
-			try
-			{
-				TestLogger(LogAndAssert);
-			}
-			finally
-			{
-				ThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
-			}
-			TestLogger((log, getLogEvents) =>
-			{
-				var loggingEvent = new LoggingEvent(GetType(), log.Logger.Repository, log.Logger.Name, Level.Info, "DummyText", null);
-				loggingEvent.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
-				log.Logger.Log(loggingEvent);
-
-				var logEvents = getLogEvents();
-				logEvents.Should().HaveCount(1);
-
-				var (_, info) = ToEcsEvents(logEvents).First();
-				info.TraceId.Should().Be(FixedTraceId);
-			});
-
-			GlobalContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
-			try
-			{
-				TestLogger(LogAndAssert);
-			}
-			finally
-			{
-				GlobalContext.Properties.Remove(LogTemplateProperties.TraceId);
-			}
-
-		}
+namespace Elastic.CommonSchema.Log4net.Tests;
 
+[CollectionDefinition("EcsProperties", DisableParallelization = true)]
+public class EcsFieldsAsPropertiesTests : LogTestsBase
+{
+	private const string FixedTraceId = "my-trace-id";
 
-		[Fact]
-		public void EcsFieldsInThreadContextStack() => TestLogger((log, getLogEvents) =>
+	[Fact]
+	public void EcsFieldInLogProperties()
+	{
+		void LogAndAssert(ILog log, Func<List<string>> getLogEvents)
 		{
-			using var _ = ThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);
-
 			log.Info("DummyText");
 
 			var logEvents = getLogEvents();
 			logEvents.Should().HaveCount(1);
 
 			var (_, info) = ToEcsEvents(logEvents).First();
 			info.TraceId.Should().Be(FixedTraceId);
-		});
+		}
+
+		// Testing these in one unit test because ThreadContext overwrites LogicalThreadContext which overwrites GlobalContext.
+		// Testing these in isolation introduces race issues when we remove the property
 
-		[Fact]
-		public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEvents) =>
+		LogicalThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
+		try
+		{
+			TestLogger(LogAndAssert);
+		}
+		finally
 		{
-			using var _ = LogicalThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);
+			LogicalThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
+		}
 
-			log.Info("DummyText");
+		ThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
+		try
+		{
+			TestLogger(LogAndAssert);
+		}
+		finally
+		{
+			ThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
+		}
+		TestLogger((log, getLogEvents) =>
+		{
+			var loggingEvent = new LoggingEvent(GetType(), log.Logger.Repository, log.Logger.Name, Level.Info, "DummyText", null);
+			loggingEvent.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
+			log.Logger.Log(loggingEvent);
 
 			var logEvents = getLogEvents();
 			logEvents.Should().HaveCount(1);
@@ -107,5 +66,43 @@ public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEven
 			info.TraceId.Should().Be(FixedTraceId);
 		});
 
+		GlobalContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
+		try
+		{
+			TestLogger(LogAndAssert);
+		}
+		finally
+		{
+			GlobalContext.Properties.Remove(LogTemplateProperties.TraceId);
+		}
+
 	}
+
+	[Fact]
+	public void EcsFieldsInThreadContextStack() => TestLogger((log, getLogEvents) =>
+	{
+		using var _ = ThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);
+
+		log.Info("DummyText");
+
+		var logEvents = getLogEvents();
+		logEvents.Should().HaveCount(1);
+
+		var (_, info) = ToEcsEvents(logEvents).First();
+		info.TraceId.Should().Be(FixedTraceId);
+	});
+
+	[Fact]
+	public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEvents) =>
+	{
+		using var _ = LogicalThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);
+
+		log.Info("DummyText");
+
+		var logEvents = getLogEvents();
+		logEvents.Should().HaveCount(1);
+
+		var (_, info) = ToEcsEvents(logEvents).First();
+		info.TraceId.Should().Be(FixedTraceId);
+	});
 }
diff --git a/tests/Elastic.CommonSchema.Log4net.Tests/LogTestsBase.cs b/tests/Elastic.CommonSchema.Log4net.Tests/LogTestsBase.cs
@@ -10,41 +10,39 @@
 using log4net.Core;
 using log4net.Repository.Hierarchy;
 
+namespace Elastic.CommonSchema.Log4net.Tests;
 
-namespace Elastic.CommonSchema.Log4net.Tests
+public abstract class LogTestsBase
 {
-	public abstract class LogTestsBase
-	{
-		private static readonly object _lock = new();
-		protected List<(string Json, EcsDocument Base)> ToEcsEvents(List<string> logEvents) =>
-			logEvents.Select(s => (s, EcsDocument.Deserialize(s)))
-				.ToList();
+	private static readonly object _lock = new();
+	protected List<(string Json, EcsDocument Base)> ToEcsEvents(List<string> logEvents) =>
+		logEvents.Select(s => (s, EcsDocument.Deserialize(s)))
+			.ToList();
 
-		protected void TestLogger(Action<ILog, Func<List<string>>> act)
+	protected void TestLogger(Action<ILog, Func<List<string>>> act)
+	{
+		lock (_lock)
 		{
-			lock (_lock)
+			var repositoryId = Guid.NewGuid().ToString();
+			var hierarchy = (Hierarchy)LogManager.CreateRepository(repositoryId);
+			var appender = new TestAppender
 			{
-				var repositoryId = Guid.NewGuid().ToString();
-				var hierarchy = (Hierarchy)LogManager.CreateRepository(repositoryId);
-				var appender = new TestAppender
-				{
-					Layout = new EcsLayout()
-				};
-				hierarchy.Root.AddAppender(appender);
-				hierarchy.Root.Level = Level.All;
-				hierarchy.Configured = true;
-
-				List<string> GetAndValidateLogEvents()
-				{
-					foreach (var log in appender.Events)
-						Spec.Validate(log);
+				Layout = new EcsLayout()
+			};
+			hierarchy.Root.AddAppender(appender);
+			hierarchy.Root.Level = Level.All;
+			hierarchy.Configured = true;
 
-					return appender.Events;
-				}
+			List<string> GetAndValidateLogEvents()
+			{
+				foreach (var log in appender.Events)
+					Spec.Validate(log);
 
-				var log = LogManager.GetLogger(repositoryId, GetType().Name);
-				act(log, GetAndValidateLogEvents);
+				return appender.Events;
 			}
+
+			var log = LogManager.GetLogger(repositoryId, GetType().Name);
+			act(log, GetAndValidateLogEvents);
 		}
 	}
 }