Skip to content

Commit

Permalink
Fix faulty AddLogger in LoggingBus (akkadotnet#6028)
Browse files Browse the repository at this point in the history 
* Fix faulty AddLogger in LoggingBus

* Ignore logger async start setting, not relevant anymore

* Simplify unit test

* Send Stop instead of PoisonPill

* Make loggers load asynchronously by default

* Change logging back to exceptions

* Remove _startupState, use closure instead

Co-authored-by: Aaron Stannard <aaron@petabridge.com>
  • Loading branch information
@Arkatufus @Aaronontheweb
Arkatufus and Aaronontheweb committed Jul 27, 2022
1 parent fc2ed1a commit c8b46b4
Show file tree
Hide file tree
Showing 2 changed files with 285 additions and 74 deletions.
224 changes: 203 additions & 21 deletions src/core/Akka.Tests/Loggers/LoggerStartupSpec.cs
View file
Expand Up @@ -9,47 +9,229 @@
using System.Threading.Tasks;
using Akka.Actor;
using Akka.Configuration;
using Akka.Dispatch;
using Akka.Event;
using Akka.TestKit;
using FluentAssertions;
using Xunit;
using Xunit.Abstractions;

namespace Akka.Tests.Loggers
{
public class LoggerStartupSpec : TestKit.Xunit2.TestKit
{
private const int LoggerResponseDelayMs = 10_000;
private const int LoggerResponseDelayMs = 1_000;

public LoggerStartupSpec(ITestOutputHelper helper) : base(nameof(LoggerStartupSpec), helper)
{
XUnitOutLogger.Helper = helper;
}

[Fact]
public async Task Logger_async_start_configuration_helps_to_ignore_hanging_loggers()
[Theory(DisplayName = "ActorSystem should start with loggers timing out")]
[InlineData(false)]
[InlineData(true)]
public async Task ActorSystem_should_start_with_loggers_timing_out(bool useAsync)
{
var loggerAsyncStartDisabledConfig = ConfigurationFactory.ParseString($"akka.logger-async-start = false");
var loggerAsyncStartEnabledConfig = ConfigurationFactory.ParseString($"akka.logger-async-start = true");

var slowLoggerConfig = ConfigurationFactory.ParseString($"akka.loggers = [\"{typeof(SlowLoggerActor).FullName}, {typeof(SlowLoggerActor).Assembly.GetName().Name}\"]");
var slowLoggerConfig = ConfigurationFactory.ParseString($@"
akka.loglevel = DEBUG
akka.stdout-logger-class = ""{typeof(XUnitOutLogger).FullName}, {typeof(XUnitOutLogger).Assembly.GetName().Name}""
akka.loggers = [
""Akka.Event.DefaultLogger"",
""{typeof(SlowLoggerActor).FullName}, {typeof(SlowLoggerActor).Assembly.GetName().Name}""
]
akka.logger-startup-timeout = 100ms").WithFallback(DefaultConfig);

// Without logger async start, ActorSystem creation will hang
this.Invoking(_ => ActorSystem.Create("handing", slowLoggerConfig.WithFallback(loggerAsyncStartDisabledConfig))).Should()
.Throw<Exception>("System can not start - logger timed out");

// With logger async start, ActorSystem is created without issues
// Created without timeouts
var system = ActorSystem.Create("working", slowLoggerConfig.WithFallback(loggerAsyncStartEnabledConfig));
var config = ConfigurationFactory.ParseString($"akka.logger-async-start = {(useAsync ? "true" : "false")}")
.WithFallback(slowLoggerConfig);

ActorSystem sys = null;
try
{
this.Invoking(_ => sys = ActorSystem.Create("test", config)).Should()
.NotThrow("System should not fail to start when a logger timed out");
var probe = CreateTestProbe(sys);
SlowLoggerActor.Probe = probe;
var logProbe = CreateTestProbe(sys);
sys.EventStream.Subscribe(logProbe, typeof(LogEvent));

// Logger actor should eventually initialize
await AwaitAssertAsync(() =>
{
var dbg = logProbe.ExpectMsg<Debug>();
dbg.Message.ToString().Should().Contain(nameof(SlowLoggerActor)).And.Contain("started");
});

var logger = Logging.GetLogger(sys, this);
logger.Error("TEST");
await AwaitAssertAsync(() =>
{
probe.ExpectMsg<string>().Should().Be("TEST");
});
}
finally
{
if(sys != null)
Shutdown(sys);
}
}

[Theory(DisplayName = "ActorSystem should start with loggers throwing exceptions")]
[InlineData("ctor")]
[InlineData("PreStart")]
[InlineData("Receive")]
public void ActorSystem_should_start_with_logger_exception(string when)
{
var config = ConfigurationFactory.ParseString($@"
akka.loglevel = DEBUG
akka.stdout-logger-class = ""{typeof(XUnitOutLogger).FullName}, {typeof(XUnitOutLogger).Assembly.GetName().Name}""
akka.loggers = [
""Akka.Event.DefaultLogger"",
""{typeof(ThrowingLogger).FullName}, {typeof(ThrowingLogger).Assembly.GetName().Name}""
]
akka.logger-startup-timeout = 100ms").WithFallback(DefaultConfig);

ThrowingLogger.ThrowWhen = when;
ActorSystem sys = null;
try
{
this.Invoking(_ => sys = ActorSystem.Create("test", config)).Should()
.NotThrow("System should not fail to start when a logger throws an exception");
}
finally
{
if(sys != null)
Shutdown(sys);
}
}

public class SlowLoggerActor : ReceiveActor
[Fact(DisplayName = "ActorSystem should throw and fail to start on invalid logger FQCN entry")]
public void ActorSystem_should_fail_on_invalid_logger()
{
public SlowLoggerActor()
var config = ConfigurationFactory.ParseString($@"
akka.loglevel = DEBUG
akka.stdout-logger-class = ""{typeof(XUnitOutLogger).FullName}, {typeof(XUnitOutLogger).Assembly.GetName().Name}""
akka.loggers = [
""Akka.Event.InvalidLogger, NonExistantAssembly""
]
akka.logger-startup-timeout = 100ms").WithFallback(DefaultConfig);

ActorSystem sys = null;
try
{
this.Invoking(_ => sys = ActorSystem.Create("test", config)).Should()
.ThrowExactly<ConfigurationException>("System should fail to start with invalid logger FQCN");
}
finally
{
if(sys != null)
Shutdown(sys);
}
}

private class TestException: Exception
{
public TestException(string message) : base(message)
{ }
}

private class ThrowingLogger : ActorBase, IRequiresMessageQueue<ILoggerMessageQueueSemantics>
{
public static string ThrowWhen = "Receive";

public ThrowingLogger()
{
ReceiveAsync<InitializeLogger>(async _ =>
if(ThrowWhen == "ctor")
throw new TestException(".ctor BOOM!");
}

protected override void PreStart()
{
base.PreStart();
if(ThrowWhen == "PreStart")
throw new TestException("PreStart BOOM!");
}

protected override bool Receive(object message)
{
if(message is InitializeLogger)
{
// Ooops... Logger is responding too slow
await Task.Delay(LoggerResponseDelayMs);
if(ThrowWhen == "Receive")
throw new TestException("Receive BOOM!");

Sender.Tell(new LoggerInitialized());
});
return true;
}

return false;
}
}

private class SlowLoggerActor : ActorBase, IWithUnboundedStash, IRequiresMessageQueue<ILoggerMessageQueueSemantics>
{
public static TestProbe Probe;

public SlowLoggerActor()
{
Become(Starting);
}

private void Log(LogLevel level, string str)
private bool Starting(object message)
{
switch (message)
{
case InitializeLogger _:
var sender = Sender;
Task.Delay(LoggerResponseDelayMs).PipeTo(Self, sender, success: () => Done.Instance);
Become(Initializing);
return true;
default:
Stash.Stash();
return true;
}
}

private bool Initializing(object message)
{
switch (message)
{
case Done _:
Sender.Tell(new LoggerInitialized());
Become(Initialized);
Stash.UnstashAll();
return true;
default:
Stash.Stash();
return true;
}
}

private bool Initialized(object message)
{
switch (message)
{
case LogEvent evt:
Probe.Tell(evt.Message.ToString());
return true;
default:
return false;
}
}

protected override bool Receive(object message)
{
throw new NotImplementedException();
}

public IStash Stash { get; set; }
}

public class XUnitOutLogger : MinimalLogger
{
public static ITestOutputHelper Helper;

protected override void Log(object message)
{
Helper.WriteLine(message.ToString());
}
}
}
Expand Down

0 comments on commit c8b46b4

Please sign in to comment.