ExpectMsgAsync deadlocks with actor that has async receive handler and testprobe.Tell

[biasc]

Version Information
Akka.TestKit.Xunit2 1.5.16 and upwards (works with 1.5.15 and downward)

Describe the bug
ExpectMsgAsync/ExpectMsg in combination with tell on an actor with async receive handler that calls "Tell" on the test probe that triggered the handler.

To Reproduce
Steps to reproduce the behavior:

1. Download the project
2. Run the unit test (the test deadlock)
3. Downgrade package to akka 1.5.15
4. Run the unit test (the test pass)

Link to the test project:
https://github.com/biasc/Akka-Bug-Report/tree/main

Expected behavior
Unit test should pass - no deadlock should occur.

Actual behavior
The unit test deadlocked.

Screenshots
If applicable, add screenshots to help explain your problem.

Environment
Windows 11, net8.0

[Aaronontheweb]

This is the only major TestKit change we made in v1.5.16 #7037 and it looks like you're not using Watch or Unwatch inside your reproduction.

Results with Akka.NET v1.5.16

However, running your reproduction I did get this log out of the box:

[INFO][04/11/2024 03:35:25.009Z][Thread 0048][akka://testActorSystem/user/$a] Message [RepointableActorRef] from [akka://testActorSystem/system/testActor1#1407816324] to [akka://testActorSystem/user/$a#649356844] was unhandled. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. Message content: [akka://testActorSystem/system/testActor2#1794388584]

And the test did indeed deadlock.

Results with Akka.NET v1.5.15

Test passed this time, but here's what's strange - I still get a DeadLetter here:

[INFO][04/11/2024 03:37:22.341Z][Thread 0049][akka://testActorSystem/user/$a] Message [RepointableActorRef] from [akka://testActorSystem/system/testActor1#1047382087] to [akka://testActorSystem/user/$a#2113645312] was unhandled. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. Message content: [akka://testActorSystem/system/testActor2#927266162]
[DEBUG][04/11/2024 03:37:22.405Z][Thread 0050][ActorSystem(testActorSystem)] System shutdown initiated
[DEBUG][04/11/2024 03:37:22.424Z][Thread 0036][EventStream] Shutting down: StandardOutLogger started
[DEBUG][04/11/2024 03:37:22.424Z][Thread 0036][EventStream] All default loggers stopped

Looks like this is a bug with the InitActor so nothing to get too excited about. I wonder if we did something with async contexts in v1.5.16. We'll investigate.

[Aaronontheweb]

Lost my original GH message due to my browser crashing, but I modified the InitActor in my fork to include some additional logging https://github.com/Aaronontheweb/Akka-Bug-Report

using Akka.Actor;
using Akka.Event;
using AkkaTest.Messages;

namespace AkkaTest.Actors;

public class InitActor : ReceiveActor
{
    private readonly ILoggingAdapter _logger = Context.GetLogger();
    
    public InitActor()
    {
        ReceiveAsync<InitRequestMessage>(Handler);
    }

    private async Task Handler(InitRequestMessage initMsg)
    {
        _logger.Info("First step - Sender: {0}", Sender);
        
        // Do something'
        await Task.Delay(1);
        
        Sender.Tell(new InitResponseMessage(), Self);
        
        _logger.Info("Second step - Sender: {0}", Sender);
        
        //await Task.Delay(1); // Uncomment this line to fix the test, with 1.5.15 works without uncomment
        
        Sender.Tell(new StartRequestMessage(), Self);
        
        _logger.Info("Third step - Sender: {0}", Sender);
    }
}

Akka.NET v1.5.16 Results

Here's what is spooky:

[INFO][04/11/2024 03:50:29.127Z][Thread 0048][akka://testActorSystem/user/$a] Message [RepointableActorRef] from [akka://testActorSystem/system/testActor1#1600264286] to [akka://testActorSystem/user/$a#336826858] was unhandled. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. Message content: [akka://testActorSystem/system/testActor2#208916759]
[INFO][04/11/2024 03:50:29.128Z][Thread 0012][akka://testActorSystem/user/$a] First step - Sender: [akka://testActorSystem/system/testActor1#1600264286]
[INFO][04/11/2024 03:50:29.146Z][Thread 0051][akka://testActorSystem/user/$a] Second step - Sender: [akka://testActorSystem/system/testActor1#1600264286]


Last launch log file: C:\Users\aaron\AppData\Local\JetBrains\Rider2023.3\log\UnitTestLogs\Sessions\2024-04-10-22-50-25-689___30df6e20-4981-4916-add0-f3707a2547c3.log

We never hit the "third step" logging call - even weirder, none of the timeouts on ExpectMsgAsync ever hit.

Akka.NET v1.5.15 Results

Added a v1.5.15 branch here https://github.com/Aaronontheweb/Akka-Bug-Report/tree/1.5.15 and ran the results:

[INFO][04/11/2024 03:57:41.402Z][Thread 0050][akka://testActorSystem/user/$a] Message [RepointableActorRef] from [akka://testActorSystem/system/testActor1#1861897476] to [akka://testActorSystem/user/$a#1001050960] was unhandled. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. Message content: [akka://testActorSystem/system/testActor2#1661560092]
[INFO][04/11/2024 03:57:41.405Z][Thread 0012][akka://testActorSystem/user/$a] First step - Sender: [akka://testActorSystem/system/testActor1#1861897476]
[INFO][04/11/2024 03:57:41.435Z][Thread 0012][akka://testActorSystem/user/$a] Second step - Sender: [akka://testActorSystem/system/testActor1#1861897476]
[INFO][04/11/2024 03:57:41.435Z][Thread 0012][akka://testActorSystem/user/$a] Third step - Sender: [akka://testActorSystem/system/testActor1#1861897476]
[DEBUG][04/11/2024 03:57:41.468Z][Thread 0012][ActorSystem(testActorSystem)] System shutdown initiated
[DEBUG][04/11/2024 03:57:41.484Z][Thread 0046][EventStream] Shutting down: StandardOutLogger started
[DEBUG][04/11/2024 03:57:41.484Z][Thread 0046][EventStream] All default loggers stopped

Works fine! So I'm left wondering, if the removal of the ConfigureAwait(false) calls on many of our TestKit methods in #7037 could somehow be responsible for this. That blows my mind, to some extent, because the actors and the test methods themselves are supposed to be running in entirely separate async contexts.

[Aaronontheweb]

If I comment out all of the ExpectMsgAsync calls, I see all three steps from the actor show up. If I add a ConfigureAwait(false) to them then only the first reply executes. I think I know what's going on here - it's a lack of async executions happening on the Sender.Tell call when we send the message back to the TestActor. This is creating a bit of a deadlock between the InitActor and the TestActor / TestProbe.

Things worked before because we had ConfigureAwait(false) everywhere but that was sloppy and created other problems (you actually WANT test methods to always be on the same async context - that's why xUnit growls at you with an analyzer rule if you start adding ConfigureAwait(false) inside of test methods.)

I think what we need to do here is fix the AsyncQueue structure that the TestActors use internally such that reading and writing can happen asynchronously. This is probably a design error going all the way back to the "async TestKit" rewrite we did for v1.5 that was basically covered up by ConfigureAwait calls. We've run into this before in our past #2546 - it's the kind of bug you have to know to look for.

That being said, this should be a straightforward fix - I think we can probably just get rid of our AsyncQueue data structure and use a System.Threading.Channel<T> instead.

[biasc]

I have checked the Akka.NET v1.5.16 notes and i'have seen this commit: 3fb9247 where the ConfigureAwait(false) has been removed

   // v1.5.15
    return ExpectMsgAsync<T>(duration, hint, cancellationToken).ConfigureAwait(false).GetAwaiter().GetResult();

   // v1.5.16
   return ExpectMsgAsync<T>(duration, hint, cancellationToken).GetAwaiter().GetResult();

Thank you for your quick answer!

[Aaronontheweb]

I have a validated fix for this here: #7157 - I just need to clean up some of the other TestKit methods first before I ask for reviews.