Akka.TestKit creation and ActorSystem.Create time-out when system is under load

[basbossink]

Recently I stumbled upon wobbly tests in our build. Investigation showed that the failing test was caused by a time-out in the TestKitBase.InitializeTest method. In trying to have a reproducible test-case I ran our tests while also running Prime95. This resulted in a lot of tests failing the failure cases could be split into two distinct cases:

Akka.Configuration.ConfigurationException : Logger [Akka.TestKit.TestEventListener, Akka.TestKit] specified in config cannot be loaded: System.AggregateException: One or more errors occurred. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Akka.Event.LoggingBus.AddLogger(ActorSystemImpl system, Type loggerType, LogLevel logLevel, String loggingBusName, TimeSpan timeout)
   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
---> (Inner Exception #0) System.Threading.Tasks.TaskCanceledException: A task was canceled.<---

---- System.AggregateException : One or more errors occurred.
-------- System.Threading.Tasks.TaskCanceledException : A task was canceled.
<stack-trace>   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
   at Akka.Actor.Internal.ActorSystemImpl.Start()
   at Akka.Actor.ActorSystem.Create(String name, Config config)
   at Akka.Vlow.TestKit.Xunit2.AsyncTestKit.CreateActorSystem() in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\Xunit2\AsyncTestKit.cs:line 133
   at Akka.Vlow.TestKit.Xunit2.AsyncTestKit.CreateActorSystem(String hokon) in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\Xunit2\AsyncTestKit.cs:line 127
   at Akka.Vlow.TestKit.Xunit2.AsyncTestKit..ctor(String hokon) in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\Xunit2\AsyncTestKit.cs:line 18
   at Akka.Vlow.TestKit.VlowTestKit..ctor(String hokon, IAkkaVlowSupportHub vlowSystem) in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\VlowTestKit.cs:line 40
   at Akka.Vlow.TestKit.VlowTestKit..ctor() in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\VlowTestKit.cs:line 22
   at Akka.Vlow.Tests.Actors.SwitchActorTests..ctor()
----- Inner Stack Trace -----
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Akka.Event.LoggingBus.AddLogger(ActorSystemImpl system, Type loggerType, LogLevel logLevel, String loggingBusName, TimeSpan timeout)
   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
----- Inner Stack Trace -----
</stack-trace>

and

Timeout 00:00:05 expired while waiting for condition.
Expected: True
Actual:   False
<stack-trace>   at Akka.TestKit.Xunit2.XunitAssertions.Fail(String format, Object[] args)
   at Akka.TestKit.TestKitBase.&lt;&gt;c__DisplayClass136_0.&lt;AwaitCondition&gt;b__0(String format, Object[] args)
   at Akka.TestKit.TestKitBase.InternalAwaitCondition(Func`1 conditionIsFulfilled, TimeSpan max, Nullable`1 interval, Action`2 fail, ILoggingAdapter logger)
   at Akka.TestKit.TestKitBase.AwaitCondition(Func`1 conditionIsFulfilled, Nullable`1 max, Nullable`1 interval, String message)
   at Akka.TestKit.TestKitBase.InitializeTest(ActorSystem system, Config config, String actorSystemName, String testActorName)
   at Akka.TestKit.Xunit2.TestKit..ctor(ActorSystem system, ITestOutputHelper output)
   at Akka.Vlow.TestKit.Xunit2.AsyncTestKit..ctor(String hokon) in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\Xunit2\AsyncTestKit.cs:line 18
   at Akka.Vlow.TestKit.VlowTestKit..ctor(String hokon, IAkkaVlowSupportHub vlowSystem) in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\VlowTestKit.cs:line 40
   at Akka.Vlow.TestKit.VlowTestKit..ctor() in C:\Divv\Vlow\Akka\src\Akka.Vlow.TestKit\VlowTestKit.cs:line 22
   at Akka.Vlow.Tests.Actors.DeliveryAggregatorTests..ctor()
</stack-trace>

Since our build runs all of our tests in parallel these two cases actually pop-up in the wild. Inspecting the code I noticed that the logger-startup-timeout is configurable. However the timeout in TestKit.InitializeTest is hard-coded. So my proposal would be to either increase it or make it configurable as well. In case the project also thinks it is a good idea to just increase the time out, I'll be happy to create a pull request for it, ;-).

[y4k]

Encountered the same issue with NUnit and parameterized tests. A combinatorial test with 3 parameters producing 40 individual tests. Running with ReSharper test runner in VisualStudio. The first 5-6 tests pass while the remainder fail (except the odd one). MSTest explorer results in the same problem.

   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__6`1.MoveNext()
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at System.Threading.Tasks.Task`1.get_Result()
   at Akka.Event.LoggingBus.AddLogger(ActorSystemImpl system, Type loggerType, LogLevel logLevel, String loggingBusName, TimeSpan timeout)
   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
---> (Inner Exception #0) Akka.Actor.AskTimeoutException: Timeout after 00:00:05 seconds
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__6`1.MoveNext()<---

  ----> System.AggregateException : One or more errors occurred.
  ----> Akka.Actor.AskTimeoutException : Timeout after 00:00:05 seconds
TearDown : System.NullReferenceException : Object reference not set to an instance of an object.
   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
   at Akka.Actor.LocalActorRefProvider.Init(ActorSystemImpl system)
   at Akka.Actor.Internal.ActorSystemImpl.Start()
   at Akka.TestKit.TestKitBase.InitializeTest(ActorSystem system, Config config, String actorSystemName, String testActorName)
   at Akka.TestKit.NUnit.TestKit.InitializeActorSystemOnSetUp()
--AggregateException
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at System.Threading.Tasks.Task`1.get_Result()
   at Akka.Event.LoggingBus.AddLogger(ActorSystemImpl system, Type loggerType, LogLevel logLevel, String loggingBusName, TimeSpan timeout)
   at Akka.Event.LoggingBus.StartDefaultLoggers(ActorSystemImpl system)
--AskTimeoutException
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Akka.Actor.Futures.<Ask>d__6`1.MoveNext()
--TearDown
   at Akka.TestKit.TestKitBase.Dilated(TimeSpan duration)
   at Akka.TestKit.TestKitBase.Shutdown(ActorSystem system, Nullable`1 duration, Boolean verifySystemShutdown)
   at Akka.TestKit.TestKitBase.Shutdown(Nullable`1 duration, Boolean verifySystemShutdown)
   at Akka.TestKit.NUnit.TestKit.AfterAll()
   at Akka.TestKit.NUnit.TestKit.ShutDownActorSystemOnTearDown()

[Aaronontheweb]

Added #4424 as a work-around for this issue.