Switching on retries on timeout causes unexpected behavior

[avinash0161]

I am trying to use the retry mechanism of Orleans. I have the following code:

Start Silo, Client and Send Requests from client to a grain:

            var siloBuilder = new SiloHostBuilder()
                .UseLocalhostClustering()
                .UseDashboard(options => { })
                .Configure<ClusterOptions>(options =>
                {
                    options.ClusterId = "dev";
                    options.ServiceId = "Orleans2StatelessWorkers";
                })
                .Configure<EndpointOptions>(options =>
                    options.AdvertisedIPAddress = IPAddress.Loopback)
                .ConfigureLogging(logging => logging.AddConsole())
                .Configure<SiloMessagingOptions>(options => {options.ResponseTimeout = new TimeSpan(0,0,32); options.ResendOnTimeout = true; options.MaxResendCount = 60; });

            var host = siloBuilder.Build();
            await host.StartAsync();

            var clientBuilder = new ClientBuilder()
                .UseLocalhostClustering()
                .Configure<ClusterOptions>(options =>
                {
                    options.ClusterId = "dev";
                    options.ServiceId = "Orleans2StatelessWorkers";
                })
                .ConfigureLogging(logging => logging.AddConsole())
                .Configure<ClientMessagingOptions>(options => {options.ResponseTimeout = new TimeSpan(0,0,32); options.ResendOnTimeout = true; options.MaxResendCount = 60;});

            var client = clientBuilder.Build();
            await client.Connect();

            var hashGenerator = client.GetGrain<IHashGeneratorGrain>(0);

            while (true)
            {
                try{
                    Console.WriteLine("Client making a call");
                    await hashGenerator.TempCall();
                }
                catch (Exception ex) // to catch timeout exceptions
                {
                    Console.WriteLine("EXCEPTION: " + ex.Message);
                }      
            }

Grain class

    public class HashGeneratorGrain : Grain, IHashGeneratorGrain
    {
        public async Task TempCall()
        {
            await Task.Delay(33000);
            return;
        }
    }

What's expected:
Client has its timeout set to 32s. It makes a call to the grain and the call takes >33s to process. So, after 32s a timeout happens and TempCall() should again be invoked.

What happens:
The timeouts happen almost immediately (after 1-2s) and logs showing retries start to appear in quick succession (1-2 s gap between them). This behavior is observed if the ResendOnTimeout option is set to true and there is some Task.Delay statement in TempCall(). To confirm this, I even increased the options.ResponseTimeout for the client to more than 2 min and decreased the Task.Delay in TempCall() to 10s. Therefore, no timeout should ideally have occurred after this change. However, the same observation (immediate timeouts and retries) ensued.
This behavior is no more seen if I remove the options.ResendOnTimeout = true; options.MaxResendCount = 60; from the Client builder messaging options in the code above. The timeout happens after the set time, but of course there is no resending.
The above described behavior (client to grain communication) is also seen in grain to grain communication.

The entire project is uploaded here.

---

Credits Note: The code used above is a modified version of the code available here. I have removed the [Stateless Grain] tag from the grains to turn them into normal grains.

[sergeybykov]

I downloaded your code, set both timeouts to 32 seconds as in the above code (the code was different), added timing to printing, and everything seems to work as expected.

public async Task TempCall()
{
            Console.WriteLine($"TempCall received a call at {DateTime.Now}");
            await Task.Delay(33000);
            Console.WriteLine($"TempCall completed at {DateTime.Now}");
            return;
}

I see:

TempCall received a call at 1/2/2019 10:14:48 AM
warn: Orleans.Runtime.CallbackData[100157]
Response did not arrive on time in 00:30:00 for message: Request cli/026d679c@6b16939c->S127.0.0.1:30000:0grn/3CA3A49E/00000000 #14: . Target History is: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000:. About to break its promise.
TempCall completed at 1/2/2019 10:15:21 AM
TempCall received a call at 1/2/2019 10:15:21 AM

after a single iteration of the loop with the second call indeed getting in after the first one completes after the timeout warning.

That being said, we discourage usage of the retry functionality in messaging and regret we didn't remove it altogether in 2.0, as it easily leads to bad patterns and unexpected behavior and exacerbates failures.

[avinash0161]

That's strange. For me the retries start immediately. I changed the timeout of both to 32s and added a timer in Main() which prints the current time every 2s.

        private static void OnTimedEvent(Object source, ElapsedEventArgs e)
        {
            Console.WriteLine($"TIMER WENT OFF AT {DateTime.Now}");
        }

The logs are as follows after the timer expires once. It can be seen that TempCall() was called at 11:27:43 and timer went off at 11:27:45 and between these two 2 retries have happened :

TempCall received a call at 1/2/19 11:27:43 AM
warn: Orleans.Runtime.CallbackData[100157]
Response did not arrive on time in 00:00:32 for message: Request cli/f845c598@7902cda1->S127.0.0.1:30000:0grn/3CA3A49E/00000000 #17: . Target History is: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000:. About to break its promise.
info: Orleans.Runtime.SiloControl[0]
GetSimpleGrainStatistics
info: Orleans.Runtime.Management.ManagementGrain[0]
GetDetailedHosts onlyActive=True
warn: Orleans.Runtime.CallbackData[100157]
Response did not arrive on time in 00:00:32 for message: Request cli/f845c598@7902cda1->S127.0.0.1:30000:0grn/3CA3A49E/00000000 #17[ResendCount=1]: . Target History is: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000:. About to break its promise.
warn: Orleans.Runtime.CallbackData[100157]
Response did not arrive on time in 00:00:32 for message: Request cli/f845c598@7902cda1->S127.0.0.1:30000:0grn/3CA3A49E/00000000 #17[ResendCount=2]: . Target History is: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000: S127.0.0.1:30000:0:*grn/3CA3A49E/00000000:. About to break its promise.
info: Orleans.Runtime.SiloControl[0]
GetSimpleGrainStatistics
info: Orleans.Runtime.Management.ManagementGrain[0]
GetDetailedHosts onlyActive=True
TIMER WENT OFF AT 1/2/19 11:27:45 AM

Maybe I should put time statements in Orleans code to see what view of time does the runtime have?

I have uploaded the modified project in the same location in project named Orleans2StatelessWorkersWithTimer.

[sergeybykov]

Here's my version of your code - https://gist.github.com/sergeybykov/414ca33c4787f3e79d7c3a755848ab55 that works as I would except it.

[avinash0161]

@sergeybykov I copy-pasted the version you gave above and ran it on my machine (Ubuntu 18.04). It gave me the same issue as I had seen before. In order to verify, I ran it on two other Macbook Mojave machines and the issue is being reproduced. However, then I ran it on a Windows 10 machine and got the output that you mentioned above. It seems like the issue is dependent on the OS. I have created a Github project for easier sharing. https://github.com/avinash0161/OrleansExperiments.

I have also seen that retry behavior changes when we use Orleans 2.2.0 instead of 2.0.3. But we can stick with 2.0.3 for now, since we have been discussing in that context.

[sergeybykov]

I'm curious if somebody else can confirm this. Our development environment is still primarily Windows.

[sergeybykov]

We are looking to remove the general message retry logic soon - #5667.

[ReubenBond]

Support for resending messages has been removed