Flaky test: InMemoryMqtt311End2EndSpecs.ShouldSubscribeAndReceiveMessagesWithMultipleSubscriptions

[Aaronontheweb]

[xUnit.net 00:00:07.17]     TurboMqtt.Tests.End2End.InMemoryMqtt311End2EndSpecs.ShouldSubscribeAndReceiveMessagesWithMultipleSubscriptions [FAIL]
[xUnit.net 00:00:07.17]       Expected connectResult.IsSuccess to be true, but found False.
[xUnit.net 00:00:07.17]       Stack Trace:
[xUnit.net 00:00:07.17]            at FluentAssertions.Execution.XUnit2TestFramework.Throw(String message)
[xUnit.net 00:00:07.17]            at FluentAssertions.Execution.TestFrameworkProvider.Throw(String message)
[xUnit.net 00:00:07.17]            at FluentAssertions.Execution.DefaultAssertionStrategy.HandleFailure(String message)
[xUnit.net 00:00:07.17]            at FluentAssertions.Execution.AssertionScope.FailWith(Func`1 failReasonFunc)
[xUnit.net 00:00:07.17]            at FluentAssertions.Primitives.BooleanAssertions`1.BeTrue(String because, Object[] becauseArgs)
[xUnit.net 00:00:07.17]         D:\a\TurboMqtt\TurboMqtt\tests\TurboMqtt.Tests\End2End\TransportSpecBase.cs(171,0): at TurboMqtt.Tests.End2End.TransportSpecBase.ShouldSubscribeAndReceiveMessagesWithMultipleSubscriptions()
[xUnit.net 00:00:07.17]         --- End of stack trace from previous location ---

Probably an issue with the transport base spec.

[Aaronontheweb]

This looks like a fluke - no real raciness or I/O here to speak of.

[Aaronontheweb]

I stand corrected - was able to reproduce this locally:

Xunit.Sdk.XunitException
Expected connectResult.IsSuccess to be true, but found False.
   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(Func`1 failReasonFunc)
   at FluentAssertions.Execution.AssertionScope.FailWith(Func`1 failReasonFunc)
   at FluentAssertions.Execution.AssertionScope.FailWith(String message, Object[] args)
   at FluentAssertions.Primitives.BooleanAssertions`1.BeTrue(String because, Object[] becauseArgs)
   at TurboMqtt.Tests.End2End.TransportSpecBase.ShouldSubscribeAndReceiveMessagesWithMultipleSubscriptions() in C:\Repositories\Petabridge\TurboMqtt\tests\TurboMqtt.Tests\End2End\TransportSpecBase.cs:line 171
   at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass46_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 259
--- End of stack trace from previous location ---
   at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90



[ERROR][04/26/2024 17:43:49.876Z][Thread 0034][akka://test/user/turbomqtt-clients/mqttclient-test-client-0/heartbeat] Worker in invalid state: 1
Cause: [akka://test/user/turbomqtt-clients/mqttclient-test-client-0/heartbeat#683506534]: Akka.Actor.ActorInitializationException: Exception during creation
 ---> System.InvalidOperationException: Worker in invalid state: 1
   at Akka.Actor.HashedWheelTimerScheduler.Start()
   at Akka.Actor.HashedWheelTimerScheduler.InternalSchedule(TimeSpan delay, TimeSpan interval, IRunnable action, ICancelable cancelable)
   at Akka.Actor.HashedWheelTimerScheduler.InternalScheduleTellRepeatedly(TimeSpan initialDelay, TimeSpan interval, ICanTell receiver, Object message, IActorRef sender, ICancelable cancelable)
   at Akka.Actor.SchedulerBase.Akka.Actor.ITellScheduler.ScheduleTellRepeatedly(TimeSpan initialDelay, TimeSpan interval, ICanTell receiver, Object message, IActorRef sender, ICancelable cancelable)
   at Akka.Actor.SchedulerExtensions.ScheduleTellRepeatedlyCancelable(IScheduler scheduler, TimeSpan initialDelay, TimeSpan interval, ICanTell receiver, Object message, IActorRef sender)
   at Akka.Actor.Scheduler.TimerScheduler.StartTimer(Object key, Object msg, TimeSpan timeout, TimeSpan initialDelay, Boolean repeat)
   at Akka.Actor.Scheduler.TimerScheduler.StartPeriodicTimer(Object key, Object msg, TimeSpan interval)
   at TurboMqtt.Protocol.HeartBeatActor.PreStart() in C:\Repositories\Petabridge\TurboMqtt\src\TurboMqtt\Protocol\HeartBeatActor.cs:line 133
   at Akka.Actor.ActorBase.AroundPreStart()
   at Akka.Actor.ActorCell.<>c__DisplayClass175_0.<Create>b__0()
   at Akka.Actor.ActorCell.UseThreadContext(Action action)
   at Akka.Actor.ActorCell.Create(Exception failure)
   --- End of inner exception stack trace ---
   at Akka.Actor.ActorCell.Create(Exception failure)
   at Akka.Actor.ActorCell.SysMsgInvokeAll(EarliestFirstSystemMessageList messages, Int32 currentState)
[DEBUG][04/26/2024 17:43:49.877Z][Thread 0033][<InMemoryMqttTransportManager> test-client] Starting to read from transport.
[ERROR][04/26/2024 17:43:49.881Z][Thread 0014][akka://test/user/turbomqtt-clients/mqttclient-test-client-0] One of the required actors [[akka://test/user/turbomqtt-clients/mqttclient-test-client-0/heartbeat#683506534]] has terminated. This is an unexpected and fatal error. Shutting down the client.
[WARNING][04/26/2024 17:43:49.886Z][Thread 0035][akka://test/user/turbomqtt-clients/mqttclient-test-client-0/stream-owner-0] Transport was terminated by broker. Shutting down client.
[DEBUG][04/26/2024 17:43:49.887Z][Thread 0012][LogSource (akka://test)] Encoded 1 messages using 37 bytes
[ERROR][04/26/2024 17:43:52.879Z][Thread 0012][akka://test/user/turbomqtt-clients/mqttclient-test-client-0] Failed to connect to MQTT broker - Reason: A task was canceled.
Cause: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at TurboMqtt.Client.MqttClient.ConnectAsync(CancellationToken cancellationToken) in C:\Repositories\Petabridge\TurboMqtt\src\TurboMqtt\Client\IMqttClient.cs:line 263
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0012][CoordinatedShutdown (akka://test)] Performing phase [before-service-unbind] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [service-unbind] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [service-requests-done] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [service-stop] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [before-cluster-shutdown] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [cluster-sharding-shutdown-region] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [cluster-leave] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [cluster-exiting] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [cluster-exiting-done] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [cluster-shutdown] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.918Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [before-actor-system-terminate] with [0] tasks.
[DEBUG][04/26/2024 17:43:52.922Z][Thread 0015][CoordinatedShutdown (akka://test)] Performing phase [actor-system-terminate] with [1] tasks: [terminate-system]
[DEBUG][04/26/2024 17:43:52.922Z][Thread 0015][ActorSystem(test)] System shutdown initiated
[DEBUG][04/26/2024 17:43:52.923Z][Thread 0007][EventStream] Shutting down: StandardOutLogger started
[DEBUG][04/26/2024 17:43:52.923Z][Thread 0007][EventStream] All default loggers stopped

This looks like an Akka.NET bug, related to akkadotnet/akka.net#7144

[Aaronontheweb]

Fix has been merged into Akka.NET - going to need to wait for the v1.5.20 release.

[Aaronontheweb]

Running this now locally with "run until failure" enabled - previously it failed in under ~10 minutes typically.