Make sure stdout-loglevel setting is honored through the whole actor …

…system lifecycle (#5251)

* Make sure stdout-loglevel setting is honored through the whole actor system lifecycle

* Add settings spec for the new StandardOutLogger setting

* Update API Approver list

* Test logger can still output logs

* Suppress LoggerInitialized from deadletter

* Update API Approver list

* Remove LogLevel.OffLevel for backward compatibility

* Update API Approver list

* Re-add OffLogLevel private const

* Fix XML doc and previously hardwired StandardOutLogger type checking.

* Add documentation to the new MinimalLogger implementation

* Change equality to inheritance check

* Add MinimalLogger spec

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

docs/articles/utilities/logging.md

@@ -25,6 +25,28 @@ Akka.NET comes with two built in loggers.
 * __StandardOutLogger__
 * __BusLogging__
 
+### StandardOutLogger
+`StandardOutLogger` is considered as a minimal logger and implements the `MinimalLogger` abstract
+class. Its job is simply to output all `LogEvent`s emitted by the `EventBus` onto the console. 
+Since it is not an actual actor, ie. it doesn't need the `ActorSystem` to operate, it is also 
+used to log other loggers activity at the very start and very end of the `ActorSystem` life cycle. 
+You can change the minimal logger start and end life cycle behaviour by changing the 
+`akka.stdout-loglevel` HOCON settings to `OFF` if you do not need these feature in your application.
+
+### Advanced MinimalLogger Setup
+You can also replace `StandardOutLogger` by making your own logger class with an empty constructor 
+that inherits/implements the `MinimalLogger` abstract class and passing the fully qualified class 
+name into the `akka.stdout-logger-class` HOCON settings. 
+
+> [!WARNING]
+> Be aware that `MinimalLogger` implementations are __NOT__ real actors and will __NOT__ have any 
+> access to the `ActorSystem` and all of its extensions. All logging done inside a `MinimalLogger` 
+> have to be done in as simple as possible manner since it is used to log how other loggers are 
+> behaving at the very start and very end of the `ActorSystem` life cycle.
+> 
+> Note that `MinimalLogger` are __NOT__ interchangeable with other Akka.NET loggers and there can 
+> only be one `MinimalLogger` registered with the `ActorSystem` in the HOCON settings.
+
 ## Contrib Loggers
 These loggers are also available as separate nuget packages
 

src/contrib/testkits/Akka.TestKit.Xunit/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.Xunit.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>(Write);
+ Receive<Info>(Write);
+ Receive<Warning>(Write);
+ Receive<Error>(Write);
  Receive<InitializeLogger>(e =>
  {
  e.LoggingBus.Subscribe(Self, typeof (LogEvent));
  });
  }
+
+ private void Write(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.API.Tests/CoreAPISpec.ApproveCore.approved.txt

@@ -1696,6 +1696,7 @@ namespace Akka.Actor
  public bool SerializeAllMessages { get; }
  public Akka.Actor.Setup.ActorSystemSetup Setup { get; }
  public string StdoutLogLevel { get; }
+ public Akka.Event.MinimalLogger StdoutLogger { get; }
  public string SupervisorStrategyClass { get; }
  public Akka.Actor.ActorSystem System { get; }
  public System.TimeSpan UnstartedPushTimeout { get; }
@@ -3089,7 +3090,7 @@ namespace Akka.Event
  public static string FromType(System.Type t, Akka.Actor.ActorSystem system) { }
  public static System.Type SourceType(object o) { }
  }
- public class LoggerInitialized : Akka.Actor.INoSerializationVerificationNeeded
+ public class LoggerInitialized : Akka.Actor.INoSerializationVerificationNeeded, Akka.Event.IDeadLetterSuppression
  {
  public LoggerInitialized() { }
  }
@@ -3099,7 +3100,6 @@ namespace Akka.Event
  }
  public class static Logging
  {
- public static readonly Akka.Event.StandardOutLogger StandardOutLogger;
  public static System.Type ClassFor(this Akka.Event.LogLevel logLevel) { }
  public static Akka.Event.ILoggingAdapter GetLogger(this Akka.Actor.IActorContext context, Akka.Event.ILogMessageFormatter logMessageFormatter = null) { }
  public static Akka.Event.ILoggingAdapter GetLogger(Akka.Actor.ActorSystem system, object logSourceObj, Akka.Event.ILogMessageFormatter logMessageFormatter = null) { }
@@ -3152,6 +3152,14 @@ namespace Akka.Event
  public void SetLogLevel(Akka.Event.LogLevel logLevel) { }
  public void StartStdoutLogger(Akka.Actor.Settings config) { }
  }
+ public abstract class MinimalLogger : Akka.Actor.MinimalActorRef
+ {
+ protected MinimalLogger() { }
+ public virtual Akka.Actor.ActorPath Path { get; }
+ public virtual Akka.Actor.IActorRefProvider Provider { get; }
+ protected abstract void Log(object message);
+ protected virtual void TellInternal(object message, Akka.Actor.IActorRef sender) { }
+ }
  public sealed class NoLogger : Akka.Event.ILoggingAdapter
  {
  public static readonly Akka.Event.ILoggingAdapter Instance;
@@ -3172,18 +3180,15 @@ namespace Akka.Event
  public void Warning(string format, params object[] args) { }
  public void Warning(System.Exception cause, string format, params object[] args) { }
  }
- public class StandardOutLogger : Akka.Actor.MinimalActorRef
+ public class StandardOutLogger : Akka.Event.MinimalLogger
  {
  public StandardOutLogger() { }
  public static System.ConsoleColor DebugColor { get; set; }
  public static System.ConsoleColor ErrorColor { get; set; }
  public static System.ConsoleColor InfoColor { get; set; }
- public override Akka.Actor.ActorPath Path { get; }
- public override Akka.Actor.IActorRefProvider Provider { get; }
  public static bool UseColors { get; set; }
  public static System.ConsoleColor WarningColor { get; set; }
- public static void PrintLogEvent(Akka.Event.LogEvent logEvent) { }
- protected override void TellInternal(object message, Akka.Actor.IActorRef sender) { }
+ protected override void Log(object message) { }
  }
  public class Subscription<TSubscriber, TClassifier>
  {

src/core/Akka.TestKit/EventFilter/TestEventListener.cs

@@ -30,57 +30,65 @@ public class TestEventListener : DefaultLogger
  /// <returns>TBD</returns>
  protected override bool Receive(object message)
  {
- if(message is InitializeLogger)
+ switch (message)
  {
- var initLogger = (InitializeLogger)message;
- var bus = initLogger.LoggingBus;
- var self = Context.Self;
- bus.Subscribe(self, typeof(Mute));
- bus.Subscribe(self, typeof(Unmute));
- bus.Subscribe(self, typeof(DeadLetter));
- bus.Subscribe(self, typeof(UnhandledMessage));
- Sender.Tell(new LoggerInitialized());
- }
- else if(message is Mute)
- {
- var mute = (Mute)message;
- foreach(var filter in mute.Filters)
+ case InitializeLogger initLogger:
  {
- AddFilter(filter);
+ base.Receive(message);
+ var bus = initLogger.LoggingBus;
+ var self = Context.Self;
+ bus.Subscribe(self, typeof(Mute));
+ bus.Subscribe(self, typeof(Unmute));
+ bus.Subscribe(self, typeof(DeadLetter));
+ bus.Subscribe(self, typeof(UnhandledMessage));
+ Sender.Tell(new LoggerInitialized());
+ break;
  }
- }
- else if(message is Unmute)
- {
- var unmute = (Unmute)message;
- foreach(var filter in unmute.Filters)
+ case Mute mute:
  {
- RemoveFilter(filter);
+ foreach(var filter in mute.Filters)
+ {
+ AddFilter(filter);
+ }
+
+ break;
  }
- }
- else if(message is LogEvent)
- {
- var logEvent = (LogEvent)message;
- if(!ShouldFilter(logEvent))
+ case Unmute unmute:
  {
- Print(logEvent);
+ foreach(var filter in unmute.Filters)
+ {
+ RemoveFilter(filter);
+ }
+
+ break;
  }
+ case LogEvent logEvent:
+ {
+ if(!ShouldFilter(logEvent))
+ {
+ Print(logEvent);
+ }
+
+ break;
+ }
+ case DeadLetter letter:
+ HandleDeadLetter(letter);
+ break;
+
+ case UnhandledMessage un:
+ {
+ var rcp = un.Recipient;
+ var warning = new Warning(rcp.Path.ToString(), rcp.GetType(), "Unhandled message from " + un.Sender + ": " + un.Message);
+ if(!ShouldFilter(warning))
+ Print(warning);
+ break;
+ }
+
+ default:
+ Print(new Debug(Context.System.Name,GetType(),message));
+ break;
  }
- else if(message is DeadLetter)
- {
- HandleDeadLetter((DeadLetter)message);
- }
- else if(message is UnhandledMessage)
- {
- var un = (UnhandledMessage) message;
- var rcp = un.Recipient;
- var warning = new Warning(rcp.Path.ToString(), rcp.GetType(), "Unhandled message from " + un.Sender + ": " + un.Message);
- if(!ShouldFilter(warning))
- Print(warning);
- }
- else
- {
- Print(new Debug(Context.System.Name,GetType(),message));
- }
+
  return true;
  }
 

src/core/Akka.Tests/Configuration/ConfigurationSpec.cs

@@ -42,6 +42,8 @@ public void The_default_configuration_file_contain_all_configuration_properties(
  settings.LoggerStartTimeout.Seconds.ShouldBe(5);
  settings.LogLevel.ShouldBe("INFO");
  settings.StdoutLogLevel.ShouldBe("WARNING");
+ settings.StdoutLogger.Should().NotBeNull();
+ settings.StdoutLogger.Should().BeOfType<StandardOutLogger>();
  settings.LogConfigOnStart.ShouldBeFalse();
  settings.LogDeadLetters.ShouldBe(10);
  settings.LogDeadLettersDuringShutdown.ShouldBeFalse();

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

@@ -2,7 +2,10 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading;
+using System.Threading.Tasks;
 using Akka.Actor;
+using Akka.Actor.Internal;
+using Akka.Actor.Setup;
 using Akka.Configuration;
 using Akka.Event;
 using Akka.TestKit;
@@ -142,5 +145,26 @@ private class FakeException : Exception
  public FakeException(string message) : base(message)
  { }
  }
+
+ [Fact]
+ public async Task ShouldBeAbleToReplaceStandardOutLoggerWithCustomMinimalLogger()
+ {
+ var config = ConfigurationFactory
+ .ParseString("akka.stdout-logger-class = \"Akka.Tests.Loggers.LoggerSpec+CustomLogger, Akka.Tests\"")
+ .WithFallback(ConfigurationFactory.Default()); 
+
+ var system = ActorSystem.Create("MinimalLoggerTest", config);
+ system.Settings.StdoutLogger.Should().BeOfType<CustomLogger>();
+ await system.Terminate();
+ }
+
+ public class CustomLogger : MinimalLogger
+ {
+ protected override void Log(object message)
+ {
+ Console.WriteLine(message);
+ }
+ }
+
  }
 }

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

@@ -0,0 +1,84 @@
+// //-----------------------------------------------------------------------
+// // <copyright file="ShutdownLoggerSpec.cs" company="Akka.NET Project">
+// // Copyright (C) 2009-2021 Lightbend Inc. <http://www.lightbend.com>
+// // Copyright (C) 2013-2021 .NET Foundation <https://github.com/akkadotnet/akka.net>
+// // </copyright>
+// //-----------------------------------------------------------------------
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Reflection;
+using System.Threading.Tasks;
+using Akka.Actor;
+using Akka.Configuration;
+using Akka.Event;
+using Akka.TestKit;
+using FluentAssertions;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace Akka.Tests.Loggers
+{
+ public class ShutdownLoggerSpec: AkkaSpec
+ {
+ private static readonly Config Config = ConfigurationFactory.ParseString(@"
+akka.loglevel = OFF
+akka.stdout-loglevel = OFF
+akka.stdout-logger-class = ""Akka.Tests.Loggers.ThrowingLogger, Akka.Tests""");
+
+ public ShutdownLoggerSpec(ITestOutputHelper output) : base(Config, output)
+ {
+ }
+
+ [Fact(DisplayName = "StandardOutLogger should not be called on shutdown when stdout-loglevel is set to OFF")]
+ public async Task StandardOutLoggerShouldNotBeCalled()
+ {
+ Sys.Settings.StdoutLogger.Should().BeOfType<ThrowingLogger>();
+
+ var probeRef = Sys.ActorOf(Props.Create(() => new LogProbe()));
+ probeRef.Tell(new InitializeLogger(Sys.EventStream));
+ var probe = await probeRef.Ask<LogProbe>("hey");
+
+ await Sys.Terminate();
+
+ await Task.Delay(RemainingOrDefault);
+ if (probe.Events.Any(o => o is Error err && err.Cause is ShutdownLogException))
+ throw new Exception("Test failed, log should not be called after shutdown.");
+ }
+ }
+
+ internal class LogProbe : ReceiveActor
+ {
+ public List<LogEvent> Events { get; } = new List<LogEvent>();
+
+ public LogProbe()
+ {
+ Receive<string>(msg => Sender.Tell(this));
+ Receive<LogEvent>(Events.Add);
+ Receive<InitializeLogger>(e =>
+ {
+ e.LoggingBus.Subscribe(Self, typeof (LogEvent));
+ Sender.Tell(new LoggerInitialized());
+ });
+
+ }
+ }
+
+ internal class ShutdownLogException : Exception
+ {
+ public ShutdownLogException()
+ { }
+
+ public ShutdownLogException(string msg) : base(msg)
+ { }
+ }
+
+ internal class ThrowingLogger : MinimalLogger
+ {
+ protected override void Log(object message)
+ {
+ throw new ShutdownLogException("This logger should never be called.");
+ }
+ }
+}