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

Conversation

IgorFedchenko
Copy link
Contributor

Continuation of #4422 , trying to make loggers to start without blocking and not blow up the test suite

@IgorFedchenko
Copy link
Contributor Author

Made async loggers startup to be configurable, and disabled by default, because probably this leads to CI suite to block without threads available. Lots of ActorSystems are running, each starts one or more logger creation tasks, each task is blocking for some time - may be the root of the issue.

Basically with new setting disabled it should be the same as earlier. CI should pass. If so, I will add few specs to verify that when some of the systems are running loggers in async way, this is fine.

@IgorFedchenko
Copy link
Contributor Author

IgorFedchenko commented May 21, 2020

So, now we have logger creation task with async support.

When akka.logger-async-start is enabled, task is started in background, is not related to current thread context, and uses async/await where possible to not block threads (so this may allow more ActorSystem instances to be started in parallel).

When setting is disabled, it is performing async/await call with blocking Wait() call. Should not make things worse for existing implementations... Will see how test suite will handle that. In theory, this may lead to deadlocks if ActorSystem is started from UI thread.

/// 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

@IgorFedchenko
Copy link
Contributor Author

IgorFedchenko commented May 21, 2020

Ok, looks like it works (does not hang) when async run setting is disabled. I will enable it now.

@IgorFedchenko
Copy link
Contributor Author

Ok, works well - only need to add api approvement

@IgorFedchenko
Copy link
Contributor Author

Note: will need to disable new setting by default before merging this.

@IgorFedchenko
Copy link
Contributor Author

And will need to add spec showing that without setting and with not-working logger ActorService is handing on Create call, but with setting enabled system is created without issues

@IgorFedchenko
Copy link
Contributor Author

IgorFedchenko commented May 21, 2020

Finally found failing spec: LoggingBus_should_stop_all_loggers_on_termination

2020-05-21T16:14:55.6966498Z [xUnit.net 00:01:28.63]         [DEBUG][5/21/2020 4:14:55 PM][Thread 0090][EventStream] Shutting down: StandardOutLogger started
2020-05-21T16:14:55.7750402Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: ErrorLevel, includeException: False, formatStr: "foo {0}", args: [1]) [61ms]
2020-05-21T16:14:55.7770047Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: DebugLevel, includeException: False, formatStr: "foo", args: []) [57ms]
2020-05-21T16:14:55.7791796Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: WarningLevel, includeException: False, formatStr: "foo {0}", args: [1]) [69ms]
2020-05-21T16:14:55.7812210Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: DebugLevel, includeException: True, formatStr: "foo", args: []) [67ms]
2020-05-21T16:14:55.7832332Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: InfoLevel, includeException: False, formatStr: "foo {0}", args: [1]) [88ms]
2020-05-21T16:14:55.7852652Z   √ Akka.Tests.Event.LoggerSpec.LoggingAdapter_should_log_all_information(logLevel: ErrorLevel, includeException: True, formatStr: "foo {0}", args: [1]) [55ms]
2020-05-21T16:14:55.7868091Z   X Akka.Tests.Event.LoggerSpec.LoggingBus_should_stop_all_loggers_on_termination [85ms]
2020-05-21T16:14:55.7876122Z   Error Message:
2020-05-21T16:14:55.7881033Z    Assert.Equal() Failure
2020-05-21T16:14:55.7886825Z Expected: System shutdown initiated
2020-05-21T16:14:55.7894740Z Actual:   Logger log293-DefaultLogger [DefaultLogger] started
2020-05-21T16:14:55.7900930Z   Stack Trace:
2020-05-21T16:14:55.7913548Z      at Akka.TestKit.AkkaSpecExtensions.ShouldBe[T](T self, T expected, String message) in /home/vsts/work/1/s/src/core/Akka.Tests.Shared.Internals/AkkaSpecExtensions.cs:line 70
2020-05-21T16:14:55.7932982Z    at Akka.Tests.Event.LoggerSpec.LoggingBus_should_stop_all_loggers_on_termination() in /home/vsts/work/1/s/src/core/Akka.Tests/Event/LoggerSpec.cs:line 123

@IgorFedchenko
Copy link
Contributor Author

Fixed it. Now should pass - at least under Linux

@IgorFedchenko
Copy link
Contributor Author

Failed specs:

.NET Framework:

Akka.Streams.Tests.Dsl.FlowBatchSpec.Batch_must_work_on_a_variable_rate_chain [12s 361ms]
  Error Message:
   Expected True, but found False.
  Stack Trace:
     at FluentAssertions.Execution.XUnit2TestFramework.Throw(String message)
   at FluentAssertions.Execution.TestFrameworkProvider.Throw(String message)
   at FluentAssertions.Execution.DefaultAssertionStrategy.HandleFailure(String message)
   at FluentAssertions.Execution.AssertionScope.FailWith(String message, Object[] args)
   at FluentAssertions.Primitives.BooleanAssertions.BeTrue(String because, Object[] becauseArgs)
   at Akka.Streams.Tests.Dsl.FlowBatchSpec.Batch_must_work_on_a_variable_rate_chain() in D:\a\1\s\src\core\Akka.Streams.Tests\Dsl\FlowBatchSpec.cs:line 81

It might be racy. Will try to fix it.

.NET Core (Windows):

Akka.Streams.Tests.Dsl.FlowThrottleSpec.Throttle_for_various_cost_elements_must_emit_elements_according_to_cost [2s 314ms]
  Error Message:
   Failed: Expected no messages during 00:00:00.7000000, instead we received <TestSubscriber.OnNext(��ݳ�rt)> from [akka://AkkaSpec/user/StreamSupervisor-849/Flow-0-0-unknown-operation#1470428615] after 00:00:00.8791352
Expected: True
Actual:   False
  Stack Trace:
     at Akka.TestKit.Xunit2.XunitAssertions.Fail(String format, Object[] args) in D:\a\1\s\src\contrib\testkits\Akka.TestKit.Xunit2\XunitAssertions.cs:line 27
   at Akka.TestKit.TestKitBase.InternalExpectNoMsg(TimeSpan duration) in D:\a\1\s\src\core\Akka.TestKit\TestKitBase_Expect.cs:line 301
   at Akka.TestKit.TestKitBase.ExpectNoMsg(TimeSpan duration) in D:\a\1\s\src\core\Akka.TestKit\TestKitBase_Expect.cs:line 276
   at Akka.Streams.TestKit.TestSubscriber.ManualProbe`1.ExpectNoMsg(TimeSpan remaining) in D:\a\1\s\src\core\Akka.Streams.TestKit\TestSubscriber.cs:line 369
   at Akka.Streams.Tests.Dsl.FlowThrottleSpec.<Throttle_for_various_cost_elements_must_emit_elements_according_to_cost>b__18_0() in D:\a\1\s\src\core\Akka.Streams.Tests\Dsl\FlowThrottleSpec.cs:line 341
   at Akka.Streams.TestKit.Tests.Utils.<>c__DisplayClass3_0.<AssertAllStagesStopped>b__0() in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 30
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped[T](AkkaSpec spec, Func`1 block, IMaterializer materializer) in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 64
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped(AkkaSpec spec, Action block, IMaterializer materializer) in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 32
   at Akka.Streams.Tests.Dsl.FlowThrottleSpec.Throttle_for_various_cost_elements_must_emit_elements_according_to_cost() in D:\a\1\s\src\core\Akka.Streams.Tests\Dsl\FlowThrottleSpec.cs:line 354
Akka.Streams.Tests.Dsl.TickSourceSpec.A_Flow_based_on_a_tick_publisher_must_be_usable_with_zip_for_a_simple_form_of_rate_limiting [2s 692ms]
  Error Message:
   Failed: Expected no messages during 00:00:00.2000000, instead we received <TestSubscriber.OnNext(2)> from [akka://AkkaSpec/user/StreamSupervisor-1283/Flow-0-0-unknown-operation#1179583667] after 00:00:00.0000024
Expected: True
Actual:   False
  Stack Trace:
     at Akka.TestKit.Xunit2.XunitAssertions.Fail(String format, Object[] args) in D:\a\1\s\src\contrib\testkits\Akka.TestKit.Xunit2\XunitAssertions.cs:line 27
   at Akka.TestKit.TestKitBase.InternalExpectNoMsg(TimeSpan duration) in D:\a\1\s\src\core\Akka.TestKit\TestKitBase_Expect.cs:line 301
   at Akka.Streams.TestKit.TestSubscriber.ManualProbe`1.ExpectNoMsg(TimeSpan remaining) in D:\a\1\s\src\core\Akka.Streams.TestKit\TestSubscriber.cs:line 369
   at Akka.Streams.Tests.Dsl.TickSourceSpec.<A_Flow_based_on_a_tick_publisher_must_be_usable_with_zip_for_a_simple_form_of_rate_limiting>b__7_0() in D:\a\1\s\src\core\Akka.Streams.Tests\Dsl\TickSourceSpec.cs:line 113
   at Akka.Streams.TestKit.Tests.Utils.<>c__DisplayClass3_0.<AssertAllStagesStopped>b__0() in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 30
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped[T](AkkaSpec spec, Func`1 block, IMaterializer materializer) in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 64
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped(AkkaSpec spec, Action block, IMaterializer materializer) in D:\a\1\s\src\core\Akka.Streams.TestKit.Tests\Utils.cs:line 32
   at Akka.Streams.Tests.Dsl.TickSourceSpec.A_Flow_based_on_a_tick_publisher_must_be_usable_with_zip_for_a_simple_form_of_rate_limiting() in D:\a\1\s\src\core\Akka.Streams.Tests\Dsl\TickSourceSpec.cs:line 117

.NET Core Linux:

Akka.Streams.Tests.Dsl.QueueSinkSpec.QueueSink_should_fail_pull_future_when_stream_is_completed [1s 175ms]
  Error Message:
   Expected True, but found False.
  Stack Trace:
     at FluentAssertions.Execution.XUnit2TestFramework.Throw(String message)
   at FluentAssertions.Execution.TestFrameworkProvider.Throw(String message)
   at FluentAssertions.Execution.DefaultAssertionStrategy.HandleFailure(String message)
   at FluentAssertions.Execution.AssertionScope.FailWith(String message, Object[] args)
   at FluentAssertions.Primitives.BooleanAssertions.BeTrue(String because, Object[] becauseArgs)
   at Akka.Streams.Tests.Dsl.QueueSinkSpec.<QueueSink_should_fail_pull_future_when_stream_is_completed>b__10_0() in /home/vsts/work/1/s/src/core/Akka.Streams.Tests/Dsl/QueueSinkSpec.cs:line 172
   at Akka.Streams.TestKit.Tests.Utils.<>c__DisplayClass3_0.<AssertAllStagesStopped>b__0() in /home/vsts/work/1/s/src/core/Akka.Streams.TestKit.Tests/Utils.cs:line 30
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped[T](AkkaSpec spec, Func`1 block, IMaterializer materializer) in /home/vsts/work/1/s/src/core/Akka.Streams.TestKit.Tests/Utils.cs:line 64
   at Akka.Streams.TestKit.Tests.Utils.AssertAllStagesStopped(AkkaSpec spec, Action block, IMaterializer materializer) in /home/vsts/work/1/s/src/core/Akka.Streams.TestKit.Tests/Utils.cs:line 32
   at Akka.Streams.Tests.Dsl.QueueSinkSpec.QueueSink_should_fail_pull_future_when_stream_is_completed() in /home/vsts/work/1/s/src/core/Akka.Streams.Tests/Dsl/QueueSinkSpec.cs:line 179
Akka.Streams.Tests.Dsl.GraphStageTimersSpec.GraphStage_timer_support_must_receive_single_shot_timer [2s 427ms]
  Error Message:
   Failed: Timeout 00:00:00.9997318 while waiting for a message of type Akka.Streams.Tests.Dsl.GraphStageTimersSpec+Tick 
Expected: True
Actual:   False
  Stack Trace:
     at Akka.TestKit.Xunit2.XunitAssertions.Fail(String format, Object[] args) in /home/vsts/work/1/s/src/contrib/testkits/Akka.TestKit.Xunit2/XunitAssertions.cs:line 27
   at Akka.TestKit.TestKitBase.InternalExpectMsgEnvelope[T](Nullable`1 timeout, Action`2 assert, String hint, Boolean shouldLog) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Expect.cs:line 253
   at Akka.TestKit.TestKitBase.InternalExpectMsgEnvelope[T](Nullable`1 timeout, Action`1 msgAssert, Action`1 senderAssert, String hint)
   at Akka.TestKit.TestKitBase.InternalExpectMsg[T](Nullable`1 timeout, Action`1 msgAssert, String hint) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Expect.cs:line 199
   at Akka.TestKit.TestKitBase.ExpectMsg[T](T message, Nullable`1 timeout, String hint) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Expect.cs:line 54
   at Akka.Streams.Tests.Dsl.GraphStageTimersSpec.<>c__DisplayClass5_0.<GraphStage_timer_support_must_receive_single_shot_timer>b__1() in /home/vsts/work/1/s/src/core/Akka.Streams.Tests/Dsl/GraphStageTimersSpec.cs:line 58
   at Akka.TestKit.TestKitBase.<>c__DisplayClass155_0.<Within>b__0() in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 57
   at Akka.TestKit.TestKitBase.Within[T](TimeSpan min, TimeSpan max, Func`1 function, String hint, Nullable`1 epsilonValue) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 134
   at Akka.TestKit.TestKitBase.Within(TimeSpan min, TimeSpan max, Action action, String hint, Nullable`1 epsilonValue) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 58
   at Akka.Streams.Tests.Dsl.GraphStageTimersSpec.<>c__DisplayClass5_0.<GraphStage_timer_support_must_receive_single_shot_timer>b__0() in /home/vsts/work/1/s/src/core/Akka.Streams.Tests/Dsl/GraphStageTimersSpec.cs:line 60
   at Akka.TestKit.TestKitBase.<>c__DisplayClass155_0.<Within>b__0() in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 57
   at Akka.TestKit.TestKitBase.Within[T](TimeSpan min, TimeSpan max, Func`1 function, String hint, Nullable`1 epsilonValue) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 134
   at Akka.TestKit.TestKitBase.Within(TimeSpan min, TimeSpan max, Action action, String hint, Nullable`1 epsilonValue) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 58
   at Akka.TestKit.TestKitBase.Within(TimeSpan max, Action action, Nullable`1 epsilonValue) in /home/vsts/work/1/s/src/core/Akka.TestKit/TestKitBase_Within.cs:line 33
   at Akka.Streams.Tests.Dsl.GraphStageTimersSpec.GraphStage_timer_support_must_receive_single_shot_timer() in /home/vsts/work/1/s/src/core/Akka.Streams.Tests/Dsl/GraphStageTimersSpec.cs:line 62
  Standard Output Messages:

Looks like all this specs are racy and are not related to the PR. But I will try making fixes for them, or at least to improve them

@IgorFedchenko IgorFedchenko marked this pull request as ready for review May 21, 2020 19:22
Copy link
Member

@Aaronontheweb Aaronontheweb left a comment

Choose a reason for hiding this comment

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

Left a question

src/core/Akka/Event/LoggingBus.cs Show resolved Hide resolved
@Aaronontheweb
Copy link
Member

@IgorFedchenko have a merge conflict here

@IgorFedchenko
Copy link
Contributor Author

@Aaronontheweb Yeah, @Arkatufus did great job on skipping specs, some of them where already skipped in my code.
Also, there is one spec that I believe not racy anymore after some refactoring on my side - so left it not-skipped when resolved conflict.

@Aaronontheweb
Copy link
Member

Looks like a real test failure:

Akka.DistributedData.Tests.ReplicatorSpecs.Bugfix_4198_PNCounterDictionary_Merge
System.Collections.Generic.KeyNotFoundException : The given key was not present in the dictionary.

@IgorFedchenko
Copy link
Contributor Author

@Aaronontheweb Not sure about is it real - passing locally, and failing in this code:

Within(TimeSpan.FromSeconds(5), () =>
{
	AwaitAssert(() =>
	{
		foreach (var (probe, replicator, _) in probes)
		{
			replicator.Tell(Dsl.Get(_keyC, new ReadAll(_timeOut)), probe);
                        // Failure is here:
			probe.ExpectMsg<GetSuccess>().Get(_keyC).Entries["x"].ShouldBe(new BigInteger(30.0d));
		}
	});
});

So seems like this is due to some increased delays.

@IgorFedchenko
Copy link
Contributor Author

Looks like some tests were hanging in Akka.Streams because I tried to make them non-racy. Probably having some deadlocks there during threads starvation.
Disabled them as @Arkatufus did, will see if it helps.

Copy link
Member

@Aaronontheweb Aaronontheweb left a comment

Choose a reason for hiding this comment

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

LGTM

@IgorFedchenko
Copy link
Contributor Author

Works well now. Good.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants