From df096e5d21a4b2d228893403ae3aa486294ca9cc Mon Sep 17 00:00:00 2001 From: Gregorius Soedharmo Date: Wed, 30 Aug 2023 04:39:59 +0700 Subject: [PATCH 1/2] Fix logger property render bug --- .../LogMessageSpecs.cs | 4 +- .../SerilogFormattingSpecs.cs | 47 +++++++++++++++++-- src/Akka.Logger.Serilog.Tests/TestSink.cs | 15 ++++++ .../MessageTemplateCache.cs | 33 +++++++++---- .../SerilogLogMessageFormatter.cs | 4 ++ 5 files changed, 89 insertions(+), 14 deletions(-) diff --git a/src/Akka.Logger.Serilog.Tests/LogMessageSpecs.cs b/src/Akka.Logger.Serilog.Tests/LogMessageSpecs.cs index f041d5e..0947bf8 100644 --- a/src/Akka.Logger.Serilog.Tests/LogMessageSpecs.cs +++ b/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() diff --git a/src/Akka.Logger.Serilog.Tests/SerilogFormattingSpecs.cs b/src/Akka.Logger.Serilog.Tests/SerilogFormattingSpecs.cs index f13afcb..71c0b4d 100644 --- a/src/Akka.Logger.Serilog.Tests/SerilogFormattingSpecs.cs +++ b/src/Akka.Logger.Serilog.Tests/SerilogFormattingSpecs.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Generic; using Akka.Actor; using Akka.Configuration; using Akka.Event; @@ -6,22 +7,33 @@ 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); @@ -29,6 +41,35 @@ public SerilogFormattingSpecs(ITestOutputHelper helper) : base(Config, output: h _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 { 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(); + + akkaLogEvent.ToString().Should().Contain(expectedMessage); + } + [Theory] [InlineData(LogLevel.DebugLevel, "test case {0}", new object[]{ 1 })] [InlineData(LogLevel.DebugLevel, "test case {myNum}", new object[] { 1 })] diff --git a/src/Akka.Logger.Serilog.Tests/TestSink.cs b/src/Akka.Logger.Serilog.Tests/TestSink.cs index 037c6b2..e87e869 100644 --- a/src/Akka.Logger.Serilog.Tests/TestSink.cs +++ b/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 Writes { get; private set; } = new ConcurrentQueue(); + private readonly ITestOutputHelper _output; + private int _count; + + public TestSink(): this(null) + { } + + public TestSink(ITestOutputHelper output) + { + _output = output; + } + + /// /// Resets the contents of the queue /// @@ -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); } } diff --git a/src/Akka.Logger.Serilog/MessageTemplateCache.cs b/src/Akka.Logger.Serilog/MessageTemplateCache.cs index 23c020e..5add8a6 100644 --- a/src/Akka.Logger.Serilog/MessageTemplateCache.cs +++ b/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 { /// @@ -12,10 +13,12 @@ namespace Akka.Logger.Serilog internal class MessageTemplateCache { private readonly MessageTemplateParser _innerParser; - private readonly Dictionary _templates = new Dictionary(); - 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; diff --git a/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs b/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs index 888023a..cd3f0fa 100644 --- a/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs +++ b/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,9 @@ public SerilogLogMessageFormatter() /// public string Format(string format, params object[] args) { + 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().ToArray(); var properties = new Dictionary(); From b6bc717a89f14d08565aa47e3071b8867a3767a0 Mon Sep 17 00:00:00 2001 From: Gregorius Soedharmo Date: Thu, 31 Aug 2023 06:16:12 +0700 Subject: [PATCH 2/2] Add comment --- src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs b/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs index cd3f0fa..e1e28e6 100644 --- a/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs +++ b/src/Akka.Logger.Serilog/SerilogLogMessageFormatter.cs @@ -38,6 +38,9 @@ public SerilogLogMessageFormatter() /// 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));