Format messages without quotes when log events come from Microsoft.Extensions.Logging

Also add the possibility to completely customize how the message is formatted with the new `Log4NetTextFormatterOptionsBuilder.UseMessageFormatter` method.

Author: 0xced

src/Log4NetTextFormatter.cs

@@ -53,6 +53,12 @@ public class Log4NetTextFormatter : ITextFormatter
     /// <remarks>https://github.com/pmetz-steelcase/Serilog.Enrichers.WithCaller/blob/1.2.0/Serilog.Enrichers.WithCaller/CallerEnricher.cs#L66</remarks>
     private const string CallerPropertyName = "Caller";
 
+    /// <summary>
+    /// The name of the event id property, set by <a href="https://www.nuget.org/packages/Serilog.Extensions.Logging/">Serilog.Extensions.Logging</a>
+    /// </summary>
+    /// <remarks>https://github.com/serilog/serilog-extensions-logging/blob/v9.0.1/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs#L158</remarks>
+    private const string EventIdPropertyName = "EventId";
+
     /// <summary>
     /// The regular exception matching "class", "method", and optionally "file" and "line" for the caller property.
     /// </summary>
@@ -130,6 +136,36 @@ public void Format(LogEvent logEvent, TextWriter output)
         output.Write(_options.XmlWriterSettings.NewLineChars);
     }
 
+    /// <summary>
+    /// The default message formatter.
+    /// <list type="bullet">
+    ///   <item>If the log event comes from <c>Microsoft.Extensions.Logging</c> (detected by the presence of the <c>EventId</c> property) then the message is formatted by switching off quoting of strings.</item>
+    ///   <item>If the log event comes from Serilog, then the message is formatted by calling <see cref="LogEvent.RenderMessage(System.IO.TextWriter,System.IFormatProvider)"/>.</item>
+    /// </list>
+    /// </summary>
+    /// <param name="logEvent">The log event to format.</param>
+    /// <param name="formatProvider">The <see cref="IFormatProvider"/> that supplies culture-specific formatting information, or <see langword="null"/>.</param>
+    /// <returns>The formatted message.</returns>
+    internal static string DefaultMessageFormatter(LogEvent logEvent, IFormatProvider? formatProvider)
+    {
+        // https://github.com/serilog/serilog-extensions-logging/blob/v9.0.1/src/Serilog.Extensions.Logging/Extensions/Logging/EventIdPropertyCache.cs#L58-L73
+        var isMicrosoftExtensionsLoggingEvent = logEvent.Properties.TryGetValue(EventIdPropertyName, out var property)
+                                                && property is StructureValue structure
+                                                && structure.Properties.Count == 2
+                                                && structure.Properties[0].Name == "Id"
+                                                && structure.Properties[1].Name == "Name";
+
+        if (isMicrosoftExtensionsLoggingEvent)
+        {
+            var formatter = new MessageTemplateTextFormatter($"{{{OutputProperties.MessagePropertyName}:l}}", formatProvider);
+            using var output = new StringWriter();
+            formatter.Format(logEvent, output);
+            return output.ToString();
+        }
+
+        return logEvent.RenderMessage(formatProvider);
+    }
+
     /// <summary>
     /// The default exception formatter. Calls the <see cref="Exception.ToString"/> method on the exception.
     /// </summary>
@@ -386,9 +422,20 @@ private void WritePropertyElement(XmlWriter writer, string name, LogEventPropert
     /// <param name="logEvent">The log event.</param>
     /// <param name="writer">The XML writer.</param>
     /// <remarks>https://github.com/apache/logging-log4net/blob/rel/2.0.8/src/Layout/XmlLayout.cs#L245-L257</remarks>
+    [SuppressMessage("Microsoft.Design", "CA1031", Justification = "Protecting from user-provided code which might throw anything")]
     private void WriteMessage(LogEvent logEvent, XmlWriter writer)
     {
-        var message = logEvent.RenderMessage(_options.FormatProvider);
+        string message;
+        try
+        {
+            message = _options.FormatMessage(logEvent, _options.FormatProvider);
+        }
+        catch (Exception exception)
+        {
+            Debugging.SelfLog.WriteLine($"[{GetType().FullName}] An exception was thrown while formatting a message. Using the default message formatter.\n{exception}");
+            message = DefaultMessageFormatter(logEvent, _options.FormatProvider);
+        }
+
         WriteContent(writer, "message", message);
     }
 

src/Log4NetTextFormatterOptions.cs

@@ -8,13 +8,14 @@ namespace Serilog.Formatting.Log4Net;
 /// </summary>
 internal sealed class Log4NetTextFormatterOptions
 {
-    internal Log4NetTextFormatterOptions(IFormatProvider? formatProvider, CDataMode cDataMode, XmlQualifiedName? xmlNamespace, XmlWriterSettings xmlWriterSettings, PropertyFilter filterProperty, ExceptionFormatter formatException)
+    internal Log4NetTextFormatterOptions(IFormatProvider? formatProvider, CDataMode cDataMode, XmlQualifiedName? xmlNamespace, XmlWriterSettings xmlWriterSettings, PropertyFilter filterProperty, MessageFormatter formatMessage, ExceptionFormatter formatException)
     {
         FormatProvider = formatProvider;
         CDataMode = cDataMode;
         XmlNamespace = xmlNamespace;
         XmlWriterSettings = xmlWriterSettings;
         FilterProperty = filterProperty;
+        FormatMessage = formatMessage;
         FormatException = formatException;
     }
 
@@ -33,6 +34,9 @@ internal Log4NetTextFormatterOptions(IFormatProvider? formatProvider, CDataMode
     /// <summary>See <see cref="Log4NetTextFormatterOptionsBuilder.UsePropertyFilter"/></summary>
     internal PropertyFilter FilterProperty { get; }
 
+    /// <summary>See <see cref="Log4NetTextFormatterOptionsBuilder.UseMessageFormatter"/></summary>
+    internal MessageFormatter FormatMessage { get; }
+
     /// <summary>See <see cref="Log4NetTextFormatterOptionsBuilder.UseExceptionFormatter"/></summary>
     internal ExceptionFormatter FormatException { get; }
 }

src/Log4NetTextFormatterOptionsBuilder.cs

@@ -46,6 +46,9 @@ internal Log4NetTextFormatterOptionsBuilder()
     /// <summary>See <see cref="UsePropertyFilter"/></summary>
     private PropertyFilter _filterProperty = (_, _) => true;
 
+    /// <summary>See <see cref="UseMessageFormatter"/></summary>
+    private MessageFormatter _formatMessage = Log4NetTextFormatter.DefaultMessageFormatter;
+
     /// <summary>See <see cref="UseExceptionFormatter"/></summary>
     private ExceptionFormatter _formatException = Log4NetTextFormatter.DefaultExceptionFormatter;
 
@@ -136,6 +139,23 @@ public Log4NetTextFormatterOptionsBuilder UsePropertyFilter(PropertyFilter filte
         return this;
     }
 
+    /// <summary>
+    /// Sets the <see cref="MessageFormatter"/> controlling how all messages are formatted.
+    /// <para/>
+    /// The default message formatter has two formatting modes.
+    /// <list type="bullet">
+    ///   <item>If the log event comes from <c>Microsoft.Extensions.Logging</c> (detected by the presence of the <c>EventId</c> property) then the message is formatted by switching off quoting of strings.</item>
+    ///   <item>If the log event comes from Serilog, then the message is formatted by calling <see cref="LogEvent.RenderMessage(System.IO.TextWriter,System.IFormatProvider)"/>.</item>
+    /// </list>
+    /// </summary>
+    /// <remarks>If an exception is thrown while executing the formatter, the default formatter will be used.</remarks>
+    /// <returns>The builder in order to fluently chain all options.</returns>
+    public Log4NetTextFormatterOptionsBuilder UseMessageFormatter(MessageFormatter formatMessage)
+    {
+        _formatMessage = formatMessage ?? throw new ArgumentNullException(nameof(formatMessage), "The message formatter can not be null.");
+        return this;
+    }
+
     /// <summary>
     /// Sets the <see cref="ExceptionFormatter"/> controlling how all exceptions are formatted.
     /// <para/>
@@ -177,7 +197,7 @@ public void UseLog4JCompatibility()
     }
 
     internal Log4NetTextFormatterOptions Build()
-        => new(_formatProvider, _cDataMode, _xmlNamespace, CreateXmlWriterSettings(_lineEnding, _indentationSettings), _filterProperty, _formatException);
+        => new(_formatProvider, _cDataMode, _xmlNamespace, CreateXmlWriterSettings(_lineEnding, _indentationSettings), _filterProperty, _formatMessage, _formatException);
 
     private static XmlWriterSettings CreateXmlWriterSettings(LineEnding lineEnding, IndentationSettings? indentationSettings)
     {
@@ -203,6 +223,14 @@ private static XmlWriterSettings CreateXmlWriterSettings(LineEnding lineEnding,
 /// <returns><see langword="true"/> to include the Serilog property in the log4net properties or <see langword="false"/> to ignore the Serilog property.</returns>
 public delegate bool PropertyFilter(LogEvent logEvent, string propertyName);
 
+/// <summary>
+/// Represents the method that formats the message for a <see cref="LogEvent"/>.
+/// </summary>
+/// <param name="logEvent">The log event to format.</param>
+/// <param name="formatProvider">The <see cref="IFormatProvider"/> that supplies culture-specific formatting information, or <see langword="null"/>.</param>
+/// <returns>The formatted message.</returns>
+public delegate string MessageFormatter(LogEvent logEvent, IFormatProvider? formatProvider);
+
 /// <summary>
 /// Represents the method that formats an <see cref="Exception"/>.
 /// </summary>

tests/Log4NetTextFormatterTest.CustomMessageFormatter.verified.xml

@@ -0,0 +1,3 @@
+<log4net:event timestamp="2003-01-04T15:09:26.535+01:00" level="INFO" xmlns:log4net="http://logging.apache.org/log4net/schemas/log4net-events-1.2/">
+  <log4net:message><![CDATA[Custom message]]></log4net:message>
+</log4net:event>

tests/Log4NetTextFormatterTest.DefaultMessageFormatter_hasEventId=False.verified.xml

@@ -0,0 +1,6 @@
+<log4net:event timestamp="2003-01-04T15:09:26.535+01:00" level="INFO" xmlns:log4net="http://logging.apache.org/log4net/schemas/log4net-events-1.2/">
+  <log4net:properties>
+    <log4net:data name="Name" value="World" />
+  </log4net:properties>
+  <log4net:message><![CDATA[Hello "World"!]]></log4net:message>
+</log4net:event>

tests/Log4NetTextFormatterTest.DefaultMessageFormatter_hasEventId=True.verified.xml

@@ -0,0 +1,8 @@
+<log4net:event timestamp="2003-01-04T15:09:26.535+01:00" level="INFO" xmlns:log4net="http://logging.apache.org/log4net/schemas/log4net-events-1.2/">
+  <log4net:properties>
+    <log4net:data name="Name" value="World" />
+    <log4net:data name="EventId.Id" value="1" />
+    <log4net:data name="EventId.Name" value="EventIdName" />
+  </log4net:properties>
+  <log4net:message><![CDATA[Hello World!]]></log4net:message>
+</log4net:event>

tests/Log4NetTextFormatterTest.MessageFormatterReturningNull.verified.xml

@@ -0,0 +1,3 @@
+<log4net:event timestamp="2003-01-04T15:09:26.535+01:00" level="INFO" xmlns:log4net="http://logging.apache.org/log4net/schemas/log4net-events-1.2/">
+  <log4net:message><![CDATA[]]></log4net:message>
+</log4net:event>

tests/Log4NetTextFormatterTest.MessageFormatterThrowing.verified.xml

@@ -0,0 +1,3 @@
+<log4net:event timestamp="2003-01-04T15:09:26.535+01:00" level="INFO" xmlns:log4net="http://logging.apache.org/log4net/schemas/log4net-events-1.2/">
+  <log4net:message><![CDATA[Hello from Serilog]]></log4net:message>
+</log4net:event>

tests/Log4NetTextFormatterTest.cs

@@ -94,6 +94,18 @@ public void SettingPropertyFilterToNullThrowsArgumentNullException()
             .And.ParamName.Should().Be("filterProperty");
     }
 
+    [Fact]
+    public void SettingMessageFormatterToNullThrowsArgumentNullException()
+    {
+        // Act
+        Action action = () => _ = new Log4NetTextFormatter(c => c.UseMessageFormatter(null!));
+
+        // Assert
+        action.Should().ThrowExactly<ArgumentNullException>()
+            .WithMessage("The message formatter can not be null.*")
+            .And.ParamName.Should().Be("formatMessage");
+    }
+
     [Fact]
     public void SettingExceptionFormatterToNullThrowsArgumentNullException()
     {
@@ -438,6 +450,75 @@ public Task Exception()
         return Verify(output);
     }
 
+    [Theory]
+    [InlineData(true)]
+    [InlineData(false)]
+    public Task DefaultMessageFormatter(bool hasEventId)
+    {
+        // Arrange
+        using var output = new StringWriter();
+        List<LogEventProperty> properties = [ new("Name", new ScalarValue("World")) ];
+        if (hasEventId)
+        {
+            LogEventProperty[] eventIdProperties = [ new("Id", new ScalarValue(1)), new("Name", new ScalarValue("EventIdName")) ];
+            properties.Add(new LogEventProperty("EventId", new StructureValue(eventIdProperties)));
+        }
+        var logEvent = CreateLogEvent(messageTemplate: "Hello {Name}!", properties: properties.ToArray());
+        var formatter = new Log4NetTextFormatter();
+
+        // Act
+        formatter.Format(logEvent, output);
+
+        // Assert
+        return Verify(output).UseParameters(hasEventId);
+    }
+
+    [Fact]
+    public Task CustomMessageFormatter()
+    {
+        // Arrange
+        using var output = new StringWriter();
+        var logEvent = CreateLogEvent();
+        var formatter = new Log4NetTextFormatter(options => options.UseMessageFormatter((_, _) => "Custom message"));
+
+        // Act
+        formatter.Format(logEvent, output);
+
+        // Assert
+        return Verify(output);
+    }
+
+    [Fact]
+    public Task MessageFormatterReturningNull()
+    {
+        // Arrange
+        using var output = new StringWriter();
+        var logEvent = CreateLogEvent();
+        var formatter = new Log4NetTextFormatter(options => options.UseMessageFormatter((_, _) => null!));
+
+        // Act
+        formatter.Format(logEvent, output);
+
+        // Assert
+        return Verify(output);
+    }
+
+    [Fact]
+    public Task MessageFormatterThrowing()
+    {
+        // Arrange
+        using var output = new StringWriter();
+        var logEvent = CreateLogEvent();
+        var formatter = new Log4NetTextFormatter(options => options.UseMessageFormatter((_, _) => throw new InvalidOperationException("💥 Boom 💥")));
+
+        // Act
+        formatter.Format(logEvent, output);
+
+        // Assert
+        SelfLogValue.Should().Contain("[Serilog.Formatting.Log4Net.Log4NetTextFormatter] An exception was thrown while formatting a message.");
+        return Verify(output);
+    }
+
     [Fact]
     public Task ExceptionFormatter()
     {

tests/PublicApi.net6.0.verified.cs

@@ -42,9 +42,11 @@ public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseFormatPr
         public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseIndentationSettings(Serilog.Formatting.Log4Net.IndentationSettings indentationSettings) { }
         public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseLineEnding(Serilog.Formatting.Log4Net.LineEnding lineEnding) { }
         public void UseLog4JCompatibility() { }
+        public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseMessageFormatter(Serilog.Formatting.Log4Net.MessageFormatter formatMessage) { }
         public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseNoIndentation() { }
         public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UseNoXmlNamespace() { }
         public Serilog.Formatting.Log4Net.Log4NetTextFormatterOptionsBuilder UsePropertyFilter(Serilog.Formatting.Log4Net.PropertyFilter filterProperty) { }
     }
+    public delegate string MessageFormatter(Serilog.Events.LogEvent logEvent, System.IFormatProvider? formatProvider);
     public delegate bool PropertyFilter(Serilog.Events.LogEvent logEvent, string propertyName);
 }