Prevent loggers to throw FormatException and show a friendly message …

…instead. (#4998)

* Prevent loggers to throw and show a friendly message instead.

* Need to wait for TestOutputLogger to initialize

Co-authored-by: Aaron Stannard <aaron@petabridge.com>

src/contrib/testkits/Akka.TestKit.Xunit2/Internals/Loggers.cs

@@ -5,6 +5,7 @@
 // </copyright>
 //-----------------------------------------------------------------------
 
+using System;
 using Akka.Actor;
 using Akka.Event;
 using Xunit.Abstractions;
@@ -16,20 +17,44 @@ namespace Akka.TestKit.Xunit2.Internals
     /// </summary>
     public class TestOutputLogger : ReceiveActor
     {
+        private readonly ITestOutputHelper _output;
+
         /// <summary>
         /// Initializes a new instance of the <see cref="TestOutputLogger"/> class.
         /// </summary>
         /// <param name="output">The provider used to write test output.</param>
         public TestOutputLogger(ITestOutputHelper output)
         {
-            Receive<Debug>(e => output.WriteLine(e.ToString()));
-            Receive<Info>(e => output.WriteLine(e.ToString()));
-            Receive<Warning>(e => output.WriteLine(e.ToString()));
-            Receive<Error>(e => output.WriteLine(e.ToString()));
+            _output = output;
+
+            Receive<Debug>(HandleLogEvent);
+            Receive<Info>(HandleLogEvent);
+            Receive<Warning>(HandleLogEvent);
+            Receive<Error>(HandleLogEvent);
             Receive<InitializeLogger>(e =>
             {
                 e.LoggingBus.Subscribe(Self, typeof (LogEvent));
             });
         }
+
+        private void HandleLogEvent(LogEvent e)
+        {
+            try
+            {
+                _output.WriteLine(e.ToString());
+            }
+            catch (FormatException ex)
+            {
+                if (e.Message is LogMessage msg)
+                {
+                    var message =
+                        $"Received a malformed formatted message. Log level: [{e.LogLevel()}], Template: [{msg.Format}], args: [{string.Join(",", msg.Args)}]";
+                    if(e.Cause != null)
+                        throw new AggregateException(message, ex, e.Cause);
+                    throw new FormatException(message, ex);
+                }
+                throw;
+            }
+        }
     }
 }

src/core/Akka.TestKit/Internal/InternalTestActor.cs

@@ -5,6 +5,7 @@
 // </copyright>
 //-----------------------------------------------------------------------
 
+using System;
 using System.Collections.Concurrent;
 using Akka.Actor;
 using Akka.Event;
@@ -38,7 +39,19 @@ public InternalTestActor(ITestActorQueue<MessageEnvelope> queue)
         /// <returns>TBD</returns>
         protected override bool Receive(object message)
         {
-            global::System.Diagnostics.Debug.WriteLine("TestActor received " + message);
+            try
+            {
+                global::System.Diagnostics.Debug.WriteLine("TestActor received " + message);
+            }
+            catch (FormatException)
+            {
+                if (message is LogEvent evt && evt.Message is LogMessage msg)
+                    global::System.Diagnostics.Debug.WriteLine(
+                        $"TestActor received a malformed formatted message. Template:[{msg.Format}], args:[{string.Join(",", msg.Args)}]");
+                else
+                    throw;
+            }
+
             var setIgnore = message as TestKit.TestActor.SetIgnore;
             if(setIgnore != null)
             {

src/core/Akka.Tests/Loggers/LoggerSpec.cs

@@ -0,0 +1,129 @@
+using System;
+using System.Collections.Generic;
+using System.Threading;
+using Akka.Actor;
+using Akka.Configuration;
+using Akka.Event;
+using Akka.TestKit;
+using Xunit;
+using Xunit.Abstractions;
+using FluentAssertions;
+
+namespace Akka.Tests.Loggers
+{
+    public class LoggerSpec : AkkaSpec
+    {
+        private static readonly Config Config = ConfigurationFactory.ParseString(@"
+akka.loglevel = DEBUG
+akka.stdout-loglevel = DEBUG");
+
+        public static readonly (string t, string[] p) Case =  
+            ("This is {0} a {1} janky formatting. {4}", new []{"also", "very", "not cool"});
+
+        public LoggerSpec(ITestOutputHelper output) : base(Config, output)
+        { }
+
+        [Fact]
+        public void TestOutputLogger_WithBadFormattingMustNotThrow()
+        {
+            // Need to wait until TestOutputLogger initializes
+            Thread.Sleep(200);
+            Sys.EventStream.Subscribe(TestActor, typeof(LogEvent));
+
+            Sys.Log.Error(new FakeException("BOOM"), Case.t, Case.p);
+            ExpectMsg<Error>().Cause.Should().BeOfType<FakeException>();
+            ExpectMsg<Error>().Cause.Should().BeOfType<AggregateException>();
+
+            Sys.Log.Warning(Case.t, Case.p);
+            ExpectMsg<Warning>();
+            ExpectMsg<Error>().Cause.Should().BeOfType<FormatException>();
+
+            Sys.Log.Info(Case.t, Case.p);
+            ExpectMsg<Info>();
+            ExpectMsg<Error>().Cause.Should().BeOfType<FormatException>();
+
+            Sys.Log.Debug(Case.t, Case.p);
+            ExpectMsg<Debug>();
+            ExpectMsg<Error>().Cause.Should().BeOfType<FormatException>();
+        }
+
+        [Fact]
+        public void DefaultLogger_WithBadFormattingMustNotThrow()
+        {
+            var config = ConfigurationFactory.ParseString("akka.loggers = [\"Akka.Event.DefaultLogger\"]");
+            var sys2 = ActorSystem.Create("DefaultLoggerTest", config.WithFallback(Sys.Settings.Config));
+            var probe = CreateTestProbe(sys2);
+
+            sys2.EventStream.Subscribe(probe, typeof(LogEvent));
+
+            sys2.Log.Error(new FakeException("BOOM"), Case.t, Case.p);
+            probe.ExpectMsg<Error>().Cause.Should().BeOfType<FakeException>();
+
+            sys2.Log.Warning(Case.t, Case.p);
+            probe.ExpectMsg<Warning>();
+
+            sys2.Log.Info(Case.t, Case.p);
+            probe.ExpectMsg<Info>();
+
+            sys2.Log.Debug(Case.t, Case.p);
+            probe.ExpectMsg<Debug>();
+
+            sys2.Terminate().Wait();
+        }
+
+        [Fact]
+        public void StandardOutLogger_WithBadFormattingMustNotThrow()
+        {
+            var config = ConfigurationFactory.ParseString("akka.loggers = [\"Akka.Event.StandardOutLogger\"]");
+            var sys2 = ActorSystem.Create("StandardOutLoggerTest", config.WithFallback(Sys.Settings.Config));
+            var probe = CreateTestProbe(sys2);
+
+            sys2.EventStream.Subscribe(probe, typeof(LogEvent));
+
+            sys2.Log.Error(new FakeException("BOOM"), Case.t, Case.p);
+            probe.ExpectMsg<Error>().Cause.Should().BeOfType<FakeException>();
+
+            sys2.Log.Warning(Case.t, Case.p);
+            probe.ExpectMsg<Warning>();
+
+            sys2.Log.Info(Case.t, Case.p);
+            probe.ExpectMsg<Info>();
+
+            sys2.Log.Debug(Case.t, Case.p);
+            probe.ExpectMsg<Debug>();
+
+            sys2.Terminate().Wait();
+        }
+
+        [Theory]
+        [MemberData(nameof(LogEventFactory))]
+        public void StandardOutLogger_PrintLogEvent_WithBadLogFormattingMustNotThrow(LogEvent @event)
+        {
+            var obj = new object();
+            obj.Invoking(o => StandardOutLogger.PrintLogEvent(@event)).Should().NotThrow();
+        }
+
+        public static IEnumerable<object[]> LogEventFactory()
+        {
+            var ex = new FakeException("BOOM");
+            var logSource = LogSource.Create(nameof(LoggerSpec));
+            var ls = logSource.Source;
+            var lc = logSource.Type;
+            var formatter = new DefaultLogMessageFormatter();
+
+            yield return new object[] { new Error(ex, ls, lc, new LogMessage(formatter, Case.t, Case.p)) }; 
+
+            yield return new object[] {new Warning(ex, ls, lc, new LogMessage(formatter, Case.t, Case.p))};
+
+            yield return new object[] {new Info(ex, ls, lc, new LogMessage(formatter, Case.t, Case.p))};
+
+            yield return new object[] {new Debug(ex, ls, lc, new LogMessage(formatter, Case.t, Case.p))};
+        }
+
+        private class FakeException : Exception
+        {
+            public FakeException(string message) : base(message)
+            { }
+        }
+    }
+}

src/core/Akka/Event/StandardOutLogger.cs

@@ -135,24 +135,26 @@ public static void PrintLogEvent(LogEvent logEvent)
 
                 StandardOutWriter.WriteLine(logEvent.ToString(), color);
             }
-            catch (FormatException)
+            catch (FormatException ex)
             {
                 /*
-                 * If we've reached this point, the `logEvent` itself is informatted incorrectly. 
+                 * If we've reached this point, the `logEvent` itself is formatted incorrectly. 
                  * Therefore we have to treat the data inside the `logEvent` as suspicious and avoid throwing
                  * a second FormatException.
                  */
                 var sb = new StringBuilder();
-                sb.AppendFormat("[ERROR][{0}][Thread {1}][StandardOutLogger] ", logEvent.Timestamp, 0);
-                sb.AppendFormat("Encoutered System.FormatException while recording log: [" +
-                                logEvent.LogLevel().PrettyNameFor() + "]")
-                    .AppendFormat("[" + logEvent.LogSource + "][" + logEvent.Message + "]");
+                sb.AppendFormat("[ERROR][{0}]", logEvent.Timestamp)
+                    .AppendFormat("[Thread {0}]", logEvent.Thread.ManagedThreadId.ToString().PadLeft(4, '0'))
+                    .AppendFormat("[{0}] ", nameof(StandardOutLogger))
+                    .AppendFormat("Encountered System.FormatException while recording log: [{0}]", logEvent.LogLevel().PrettyNameFor())
+                    .AppendFormat("[{0}]. ", logEvent.LogSource)
+                    .Append(ex.Message);
 
                 string msg;
                 switch (logEvent.Message)
                 {
                     case LogMessage formatted: // a parameterized log
-                        msg = "str=[" + formatted.Format + "],args=["+ string.Join(",", formatted.Args) +"]";
+                        msg = " str=[" + formatted.Format + "], args=["+ string.Join(",", formatted.Args) +"]";
                         break;
                     case string unformatted: // pre-formatted or non-parameterized log
                         msg = unformatted;
@@ -163,7 +165,7 @@ public static void PrintLogEvent(LogEvent logEvent)
                 }
 
                 sb.Append(msg)
-                    .Append("Please take a look at the logging call where this occurred and fix your format string.");
+                    .Append(" Please take a look at the logging call where this occurred and fix your format string.");
 
                 StandardOutWriter.WriteLine(sb.ToString(), ErrorColor);
             }