From f8d435d45f2ec05ffdc7d920f1a61af48cd711d0 Mon Sep 17 00:00:00 2001 From: andreycha Date: Fri, 12 Apr 2024 12:26:38 +0200 Subject: [PATCH] Add structured logging support. --- README.md | 7 +- doc/ModifyingLoggingBehaviour.md | 18 ++++- .../Log4NetLoggingEventFactory.cs | 73 +++++++++++++++---- tests/Unit.Tests/Log4NetLoggerTests.cs | 59 +++++++++++---- ...OverriddenPropertiesLoggingEventFactory.cs | 20 +++++ .../OverriddenScopesLoggingEventFactory.cs | 19 +++++ 6 files changed, 163 insertions(+), 33 deletions(-) create mode 100644 tests/Unit.Tests/Mocks/OverriddenPropertiesLoggingEventFactory.cs create mode 100644 tests/Unit.Tests/Mocks/OverriddenScopesLoggingEventFactory.cs diff --git a/README.md b/README.md index daa5364..0b3240f 100644 --- a/README.md +++ b/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. diff --git a/doc/ModifyingLoggingBehaviour.md b/doc/ModifyingLoggingBehaviour.md index 2d09f6c..4f637be 100644 --- a/doc/ModifyingLoggingBehaviour.md +++ b/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( MessageCandidate 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(LoggingEvent loggingEvent, in MessageCandidate 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(), }); -``` \ No newline at end of file +``` diff --git a/src/Microsoft.Extensions.Logging.Log4Net.AspNetCore/Log4NetLoggingEventFactory.cs b/src/Microsoft.Extensions.Logging.Log4Net.AspNetCore/Log4NetLoggingEventFactory.cs index 097fb71..e92e3e4 100644 --- a/src/Microsoft.Extensions.Logging.Log4Net.AspNetCore/Log4NetLoggingEventFactory.cs +++ b/src/Microsoft.Extensions.Logging.Log4Net.AspNetCore/Log4NetLoggingEventFactory.cs @@ -20,6 +20,11 @@ public class Log4NetLoggingEventFactory /// protected const string DefaultScopeProperty = "scope"; + /// + /// The property name for message format as used in Microsoft.Extensions.Logging.FormattedLogValues. + /// + protected const string OriginalFormatProperty = "{OriginalFormat}"; + /// public LoggingEvent CreateLoggingEvent( in MessageCandidate messageCandidate, @@ -43,8 +48,8 @@ public LoggingEvent CreateLoggingEvent( 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) + if (item is KeyValuePair kvpString) { - var keyValuePair = (KeyValuePair)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) + if (item is KeyValuePair kvpObject) { - var keyValuePair = (KeyValuePair)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() { - if (scope is ValueTuple) + if (scope is ValueTuple valueTuple) { - var valueTuple = (ValueTuple)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() }, loggingEvent); } - + + /// + /// Enriches logging event with additional properties. + /// + /// + /// 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. + /// + /// Type of the state that is used to format the error message. + /// The properties will be added to. + /// Log message candidate. + protected virtual void EnrichProperties(LoggingEvent loggingEvent, in MessageCandidate messageCandidate) + { + loggingEvent.Properties[EventIdProperty] = messageCandidate.EventId; + + // State is always passed as Microsoft.Extensions.Logging.FormattedLogValues which is internal + // but implements IReadOnlyCollection> + if (messageCandidate.State is IReadOnlyCollection> 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 value) + { + var convertedValue = Convert.ToString(value, CultureInfo.InvariantCulture); + return convertedValue; + } + private static string JoinOldAndNewValue(string previousValue, string newValue) { if (string.IsNullOrEmpty(previousValue)) diff --git a/tests/Unit.Tests/Log4NetLoggerTests.cs b/tests/Unit.Tests/Log4NetLoggerTests.cs index 4761027..8953aee 100644 --- a/tests/Unit.Tests/Log4NetLoggerTests.cs +++ b/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(MockBehavior.Strict); + options.LoggingEventFactory = new OverriddenScopesLoggingEventFactory( + (@event) => @event.Properties[customPropertyValue] = expectedCustomPropertyValue); - mockedFactory.Protected() - .Setup("EnrichWithScopes", ItExpr.IsAny(), scopeProvider) - .Callback( - (@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() { diff --git a/tests/Unit.Tests/Mocks/OverriddenPropertiesLoggingEventFactory.cs b/tests/Unit.Tests/Mocks/OverriddenPropertiesLoggingEventFactory.cs new file mode 100644 index 0000000..f048a5f --- /dev/null +++ b/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 _enrichPropertiesOverride; + + public OverriddenPropertiesLoggingEventFactory(Action enrichPropertiesOverride) + { + _enrichPropertiesOverride = enrichPropertiesOverride; + } + + protected override void EnrichProperties(LoggingEvent loggingEvent, in MessageCandidate messageCandidate) + => _enrichPropertiesOverride(loggingEvent); + } +} \ No newline at end of file diff --git a/tests/Unit.Tests/Mocks/OverriddenScopesLoggingEventFactory.cs b/tests/Unit.Tests/Mocks/OverriddenScopesLoggingEventFactory.cs new file mode 100644 index 0000000..4188a55 --- /dev/null +++ b/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 _enrichWithScopesOverride; + + public OverriddenScopesLoggingEventFactory(Action enrichWithScopesOverride) + { + _enrichWithScopesOverride = enrichWithScopesOverride; + } + + protected override void EnrichWithScopes(LoggingEvent loggingEvent, IExternalScopeProvider scopeProvider) + => _enrichWithScopesOverride(loggingEvent); + } +} \ No newline at end of file