Akka.Net BackoffSupervisor investigation with max number of retries working not as expected for issue https://github.com/akkadotnet/akka.net/issues/4601

AkkaBackoffSupervisorInvestigation.cs

using System;
using System.Linq;
using Akka.Actor;
using Akka.Event;
using Akka.Pattern;
using Akka.TestKit;
using Akka.TestKit.NUnit;
using Akka.Util.Internal;
using NLog;
using NLog.Targets;
using NUnit.Framework;

namespace ProveBug
{
    [TestFixture]
    public class ProveBugTests : TestKit
    {
        // ReSharper disable once InconsistentNaming
        private TestScheduler Scheduler => (TestScheduler)Sys.Scheduler;

        public ProveBugTests()
            : base(@"
            akka.scheduler.implementation = ""Akka.TestKit.TestScheduler, Akka.TestKit""
            akka.loggers = [""Akka.Logger.NLog.NLogLogger, Akka.Logger.NLog""]
            akka.loglevel = DEBUG")
        {
        }

        [Test]
        public void ProveBug()
        { // This test is only for creating situation, not to prove bug by being red
            var downloaderActor = Sys.ActorOf(Props.Create(() => new DownloaderActor()));
            
            downloaderActor.Tell(new DownloaderActor.Do.Download());
            
            Scheduler.Advance(DownloaderActor.MaxBackOff);
            
            ExpectNoMsg();
            
            downloaderActor.Tell(new DownloaderActor.Do.Download());
            
            ExpectNoMsg();
        }

        [TearDown]
        public void TearDown() => LogManager.Configuration.FindTargetByName<MemoryTarget>("memory").Logs.ToArray().ForEach(TestContext.WriteLine);
        
    }
    
    public class DownloaderActor : ReceiveActor
    {
        private readonly ILoggingAdapter _logger;
        private const int MaxNumberOfRetries = 5;
        public const int MaxNumberOfAttempts = MaxNumberOfRetries + 1;
        public static readonly TimeSpan MaxBackOff = TimeSpan.FromHours(23);

        public DownloaderActor()
        {
            _logger = Context.GetLogger();
            Become(Idle);
        }

        private void Idle()
        {
            Receive<Do.Download>(downloadCommand => Become(() => Working(downloadCommand, Sender)));

            _logger.Info("Became idle");
        }

        private void Working(Do.Download downloadCommand, IActorRef actorWhichWantsDownloadResult)
        {
            _logger.Debug("Got download command, creating request actor");
            var requestActor = CreateRequestActorWhichWillBeRestartedAfterFailure();

            _logger.Debug("Telling request actor to download");
            requestActor.Tell(downloadCommand);

            Receive<RequestActor.Has.Downloaded>(e =>
            {
                _logger.Info("Download succeeded, job is done, becoming idle");
                actorWhichWantsDownloadResult.Forward(e);
                Become(Idle);
            });

            var numberOfFailures = 0;
            Receive<RequestActor.Has.Failed>(e =>
            {
                _logger.Warning("Request failed");
                if (++numberOfFailures == MaxNumberOfAttempts)
                {
                    _logger.Warning($"Max number of attempts ({MaxNumberOfAttempts}) reached, giving up");
                    Become(Idle);
                }
                else
                {
                    _logger.Debug("Telling request actor to download");
                    requestActor.Tell(downloadCommand);
                }
            });

            Receive<Do.Download>(e => _logger.Debug("Received download command while already working, skipping: {@e}", e));

            _logger.Info("Became working");
        }

        private IActorRef CreateRequestActorWhichWillBeRestartedAfterFailure()
        {
            var requestActorProps = BackoffSupervisor.Props(
                Backoff.OnStop(Props.Create(() => new RequestActor()), 
                        childName: nameof(RequestActor),
                        minBackoff: TimeSpan.FromSeconds(2),
                        maxBackoff: MaxBackOff,
                        randomFactor: 0.2,
                        maxNrOfRetries: MaxNumberOfRetries)
                    .WithSupervisorStrategy(new OneForOneStrategy(exception => Directive.Restart)));
                    // Here is the problem, described in issue https://github.com/akkadotnet/akka.net/issues/4601

            return Context.ActorOf(requestActorProps, nameof(RequestActor));
        }

        // ReSharper disable once ClassNeverInstantiated.Global
        public class Do
        {
            public class Download
            {
            }
        }
    }
    
    public class RequestActor : ReceiveActor
    {
        public RequestActor()
        {
            var logger = Context.GetLogger();

            Receive<DownloaderActor.Do.Download>(update =>
            {
                logger.Info("Got download command");
                
                // Here will be real downloading performed and let's say it failed
                Sender.Tell(new Has.Failed());
                throw new Exception("Couldn't download");
            });

            logger.Debug("Actor for one request created");
        }

        // ReSharper disable once ClassNeverInstantiated.Global
        public class Has
        {
            public class Failed
            {
            }

            public class Downloaded
            {
            }
        }
    }
}

/*
Logs:

2020-11-01_00:03:50.709 [Debug] [Logger log1-NLogLogger [NLogLogger] started] | 
2020-11-01_00:03:50.744 [Debug] [StandardOutLogger being removed] | 
2020-11-01_00:03:50.744 [Debug] [Default Loggers started] | 
2020-11-01_00:03:50.744 [Info] [Became idle] | 
2020-11-01_00:03:50.744 [Debug] [Got download command, creating request actor] | 
2020-11-01_00:03:50.744 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.744 [Info] [Became working] | 
2020-11-01_00:03:50.744 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.744 [Info] [Got download command] | 
2020-11-01_00:03:50.744 [Warn] [Request failed] | 
2020-11-01_00:03:50.744 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.744 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.781 [Info] [Got download command] | 
2020-11-01_00:03:50.781 [Warn] [Request failed] | 
2020-11-01_00:03:50.781 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.781 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.781 [Info] [Got download command] | 
2020-11-01_00:03:50.781 [Warn] [Request failed] | 
2020-11-01_00:03:50.781 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.781 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.781 [Info] [Got download command] | 
2020-11-01_00:03:50.781 [Warn] [Request failed] | 
2020-11-01_00:03:50.781 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.781 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.781 [Info] [Got download command] | 
2020-11-01_00:03:50.781 [Warn] [Request failed] | 
2020-11-01_00:03:50.781 [Debug] [Telling request actor to download] | 
2020-11-01_00:03:50.781 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:50.781 [Info] [Got download command] | 
2020-11-01_00:03:50.781 [Warn] [Request failed] | 
2020-11-01_00:03:50.781 [Warn] [Max number of attempts (6) reached, giving up] | 
2020-11-01_00:03:50.781 [Info] [Became idle] | 
2020-11-01_00:03:50.781 [Error] [Couldn't download] | EXCEPTION OCCURRED:System.Exception Couldn't download Boolean <.ctor>b__0(Download)    at ProveBug.RequestActor.<>c__DisplayClass0_0.<.ctor>b__0(Download update) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 141
   at lambda_method(Closure , Object , Func`2 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.UntypedActor.Receive(Object message)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:50.781 [Debug] [Actor for one request created] | 
2020-11-01_00:03:53.459 [Debug] [Got download command, creating request actor] | 
2020-11-01_00:03:53.481 [Error] [Actor name "RequestActor" is not unique!] | EXCEPTION OCCURRED:Akka.Actor.InvalidActorNameException Actor name "RequestActor" is not unique! Akka.Actor.Internal.IChildrenContainer Reserve(System.String)    at Akka.Actor.Internal.NormalChildrenContainer.Reserve(String name)
   at Akka.Actor.ActorCell.ReserveChild(String name)
   at Akka.Actor.ActorCell.MakeChild(Props props, String name, Boolean async, Boolean systemService)
   at Akka.Actor.ActorCell.ActorOf(Props props, String name)
   at ProveBug.DownloaderActor.CreateRequestActorWhichWillBeRestartedAfterFailure() in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 117
   at ProveBug.DownloaderActor.Working(Download downloadCommand, IActorRef actorWhichWantsDownloadResult) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 73
   at ProveBug.DownloaderActor.<>c__DisplayClass5_0.<Idle>b__1() in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 65
   at Akka.Actor.ReceiveActor.CreateNewHandler(Action configure)
   at Akka.Actor.ReceiveActor.Become(Action configure)
   at ProveBug.DownloaderActor.<Idle>b__5_0(Download downloadCommand) in C:\GIT\EQ\src\Server\Phone.Service.Tests\ExternalQueues\ProveBugTests.cs:line 65
   at lambda_method(Closure , Object , Action`1 )
   at Akka.Actor.ReceiveActor.ExecutePartialMessageHandler(Object message, PartialAction`1 partialAction)
   at Akka.Actor.ActorCell.<>c__DisplayClass114_0.<Akka.Actor.IUntypedActorContext.Become>b__0(Object m)
   at Akka.Actor.ActorBase.AroundReceive(Receive receive, Object message)
   at Akka.Actor.ActorCell.ReceiveMessage(Object message)
   at Akka.Actor.ActorCell.Invoke(Envelope envelope)
2020-11-01_00:03:53.526 [Info] [Became idle] |


Corresponding NLog configuration (to have logs output in test explorer):
<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off"
      internalLogFile="c:\temp\nlog-internal.log">

    <variable name="exceptionFormat" value="${onexception:EXCEPTION OCCURRED\:${exception:format=type,message,method,stacktrace,data:maxInnerExceptionLevel=5:innerFormat=shorttype,message,method,stacktrace,data}" />
    <variable name="layoutPrefix" value="${date:format=yyyy-MM-dd_HH\:mm\:ss.fff}" />
    <variable name="layoutSuffix" value="[${level}] [${message}] | ${exceptionFormat}" />

    <targets>
        <target name="memory" xsi:type="Memory" layout="${layoutPrefix} ${layoutSuffix}" />
    </targets>

    <rules>
        <logger name="*" minlevel="Trace" writeTo="memory" />
    </rules>
</nlog>
*/