Fix logger property render bug (#255)

* Fix logger property render bug

* Add comment

Author: Arkatufus

src/Akka.Logger.Serilog.Tests/LogMessageSpecs.cs

@@ -17,10 +17,12 @@ public class LogMessageSpecs : TestKit.Xunit2.TestKit
                                                  akka.loggers=[""Akka.Logger.Serilog.SerilogLogger, Akka.Logger.Serilog""]";
 
         private readonly ILoggingAdapter _loggingAdapter;
-        private readonly TestSink _sink = new TestSink();
+        private readonly TestSink _sink;
 
         public LogMessageSpecs(ITestOutputHelper helper) : base(Config, output: helper)
         {
+            _sink = new TestSink(helper);
+            
             global::Serilog.Log.Logger = new LoggerConfiguration()
                 .WriteTo.Sink(_sink)
                 .MinimumLevel.Debug()

src/Akka.Logger.Serilog.Tests/SerilogFormattingSpecs.cs

@@ -1,34 +1,75 @@
 using System;
+using System.Collections.Generic;
 using Akka.Actor;
 using Akka.Configuration;
 using Akka.Event;
 using FluentAssertions;
 using Serilog;
 using Xunit;
 using Xunit.Abstractions;
+using SerilogLog = Serilog.Log;
 
 namespace Akka.Logger.Serilog.Tests
 {
     public class SerilogFormattingSpecs : TestKit.Xunit2.TestKit
     {
-        public static readonly Config Config = @"akka.loglevel = DEBUG";
-        private ILogger _serilogLogger;
+        public static readonly Config Config = 
+@"
+akka.loglevel = DEBUG
+# akka.loggers=[""Akka.Logger.Serilog.SerilogLogger, Akka.Logger.Serilog""]
+";
+        private readonly ILogger _serilogLogger;
+        private readonly TestSink _sink;
 
-        private ILoggingAdapter _loggingAdapter;
+        private readonly ILoggingAdapter _loggingAdapter;
 
         public SerilogFormattingSpecs(ITestOutputHelper helper) : base(Config, output: helper)
         {
+            _sink = new TestSink(helper);
+            
             _serilogLogger = new LoggerConfiguration()
                 .WriteTo.ColoredConsole()
+                .WriteTo.Sink(_sink)
                 .MinimumLevel.Information()
                 .CreateLogger();
+            
+            SerilogLog.Logger = _serilogLogger;
 
             var logSource = Sys.Name;
             var logClass = typeof(ActorSystem);
 
             _loggingAdapter = new SerilogLoggingAdapter(Sys.EventStream, logSource, logClass);
         }
 
+        [Fact]
+        public void LogOutputRegressionTest()
+        {
+            const string message = "{IntArray} {DoubleArray} {StringArray} {DoubleList}";
+            const string expectedMessage = "[0, 1, 2] [0.1, 0.2, 0.3] [\"One\", \"Two\"] [1, 2, 3]";
+            var args = new object[]
+            {
+                new int[] { 0, 1, 2 },
+                new double[] { 0.1, 0.2, 0.3 },
+                new string[] { "One", "Two" },
+                new List<double> { 1, 2, 3 }
+            };
+            
+            _sink.Clear();
+            AwaitCondition(() => _sink.Writes.Count == 0);
+            
+            _serilogLogger.Information(message, args);
+            AwaitCondition(() => _sink.Writes.Count == 1);
+
+            _sink.Writes.TryDequeue(out var logEvent).Should().BeTrue();
+            logEvent.RenderMessage().Should().Be(expectedMessage);
+            
+            Sys.EventStream.Subscribe(TestActor, typeof(LogEvent));
+            _loggingAdapter.Log(LogLevel.InfoLevel, message, args);
+            var akkaLogEvent = ExpectMsg<LogEvent>();
+
+            akkaLogEvent.ToString().Should().Contain(expectedMessage);
+        }
+        
         [Theory]
         [InlineData(LogLevel.DebugLevel, "test case {0}", new object[]{ 1 })]
         [InlineData(LogLevel.DebugLevel, "test case {myNum}", new object[] { 1 })]

src/Akka.Logger.Serilog.Tests/TestSink.cs

@@ -2,6 +2,7 @@
 using Serilog.Core;
 using Serilog.Events;
 using Xunit;
+using Xunit.Abstractions;
 
 [assembly: CollectionBehavior(DisableTestParallelization = true)]
 
@@ -15,6 +16,18 @@ public sealed class TestSink : ILogEventSink
     {
         public ConcurrentQueue<global::Serilog.Events.LogEvent> Writes { get; private set; } = new ConcurrentQueue<global::Serilog.Events.LogEvent>();
 
+        private readonly ITestOutputHelper _output;
+        private int _count;
+
+        public TestSink(): this(null)
+        { }
+        
+        public TestSink(ITestOutputHelper output)
+        {
+            _output = output;
+        }
+
+
         /// <summary>
         /// Resets the contents of the queue
         /// </summary>
@@ -25,6 +38,8 @@ public void Clear()
 
         public void Emit(global::Serilog.Events.LogEvent logEvent)
         {
+            _count++;
+            _output?.WriteLine($"[{nameof(TestSink)}][{_count}]: {logEvent.RenderMessage()}");
             Writes.Enqueue(logEvent);
         }
     }

src/Akka.Logger.Serilog/MessageTemplateCache.cs

@@ -1,8 +1,9 @@
 using System;
-using System.Collections.Generic;
+using System.Collections;
 using Serilog.Events;
 using Serilog.Parsing;
 
+#nullable enable
 namespace Akka.Logger.Serilog
 {
     /// <summary>
@@ -12,10 +13,12 @@ namespace Akka.Logger.Serilog
     internal class MessageTemplateCache
     {
         private readonly MessageTemplateParser _innerParser;
-        private readonly Dictionary<string, MessageTemplate> _templates = new Dictionary<string, MessageTemplate>();
-        private readonly object _templatesLock = new object();
+        private readonly object _templatesLock = new();
 
-        const int MaxCacheItems = 1000;
+        private readonly Hashtable _templates = new();
+
+        private const int MaxCacheItems = 1000;
+        private const int MaxCachedTemplateLength = 1024;
 
         public MessageTemplateCache(MessageTemplateParser innerParser)
         {
@@ -26,10 +29,14 @@ public MessageTemplate Parse(string messageTemplate)
         {
             if (messageTemplate == null) throw new ArgumentNullException(nameof(messageTemplate));
 
-            MessageTemplate result;
-            lock (_templatesLock)
-                if (_templates.TryGetValue(messageTemplate, out result))
-                    return result;
+            if (messageTemplate.Length > MaxCachedTemplateLength)
+                return _innerParser.Parse(messageTemplate);
+
+            // ReSharper disable once InconsistentlySynchronizedField
+            // ignored warning because this is by design
+            var result = (MessageTemplate?)_templates[messageTemplate];
+            if (result != null)
+                return result;
 
             result = _innerParser.Parse(messageTemplate);
 
@@ -39,8 +46,14 @@ public MessageTemplate Parse(string messageTemplate)
                 // conditions when the library is used incorrectly. Correct use (templates, rather than
                 // direct message strings) should barely, if ever, overflow this cache.
 
-                if (_templates.Count <= MaxCacheItems)
-                    _templates[messageTemplate] = result;
+                // Changing workloads through the lifecycle of an app instance mean we can gain some ground by
+                // potentially dropping templates generated only in startup, or only during specific infrequent
+                // activities.
+
+                if (_templates.Count == MaxCacheItems)
+                    _templates.Clear();
+
+                _templates[messageTemplate] = result;
             }
 
             return result;

src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs

@@ -1,6 +1,7 @@
 using System.Collections.Generic;
 using System.Linq;
 using Akka.Event;
+using Serilog;
 using Serilog.Events;
 using Serilog.Parsing;
 
@@ -37,6 +38,12 @@ public SerilogLogMessageFormatter()
         /// </returns>
         public string Format(string format, params object[] args)
         {
+            // We're using serilog built-in function to bind all the object arguments to their proper
+            // value types. If this fails, we fell back to the old implementation where we map everything
+            // to ScalarValue.
+            if (Log.Logger.BindMessageTemplate(format, args, out var boundTemplate, out var boundProps))
+                return boundTemplate.Render(boundProps.ToDictionary(p => p.Name, p => p.Value));
+            
             var template = _templateCache.Parse(format);
             var propertyTokens = template.Tokens.OfType<PropertyToken>().ToArray();
             var properties = new Dictionary<string, LogEventPropertyValue>();