Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Make loggers to not block ActorSystem creation #4424

Merged
merged 22 commits into from
May 26, 2020
Merged
Show file tree
Hide file tree
Changes from 16 commits
Commits
Show all changes
22 commits
Select commit Hold shift + click to select a range
bbe90a4
enable loggers to start asynchronously
Aaronontheweb May 20, 2020
86d4a44
Refactored and optimized loggers addition
IgorFedchenko May 21, 2020
8ea1601
Using Task.Run to start background task with thread context capture
IgorFedchenko May 21, 2020
2267c83
Rollback from async Ask to blocking Result after Task.Run
IgorFedchenko May 21, 2020
dafff6a
Moved async loggers to settings, disabled by default
IgorFedchenko May 21, 2020
0e0a181
Use async API when possible inside logger creation task
IgorFedchenko May 21, 2020
0755636
Renamed new logger setting to LoggerAsyncStart
IgorFedchenko May 21, 2020
7560048
Removed async/await use in logger creation
IgorFedchenko May 21, 2020
dcb3874
Return old Ask implementation
IgorFedchenko May 21, 2020
b305b4e
Enabled async loggers start by default
IgorFedchenko May 21, 2020
271826b
Added API approvement
IgorFedchenko May 21, 2020
6722974
Added new setting spec (passing)
IgorFedchenko May 21, 2020
bd3c560
Fixed LoggerSpec
IgorFedchenko May 21, 2020
1e3f00e
Included akka.logger-async-start into reference akka.net configuration
IgorFedchenko May 21, 2020
2c12a89
Fixed/disabled racy specs
IgorFedchenko May 21, 2020
65bec08
Enabled setting by default
IgorFedchenko May 21, 2020
5035f15
Disabled setting by default
IgorFedchenko May 21, 2020
36e5cbe
Merge branch 'dev' into 4054-load-loggers-async
IgorFedchenko May 22, 2020
390cc1f
Merge branch 'dev' into 4054-load-loggers-async
IgorFedchenko May 23, 2020
29d4b8b
Merge branch 'dev' into 4054-load-loggers-async
IgorFedchenko May 26, 2020
2b683ac
Disabled racy/hanging specs
IgorFedchenko May 26, 2020
b808798
Merge branch 'dev' into 4054-load-loggers-async
IgorFedchenko May 26, 2020
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -1594,6 +1594,7 @@ namespace Akka.Actor
public int LogDeadLetters { get; }
public bool LogDeadLettersDuringShutdown { get; }
public string LogLevel { get; }
public bool LoggerAsyncStart { get; }
public System.TimeSpan LoggerStartTimeout { get; }
public System.Collections.Generic.IList<string> Loggers { get; }
public string LoggersDispatcher { get; }
Expand Down
9 changes: 5 additions & 4 deletions src/core/Akka.Streams.Tests/Dsl/FlowBatchSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Akka.Streams.Dsl;
using Akka.Streams.TestKit;
using Akka.TestKit;
Expand Down Expand Up @@ -76,16 +77,16 @@ public void Batch_must_aggregate_elements_while_downstream_is_silent()
}

[Fact]
public void Batch_must_work_on_a_variable_rate_chain()
public async Task Batch_must_work_on_a_variable_rate_chain()
{
var future = Source.From(Enumerable.Range(1, 1000)).Batch(100, i => i, (sum, i) => sum + i).Select(i =>
var result = await Source.From(Enumerable.Range(1, 1000)).Batch(100, i => i, (sum, i) => sum + i).Select(i =>
{
if (ThreadLocalRandom.Current.Next(1, 3) == 1)
Thread.Sleep(10);
return i;
}).RunAggregate(0, (i, i1) => i + i1, Materializer);
future.Wait(TimeSpan.FromSeconds(10)).Should().BeTrue();
future.Result.Should().Be(500500);

result.Should().Be(500500);
}

[Fact]
Expand Down
2 changes: 1 addition & 1 deletion src/core/Akka.Streams.Tests/Dsl/FlowThrottleSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -331,7 +331,7 @@ public void Throttle_for_various_cost_elements_must_work_for_the_happy_case()
}, Materializer);
}

[Fact]
[Fact(Skip = "Racy, see https://github.com/akkadotnet/akka.net/pull/4424#issuecomment-632284459")]
public void Throttle_for_various_cost_elements_must_emit_elements_according_to_cost()
{
this.AssertAllStagesStopped(() =>
Expand Down
12 changes: 4 additions & 8 deletions src/core/Akka.Streams.Tests/Dsl/GraphStageTimersSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -46,17 +46,13 @@ private SideChannel SetupIsolatedStage()
}

[Fact]
public void GraphStage_timer_support_must_receive_single_shot_timer()
public async Task GraphStage_timer_support_must_receive_single_shot_timer()
{
var driver = SetupIsolatedStage();
Within(TimeSpan.FromSeconds(2), () =>
await AwaitAssertAsync(() =>
{
Within(TimeSpan.FromMilliseconds(500), TimeSpan.FromSeconds(1), () =>
{
driver.Tell(TestSingleTimer.Instance);
ExpectMsg(new Tick(1));
});

driver.Tell(TestSingleTimer.Instance);
ExpectMsg(new Tick(1), TimeSpan.FromSeconds(10));
ExpectNoMsg(TimeSpan.FromSeconds(1));
});
driver.StopStage();
Expand Down
7 changes: 3 additions & 4 deletions src/core/Akka.Streams.Tests/Dsl/QueueSinkSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -167,14 +167,13 @@ public void QueueSink_should_fail_pull_future_when_stream_is_completed()
ExpectMsg(new Option<int>(1));

sub.SendComplete();
var future = queue.PullAsync();
future.Wait(_pause).Should().BeTrue();
future.Result.Should().Be(Option<int>.None);
var result = queue.PullAsync().Result;
result.Should().Be(Option<int>.None);

((Task)queue.PullAsync()).ContinueWith(t =>
{
t.Exception.InnerException.Should().BeOfType<IllegalStateException>();
}, TaskContinuationOptions.OnlyOnFaulted).Wait(TimeSpan.FromMilliseconds(300));
}, TaskContinuationOptions.OnlyOnFaulted).Wait();
}, _materializer);
}

Expand Down
2 changes: 1 addition & 1 deletion src/core/Akka.Streams.Tests/Dsl/TickSourceSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -89,7 +89,7 @@ public void A_Flow_based_on_a_tick_publisher_must_reject_multiple_subscribers_bu
}, Materializer);
}

[Fact]
[Fact(Skip = "Racy. See https://github.com/akkadotnet/akka.net/pull/4424#issuecomment-632284459")]
public void A_Flow_based_on_a_tick_publisher_must_be_usable_with_zip_for_a_simple_form_of_rate_limiting()
{
this.AssertAllStagesStopped(() =>
Expand Down
9 changes: 6 additions & 3 deletions src/core/Akka.Tests/Event/LoggerSpec.cs
Original file line number Diff line number Diff line change
Expand Up @@ -117,9 +117,12 @@ public async Task LoggingBus_should_stop_all_loggers_on_termination()
system.EventStream.Subscribe(TestActor, typeof(Debug));
await system.Terminate();

var shutdownInitiated = ExpectMsg<Debug>(TestKitSettings.DefaultTimeout);
shutdownInitiated.Message.ShouldBe("System shutdown initiated");

await AwaitAssertAsync(() =>
{
var shutdownInitiated = ExpectMsg<Debug>(TestKitSettings.DefaultTimeout);
shutdownInitiated.Message.ShouldBe("System shutdown initiated");
});

var loggerStarted = ExpectMsg<Debug>(TestKitSettings.DefaultTimeout);
loggerStarted.Message.ShouldBe("Shutting down: StandardOutLogger started");
loggerStarted.LogClass.ShouldBe(typeof(EventStream));
Expand Down
56 changes: 56 additions & 0 deletions src/core/Akka.Tests/Loggers/LoggerStartupSpec.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
// //-----------------------------------------------------------------------
// // <copyright file="LoggerStartupSpec.cs" company="Akka.NET Project">
// // Copyright (C) 2009-2020 Lightbend Inc. <http://www.lightbend.com>
// // Copyright (C) 2013-2020 .NET Foundation <https://github.com/akkadotnet/akka.net>
// // </copyright>
// //-----------------------------------------------------------------------

using System;
using System.Threading.Tasks;
using Akka.Actor;
using Akka.Configuration;
using Akka.Event;
using FluentAssertions;
using Xunit;

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

[Fact]
public async Task Logger_async_start_configuration_helps_to_ignore_hanging_loggers()
{
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}\"]");

// Without logger async start, ActorSystem creation will hang
this.Invoking(_ => ActorSystem.Create("handing", slowLoggerConfig.WithFallback(loggerAsyncStartDisabledConfig)))
.ShouldThrow<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));
}

public class SlowLoggerActor : ReceiveActor
{
public SlowLoggerActor()
{
ReceiveAsync<InitializeLogger>(async _ =>
{
// Ooops... Logger is responding too slow
await Task.Delay(LoggerResponseDelayMs);
Sender.Tell(new LoggerInitialized());
});
}

private void Log(LogLevel level, string str)
{
}
}
}
}
7 changes: 7 additions & 0 deletions src/core/Akka/Actor/Settings.cs
Original file line number Diff line number Diff line change
Expand Up @@ -84,6 +84,7 @@ public Settings(ActorSystem system, Config config)
Loggers = Config.GetStringList("akka.loggers", new string[] { });
LoggersDispatcher = Config.GetString("akka.loggers-dispatcher", null);
LoggerStartTimeout = Config.GetTimeSpan("akka.logger-startup-timeout", null);
LoggerAsyncStart = Config.GetBoolean("akka.logger-async-start", true);

//handled
LogConfigOnStart = Config.GetBoolean("akka.log-config-on-start", false);
Expand Down Expand Up @@ -234,6 +235,12 @@ private static string GetProviderClass(string provider)
/// </summary>
/// <value>The logger start timeout.</value>
public TimeSpan LoggerStartTimeout { get; private set; }

/// <summary>
/// Gets the logger start timeout.
/// </summary>
/// <value>The logger start timeout.</value>
public bool LoggerAsyncStart { get; private set; }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you try running it with this setting enabled to true everywhere? Looks like the test suite is running without it

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes - want to check if test suite will work well. Because it seems to me that it is blocking even without async version.
And before introducing this setting, the code was using "async" implementation by default (so I added this setting to be able to disable new behavior) - and test suite kind of stopped.

Probably I need to wait longer. Just checking out CI output and it does not change for some time


/// <summary>
/// Gets a value indicating whether [log configuration on start].
Expand Down
10 changes: 8 additions & 2 deletions src/core/Akka/Configuration/Pigeon.conf
Original file line number Diff line number Diff line change
Expand Up @@ -20,10 +20,16 @@ akka {
# Specifies the default loggers dispatcher
loggers-dispatcher = "akka.actor.default-dispatcher"

# Loggers are created and registered synchronously during ActorSystem
# Loggers are created and registered during ActorSystem
# start-up, and since they are actors, this timeout is used to bound the
# waiting time
# waiting time.
# Especially important when `logger-async-start` is disabled
logger-startup-timeout = 5s

# You can disable asynchronous loggers creation by setting this to `true`.
# This may be useful in cases when ActorSystem creation takes more time
# then it should, or for whatever other reason
logger-async-start = true

# Log level used by the configured loggers (see "loggers") as soon
# as they have been started; before that, see "stdout-loglevel"
Expand Down
26 changes: 21 additions & 5 deletions src/core/Akka/Event/LoggingBus.cs
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,7 @@ internal void StartDefaultLoggers(ActorSystemImpl system)
var logLevel = Logging.LogLevelFor(system.Settings.LogLevel);
var loggerTypes = system.Settings.Loggers;
var timeout = system.Settings.LoggerStartTimeout;
var asyncStart = system.Settings.LoggerAsyncStart;
var shouldRemoveStandardOutLogger = true;

foreach (var strLoggerType in loggerTypes)
Expand All @@ -106,14 +107,29 @@ internal void StartDefaultLoggers(ActorSystemImpl system)
shouldRemoveStandardOutLogger = false;
continue;
}
try

if (asyncStart)
IgorFedchenko marked this conversation as resolved.
Show resolved Hide resolved
{
AddLogger(system, loggerType, logLevel, logName, timeout);
// Not awaiting for result, and not depending on current thread context
Task.Run(() => AddLogger(system, loggerType, logLevel, logName, timeout))
.ContinueWith(t =>
{
if (t.Exception != null)
{
Console.WriteLine($"Logger [{strLoggerType}] specified in config cannot be loaded: {t.Exception}");
}
});
}
catch (Exception e)
else
{
throw new ConfigurationException($"Logger [{strLoggerType}] specified in config cannot be loaded: {e}", e);
try
{
AddLogger(system, loggerType, logLevel, logName, timeout);
}
catch (Exception ex)
{
throw new ConfigurationException($"Logger [{strLoggerType}] specified in config cannot be loaded: {ex}", ex);
}
}
}

Expand Down