Add structured logging support

README.md

@@ -31,8 +31,8 @@ public class Startup
     }
 }
 ```
-* For dotnet 6.0 and later add `builder.Logging.AddLog4Net();` call in your `Program.cs` file.
 
+* For dotnet 6.0 and later add `builder.Logging.AddLog4Net();` call in your `Program.cs` file.
 
 * Add a `log4net.config` file with the content:
 
@@ -149,6 +149,7 @@ public static IWebHost BuildWebHost(string[] args) =>
             })
             .Build();
 ```
+
 ### Logging lower than the Information Level
 
 > Associated issues #85
@@ -165,6 +166,10 @@ Also note that when trying to allow for levels messages below the Information le
 }
 ```
 
+### Structured logging
+
+Structured logging is supported in a way that message format string and its arguments are stored in logging event properties. The message format string is stored in a property named "MessageTemplate", arguments are stored in properties whose names correspond to the argument names and values are string representations of the argument values.
+
 ### Modifying logging behaviour
 In many cases you can modfiy the logging behaviour of the provider to fit your own needs. See [modifying logging behaviour](/doc/ModifyingLoggingBehaviour.md) for more information.
 

doc/ModifyingLoggingBehaviour.md

@@ -86,7 +86,7 @@ public interface ILog4NetLoggingEventFactory
 It can for example be used to extract the state information passed to the logging provider and include it in the message object:
 
 ```csharp
-public class CustomLoggingEventFactory
+public class CustomLoggingEventFactory : ILog4NetLoggingEventFactory
 {
     LoggingEvent CreateLoggingEvent<TState>(
         MessageCandidate<TState> messageCandidate,
@@ -150,10 +150,24 @@ public class CustomLoggingEventFactory
 }
 ```
 
+It is also possible to inherit default implementation `LoggingEventFactory` and override `EnrichWithScope()` and/or `EnrichProperties` methods:
+
+```csharp
+public class CustomLoggingEventFactory : LoggingEventFactory
+{
+    protected override void EnrichProperties<TState>(LoggingEvent loggingEvent, in MessageCandidate<TState> messageCandidate)
+    {
+        base.EnrichProperties(loggingEvent, in messageCandidate);
+        loggingEvent.Properties["ApplicationName"] = Assembly.GetEntryAssembly().GetName().Name;
+        loggingEvent.Properties["ApplicationVersion"] = Assembly.GetEntryAssembly().GetName().Version.ToString();
+    }
+}
+```
+
 Afterwards we can configure the provider to use this mapping by specifying it `Log4NetProviderOptions.LoggingEventFactory`.
 
 ```csharp
 loggerFactory.AddLog4Net(new Log4NetProviderOptions {
     LoggingEventFactory = new CustomLoggingEventFactory(),
 });
-```
+```

src/Microsoft.Extensions.Logging.Log4Net.AspNetCore/Log4NetLoggingEventFactory.cs

@@ -20,6 +20,11 @@ public class Log4NetLoggingEventFactory
         /// </summary>
         protected const string DefaultScopeProperty = "scope";
 
+        /// <summary>
+        /// The property name for message format as used in Microsoft.Extensions.Logging.FormattedLogValues.
+        /// </summary>
+        protected const string OriginalFormatProperty = "{OriginalFormat}";
+
         /// <inheritdoc/>
         public LoggingEvent CreateLoggingEvent<TState>(
             in MessageCandidate<TState> messageCandidate,
@@ -43,8 +48,8 @@ public LoggingEvent CreateLoggingEvent<TState>(
                 exception: messageCandidate.Exception);
 
             EnrichWithScopes(loggingEvent, scopeProvider);
-
-            loggingEvent.Properties[EventIdProperty] = messageCandidate.EventId;
+            // in case scope and formatted message contain arguments with the same names, formatted message should win
+            EnrichProperties(loggingEvent, in messageCandidate);
 
             return loggingEvent;
         }
@@ -86,24 +91,22 @@ protected virtual void EnrichWithScopes(LoggingEvent loggingEvent, IExternalScop
                 {
                     foreach (var item in col)
                     {
-                        if (item is KeyValuePair<string, string>)
+                        if (item is KeyValuePair<string, string> kvpString)
                         {
-                            var keyValuePair = (KeyValuePair<string, string>)item;
-                            string previousValue = @event.Properties[keyValuePair.Key] as string;
-                            @event.Properties[keyValuePair.Key] = JoinOldAndNewValue(previousValue, keyValuePair.Value);
+                            string previousValue = @event.Properties[kvpString.Key] as string;
+                            @event.Properties[kvpString.Key] = JoinOldAndNewValue(previousValue, kvpString.Value);
                             continue;
                         }
 
-                        if (item is KeyValuePair<string, object>)
+                        if (item is KeyValuePair<string, object> kvpObject)
                         {
-                            var keyValuePair = (KeyValuePair<string, object>)item;
-                            string previousValue = @event.Properties[keyValuePair.Key] as string;
+                            string previousValue = @event.Properties[kvpObject.Key] as string;
 
                             // The current culture should not influence how integers/floats/... are displayed in logging,
                             // so we are using Convert.ToString which will convert IConvertible and IFormattable with
                             // the specified IFormatProvider.
-                            string additionalValue = Convert.ToString(keyValuePair.Value, CultureInfo.InvariantCulture);
-                            @event.Properties[keyValuePair.Key] = JoinOldAndNewValue(previousValue, additionalValue);
+                            string additionalValue = ConvertValue(kvpObject.Value);
+                            @event.Properties[kvpObject.Key] = JoinOldAndNewValue(previousValue, additionalValue);
                             continue;
                         }
                     }
@@ -140,18 +143,17 @@ protected virtual void EnrichWithScopes(LoggingEvent loggingEvent, IExternalScop
                 if (scope is object)
                 {
                     string previousValue = @event.Properties[DefaultScopeProperty] as string;
-                    string additionalValue = Convert.ToString(scope, CultureInfo.InvariantCulture);
+                    string additionalValue = ConvertValue(scope);
                     @event.Properties[DefaultScopeProperty] = JoinOldAndNewValue(previousValue, additionalValue);
                     return;
                 }
 
                 bool FromValueTuple<T>()
                 {
-                    if (scope is ValueTuple<string, T>)
+                    if (scope is ValueTuple<string, T> valueTuple)
                     {
-                        var valueTuple = (ValueTuple<string, T>)scope;
                         string previousValue = @event.Properties[valueTuple.Item1] as string;
-                        string additionalValue = Convert.ToString(valueTuple.Item2, CultureInfo.InvariantCulture);
+                        string additionalValue = ConvertValue(valueTuple.Item2);
                         @event.Properties[valueTuple.Item1] = JoinOldAndNewValue(previousValue, additionalValue);
                         return true;
                     }
@@ -160,7 +162,46 @@ bool FromValueTuple<T>()
 
             }, loggingEvent);
         }
-
+
+        /// <summary>
+        /// Enriches logging event with additional properties.
+        /// </summary>
+        /// <remarks>
+        /// The default implementation will adds event id, original format string as "MessageTemplate" properties, and format arguments, if any.
+        /// Format arguments are added as strings using Convert.ToString(scope, CultureInfo.InvariantCulture).
+        /// If you want to do this conversion inside the Log4Net Pipeline, e. g. with a custom layout, you can override this
+        /// method and change the behaviour.
+        /// </remarks>
+        /// <typeparam name="TState">Type of the state that is used to format the error message.</typeparam>
+        /// <param name="loggingEvent">The <see cref="LoggingEvent"/> properties will be added to.</param>
+        /// <param name="messageCandidate">Log message candidate.</param>
+        protected virtual void EnrichProperties<TState>(LoggingEvent loggingEvent, in MessageCandidate<TState> messageCandidate)
+        {
+            loggingEvent.Properties[EventIdProperty] = messageCandidate.EventId;
+
+            // State is always passed as Microsoft.Extensions.Logging.FormattedLogValues which is internal
+            // but implements IReadOnlyCollection<KeyValuePair<string, object>>
+            if (messageCandidate.State is IReadOnlyCollection<KeyValuePair<string, object>> stateProperties)
+            {
+                foreach (var kvp in stateProperties)
+                {
+                    var key = kvp.Key;
+                    if (kvp.Key == OriginalFormatProperty && kvp.Value is string)
+                    {
+                        // change property name to match Serilog
+                        key = "MessageTemplate";
+                    }
+                    loggingEvent.Properties[key] = ConvertValue(kvp.Value);
+                }
+            }
+        }
+
+        private static string ConvertValue<T>(T value)
+        {
+            var convertedValue = Convert.ToString(value, CultureInfo.InvariantCulture);
+            return convertedValue;
+        }
+
         private static string JoinOldAndNewValue(string previousValue, string newValue)
         {
             if (string.IsNullOrEmpty(previousValue))

tests/Unit.Tests/Log4NetLoggerTests.cs

@@ -2,10 +2,10 @@
 using log4net.Appender;
 using log4net.Core;
 using Microsoft.Extensions.Logging;
+#if NET6_0
 using Microsoft.Extensions.Logging.Log4Net.AspNetCore.Entities;
-using Microsoft.Extensions.Logging.Log4Net.AspNetCore.Scope;
+#endif
 using Moq;
-using Moq.Protected;
 using System;
 using System.Collections.Generic;
 using System.IO;
@@ -299,20 +299,52 @@ public void Log_Should_Emit_Custom_Scope_Operations_Created_By_Overriden_Enrich_
             LoggerExternalScopeProvider scopeProvider = new LoggerExternalScopeProvider();
 
             var expectedRepository = log4net.LogManager.GetRepository(options.LoggerRepository);
+            var customPropertyValue = "customStuff";
             var expectedCustomPropertyValue = (4, 3f);
 
-            var mockedFactory = new Mock<Log4NetLoggingEventFactory>(MockBehavior.Strict);
+            options.LoggingEventFactory = new OverriddenScopesLoggingEventFactory(
+                (@event) => @event.Properties[customPropertyValue] = expectedCustomPropertyValue);
 
-            mockedFactory.Protected()
-                .Setup("EnrichWithScopes", ItExpr.IsAny<LoggingEvent>(), scopeProvider)
-                .Callback<LoggingEvent, IExternalScopeProvider>(
-                    (@event, _) =>
-                    {
-                        @event.Properties["customStuff"] = expectedCustomPropertyValue;
-                    }
-                ).Verifiable();
+            var testAppender = GetTestAppender(options);
+            var sut = new Log4NetLogger(options, scopeProvider);
 
-            options.LoggingEventFactory = mockedFactory.Object;
+            sut.Log(LogLevel.Debug, _eventId, _logState, null, (message, exception) => message);
+
+            testAppender.GetEvents()
+                        .Should()
+                        .NotBeEmpty()
+                        .And
+                        .HaveCount(1);
+
+            var loggingEvent = testAppender.GetEvents()
+                                           .First();
+
+            loggingEvent.Repository
+                        .Should()
+                        .Be(expectedRepository);
+            loggingEvent.Level
+                        .Should()
+                        .Be(Level.Debug);
+            loggingEvent.MessageObject
+                        .Should()
+                        .Be(_logState);
+            loggingEvent.GetProperties()[customPropertyValue]
+                        .Should()
+                        .Be(expectedCustomPropertyValue);
+        }
+
+        [Fact]
+        public void Log_Should_Emit_Custom_Scope_Operations_Created_By_Overriden_Enrich_Properties_Method()
+        {
+            var options = ConfigureOptions(Log4NetFileOption.TestAppenderTrace);
+            LoggerExternalScopeProvider scopeProvider = new LoggerExternalScopeProvider();
+
+            var expectedRepository = log4net.LogManager.GetRepository(options.LoggerRepository);
+            var customPropertyValue = "customStuff";
+            var expectedCustomPropertyValue = (4, 3f);
+
+            options.LoggingEventFactory = new OverriddenPropertiesLoggingEventFactory(
+                (@event) => @event.Properties[customPropertyValue] = expectedCustomPropertyValue);
 
             var testAppender = GetTestAppender(options);
             var sut = new Log4NetLogger(options, scopeProvider);
@@ -337,12 +369,11 @@ public void Log_Should_Emit_Custom_Scope_Operations_Created_By_Overriden_Enrich_
             loggingEvent.MessageObject
                         .Should()
                         .Be(_logState);
-            loggingEvent.GetProperties()["customStuff"]
+            loggingEvent.GetProperties()[customPropertyValue]
                         .Should()
                         .Be(expectedCustomPropertyValue);
         }
 
-
         [Fact]
         public void Log_Should_Emit_At_LogLevels_Translate_By_LogLevelTranslator()
         {

tests/Unit.Tests/Mocks/OverriddenPropertiesLoggingEventFactory.cs

@@ -0,0 +1,20 @@
+using System;
+using log4net.Core;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Log4Net.AspNetCore.Entities;
+
+namespace Unit.Tests.Mocks
+{
+    internal class OverriddenPropertiesLoggingEventFactory : Log4NetLoggingEventFactory
+    {
+        private readonly Action<LoggingEvent> _enrichPropertiesOverride;
+
+        public OverriddenPropertiesLoggingEventFactory(Action<LoggingEvent> enrichPropertiesOverride)
+        {
+            _enrichPropertiesOverride = enrichPropertiesOverride;
+        }
+
+        protected override void EnrichProperties<TState>(LoggingEvent loggingEvent, in MessageCandidate<TState> messageCandidate)
+           => _enrichPropertiesOverride(loggingEvent);
+    }
+}

tests/Unit.Tests/Mocks/OverriddenScopesLoggingEventFactory.cs

@@ -0,0 +1,19 @@
+using System;
+using log4net.Core;
+using Microsoft.Extensions.Logging;
+
+namespace Unit.Tests.Mocks
+{
+    internal class OverriddenScopesLoggingEventFactory : Log4NetLoggingEventFactory
+    {
+        private readonly Action<LoggingEvent> _enrichWithScopesOverride;
+
+        public OverriddenScopesLoggingEventFactory(Action<LoggingEvent> enrichWithScopesOverride)
+        {
+            _enrichWithScopesOverride = enrichWithScopesOverride;
+        }
+
+        protected override void EnrichWithScopes(LoggingEvent loggingEvent, IExternalScopeProvider scopeProvider)
+            => _enrichWithScopesOverride(loggingEvent);
+    }
+}