Service-fabric: Deleting service or primary replica move causes service to get stuck in RunAsync

[juho-hanhimaki]

Service Fabric Runtime Version: 7.1.458.9590

Environment: Dev

Description:
I am puzzled by this issue. I have created a new stateful service from the .NET Core stateful service template and minimally modified the RunAsync method.

Debugging this service locally I delete the service instance via the SF explorer and sometimes (maybe 1 in 3 attempts) the service gets stuck deleting. I have set a breakpoint like shown in the above screenshot and sometimes it is not hit at all. The Stateful1.exe process just keeps running and also the local cluster manager shows the service stuck in RunAsyncSlowCancellation.

In the debug log this keeps repeating indefinitely:

Tasks debug panel:

It seems to me like the program is stuck in loop somewhere inside AddOrUpdateAsync since if I break in VS manually I cannot step the code at all in VS.

As I understand this should not be happening, but I can reproduce this consistently.

I am fairly sure have observed this same behavior in Azure Cluster (but don't have the luxury of time to spin up a new cluster to test this again).

Observed behavior:
The stateful service is stuck in RunAsync.

Expected Behavior:
The stateful service is not stuck. 🤣

OS(Windows/Linux): Windows

---

Assignees: /cc @microsoft/service-fabric-triage

[jackbond]

@juho-hanhimaki If you haven't created an issue here before, let me clue you in on how this is going to go down. You're going to be ignored for weeks. At which point, I'd recommend you start dropping some F bombs, combined with some tweets at https://twitter.com/scottgu. Be sure to include #ServiceFabric

Someone MIGHT come along sooner and promise the team is working on being more responsive. That's if you're lucky. It's equally likely you'll get a "FO, file a service ticket" response (although in politer terms.)

[juho-hanhimaki]

Let's hope you're not right, even though previous experiences might not have been optimal! I like to stay hopeful.

Surely it must be SF team goal to keep the product improving and moving forward.

[zuhairp]

Can you try passing the CancellationToken to the call to myDictionary.AddOrUpdateAsync?

How does the CPU, Memory, and Disk performance look like while the code is running?

[jackbond]

It's always best practice to pass the CancellationToken, but according to the documentation...

https://docs.microsoft.com/en-us/dotnet/api/microsoft.servicefabric.data.collections.ireliabledictionary-2.addorupdateasync?view=azure-dotnet

the default timeout is 4 seconds, so that shouldn't hang the delete indefinitely. Also, the logs are showing FabricNotPrimary exceptions, so that seems more like the CommitAsync is failing, as opposed to AddOrUpdateAsync blocking. Out of curiosity, why doesn't CommitAsync take a CancellationToken as an argument?

[zuhairp]

FabricNotPrimary will come from AddOrUpdateAsync. The four second timeout will help with "deadlock"-esque scenarios, but these seems slightly like a "livelock"-esque scenario, where the AddOrUpdateAsync keeps retrying. It seems like the ThrowIfCancellationRequested is not working correctly.

why doesn't CommitAsync take a CancellationToken as an argument?

This is because we prioritize strong consistency, and once CommitAsync has begun we want to ensure that it's properly completed so that the replica set isn't left in an inconsistent state.

[jackbond]

@zuhairp Always wondered about that. Thanks for the info.

[juho-hanhimaki]

I just tried passing the CancellationToken to the AddOrUpdateAsync and it made no difference.

I don't think system resources are the limiting factor in this case because my dev box is quite the monster. Screenshot of task manager from service startup to the delete command from SF explorer (which got stuck).

Maybe someone can try to reproduce on their system?

The program is the default .NET Core 3.1 stateful service with no modifications other than the RunAsync and DoWork function supplied below. The cluster version was still 7.1.458.9590 with 1-node local configuration.

        protected override async Task RunAsync(CancellationToken cancellationToken)
        {
            try
            {
                var tasks = Enumerable.Range(0, 10).Select(i => DoWork(i, cancellationToken));
                await Task.WhenAll(tasks);
            }
            catch (Exception)
            {
                throw;
            }
        }

        async Task DoWork(int i, CancellationToken cancellationToken)
        {
            var myDictionary = await this.StateManager.GetOrAddAsync<IReliableDictionary<string, long>>("myDictionary");
            while (true)
            {
                cancellationToken.ThrowIfCancellationRequested();

                using (var tx = this.StateManager.CreateTransaction())
                {
                    await myDictionary.AddOrUpdateAsync(tx, $"Counter{i}", 0, (key, value) => ++value);
                    await tx.CommitAsync();
                }
            }
        }

[juho-hanhimaki]

It seems like the ThrowIfCancellationRequested is not working correctly.

In that case I would expect to be able to hit a breakpoint inside the loop while the service is stuck deleting. However that is not the case. Before the delete command I can hit breakpoints inside the loop just fine.

[LeroyK]

I'm able to reproduce this on my dev machine with 7.1.458.9590 and a 5-node local cluster. I wonder if this also affects primary partition moves.

[LeroyK]

If you add some logging, you can see that it hangs on AddOrUpdateAsync. The last log entry will be "Before AddOrUpdateAsync ...".

I also just got a System.ExecutionEngineException while testing this with .NET Core 3.1.

System.ExecutionEngineException
  HResult=0x80131506
  Message=Exception of type 'System.ExecutionEngineException' was thrown.

Code:
```c#
async Task DoWork(int i, CancellationToken cancellationToken)
{
var myDictionary = await StateManager.GetOrAddAsync>("myDictionary");
while (true)
{
ServiceEventSource.Current.Message($"Before ThrowIfCancellationRequested {i}: {cancellationToken.IsCancellationRequested}");
cancellationToken.ThrowIfCancellationRequested();
ServiceEventSource.Current.Message($"After ThrowIfCancellationRequested {i}: {cancellationToken.IsCancellationRequested}");

    using (var tx = StateManager.CreateTransaction())
    {
        ServiceEventSource.Current.Message($"Before AddOrUpdateAsync {i}: {cancellationToken.IsCancellationRequested}");
        await myDictionary.AddOrUpdateAsync(tx, $"Counter{i}", 0, (key, value) => ++value, TimeSpan.FromSeconds(4), cancellationToken);
        ServiceEventSource.Current.Message($"After AddOrUpdateAsync {i}: {cancellationToken.IsCancellationRequested}");
        await tx.CommitAsync();
        ServiceEventSource.Current.Message($"After CommitAsync {i}: {cancellationToken.IsCancellationRequested}");
    }
}

}
```

[tuhland]

This looks very similar to an issue we seem to have (5 node cluster and .NET Core 3.1 as well).

Sometimes our actors seem to get stuck when working with the state, this usually happens in combination with partition moves, slow shutdown warnings and sometimes escalates to node shutdowns. I couldn't yet figure out which of these comes first.

We also sometimes (every other day) have cancelled actor requests in the SF operational logs, which are usually methods that just read from or update something in the state.

[LeroyK]

Moving primary partitions indeed also has similar issues of replicas getting stuck. Fixing these should have high priority, because this breaks running services.

I used the PowerShell command Restart-ServiceFabricReplica -ServiceName fabric:/SFStuckTest1/Stateful1 -ReplicaKindPrimary several times, after waiting for each primary move to complete. The SF app was configured with a single partition and a min/target replica set size of 3.

One of the active secondary replicas eventually got stuck (which was probably the previous primary replica):

'System.RAP' reported Warning for property 'IStatefulServiceReplica.CloseDuration'.
The api IStatefulServiceReplica.Close on node _Node_1 is stuck. Start Time (UTC): 2020-11-20 12:51:08.149.

This ETW event keeps repeating:

{
  "Timestamp": "2020-11-20T13:56:51.4006926+01:00",
  "ProviderName": "Microsoft-ServiceFabric",
  "Id": 54422,
  "Message": "EventName: PartitionNewHealthReport Category: Health EventInstanceId: b0006046-13b5-46f9-b171-11b6e0a81b47 PartitionId: aafe3c73-fd31-4fcb-9bcf-e8ac47bb7654 SourceId=RunAsync Property=RunAsyncSlowCancellation HealthState=Warning TTL=300000 SequenceNumber=132503505983568697 Description='RunAsync is taking longer than expected time (15s) to cancel.' RemoveWhenExpired=True SourceUTCTimestamp=11/20/2020 13:56:38 ",
  "ProcessId": 4728,
  "Level": "Informational",
  "Keywords": "0x4000000000000001",
  "EventName": "HM",
  "ActivityID": null,
  "RelatedActivityID": null,
  "Payload": {
    "eventName": "PartitionNewHealthReport",
    "category": "Health",
    "eventInstanceId": "\"b0006046-13b5-46f9-b171-11b6e0a81b47\"",
    "partitionId": "\"aafe3c73-fd31-4fcb-9bcf-e8ac47bb7654\"",
    "sourceId": "RunAsync",
    "property": "RunAsyncSlowCancellation",
    "healthState": 2,
    "TTLtimespan": 300000,
    "sequenceNumber": 132503505983568697,
    "description": "RunAsync is taking longer than expected time (15s) to cancel.",
    "removeWhenExpired": true,
    "sourceUtcTimestamp": "\"\/Date(1605876998356)\/\""
  }
}

[LeroyK]

Just upgraded to 7.2.434.9590 and the issue is still present.

[LeroyK]

What's the status of this now? Is anyone on the SF team working on fixing this issue? Please keep us informed, as this is quite critical.

[LeroyK]

I ran some more tests on 7.2.434.9590. It seems to hang on CommitAsync(). This might have been the case too for 7.1.458.9590. Currently I have seen the following states after cancellation was requested for RunAsync().

0: Finished TransactionFaultedException: Operation canceled.
1: Finished TransactionFaultedException: Operation canceled.
2: Finished TransactionFaultedException: Operation canceled.
3: Finished TransactionFaultedException: Operation canceled.
4: Finished TransactionFaultedException: Operation canceled.
5: Before CommitAsync
6: Finished TransactionFaultedException: Operation canceled.
7: Finished TransactionFaultedException: Operation canceled.
8: Finished TransactionFaultedException: Operation canceled.
9: Finished TransactionFaultedException: Operation canceled.

In another run:

0: Before CommitAsync
1: Finished FabricNotPrimaryException: 
2: Before CommitAsync
3: Before CommitAsync
4: Finished FabricNotPrimaryException: 
5: Before CommitAsync
6: Finished FabricNotPrimaryException: 
7: Before CommitAsync
8: Before CommitAsync
9: Before CommitAsync

The code I used for testing stores the last message for each Task and logs that value every 5 seconds.
```c#
using Microsoft.ServiceFabric.Data.Collections;
using Microsoft.ServiceFabric.Services.Runtime;
using System;
using System.Collections.Concurrent;
using System.Fabric;
using System.Linq;
using System.Text;
using System.Threading;
using System.Threading.Tasks;

namespace Stateful1
{
internal sealed class Stateful1 : StatefulService
{
public Stateful1(StatefulServiceContext context)
: base(context)
{ }

    protected override async Task RunAsync(CancellationToken cancellationToken)
    {
        _ = Task.Run(() => LogLastMessagesAsync());

        try
        {
            cancellationToken.Register(() => ServiceEventSource.Current.Message("Cancellation requested"), false);

            var tasks = Enumerable.Range(0, 10).Select(i => Task.Run(() => DoWork(i, cancellationToken)));
            await Task.WhenAll(tasks).ConfigureAwait(false);
        }
        catch (Exception)
        {
            if (!cancellationToken.IsCancellationRequested)
                throw;
        }
    }

    private readonly ConcurrentDictionary<int, MessageHolder> s_lastMessages = new ConcurrentDictionary<int, MessageHolder>();

    private sealed class MessageHolder
    {
        public volatile string Message;
    }

    public async Task LogLastMessagesAsync()
    {
        var builder = new StringBuilder();

        while (true)
        {
            await Task.Delay(TimeSpan.FromSeconds(5)).ConfigureAwait(false);

            builder.Clear();

            foreach (var (i, lastMessage) in s_lastMessages.ToArray().OrderBy(x => x.Key))
                builder.AppendLine($"{i}: {lastMessage.Message}");

            if (builder.Length > Environment.NewLine.Length)
                builder.Length -= Environment.NewLine.Length;

            ServiceEventSource.Current.Message(builder.ToString());
        }
    }

    async Task DoWork(int i, CancellationToken cancellationToken)
    {
        var myDictionary = await StateManager.GetOrAddAsync<IReliableDictionary<string, long>>("myDictionary").ConfigureAwait(false);

        var lastMessageHolder = s_lastMessages.GetOrAdd(i, _ => new MessageHolder());

        try
        {
            while (true)
            {
                Interlocked.Exchange(ref lastMessageHolder.Message, "Before ThrowIfCancellationRequested");
                cancellationToken.ThrowIfCancellationRequested();

                Interlocked.Exchange(ref lastMessageHolder.Message, "Before CreateTransaction");
                using (var tx = StateManager.CreateTransaction())
                {
                    Interlocked.Exchange(ref lastMessageHolder.Message, "Before AddOrUpdateAsync");
                    await myDictionary.AddOrUpdateAsync(tx, $"Counter{i}", 0, (key, value) => ++value, TimeSpan.FromSeconds(4), cancellationToken).ConfigureAwait(false);

                    Interlocked.Exchange(ref lastMessageHolder.Message, "Before CommitAsync");
                    await tx.CommitAsync().ConfigureAwait(false);

                    Interlocked.Exchange(ref lastMessageHolder.Message, "After CommitAsync");
                }
            }
        }
        catch (Exception ex)
        {
            Interlocked.Exchange(ref lastMessageHolder.Message, $"Finished {ex.GetType().Name}: {ex.Message}");
        }
    }
}

}
```
Maybe the title of the issue should be changed as well, since it also affects primary partition moves.

[vinay-y]

Hey @LeroyK. Looks like AddOrUpdateAsync is not getting stuck anymore after you pass in the cancellation token. Only CommitAsync() seems to be getting stuck. Which version of SF SDK are you using?

We can look into the traces to understand what's going on. You should typically find them for the dev cluster in C:SfDevClusterLogTraces. Can you please share those along with the partition id that gets created?

[LeroyK]

@vinay-y SDK version 4.2.434, but this issue also occurs with SDK version 4.1.458.

To avoid going back and forth with traces, it's probably better if someone from the SF team runs the code and collect everything they need from their dev cluster. It's pretty easy to reproduce (like I did from code provided by the OP @juho-hanhimaki).

[vinay-y]

Thanks. We will try to reproduce and get back to you.

[vinay-y]

Thanks for getting this to our attention. We were able to reproduce the issue during primary failover in some runs. Replicator team is investigating it.

[tmgalorath]

Thank you for bringing all of this information to our attention. This is a known issue but the details you have shared helped us. We are working on a fix for this and we will update you when it is ready for release. In the meantime you can use this workaround in your application. The workaround is to set a timeout for any CommitAsync call in RunAsync method. (Note this is only required for RunAsync method)

Example:

```c#
Task commitTask = tx.CommitAsync();

if (await Task.WhenAny(commitTask, Task.Delay(10000)) != commitTask)
{
cancellationToken.ThrowIfCancellationRequested();
}
```

[juho-hanhimaki]

Great to hear! The provided workaround seems to fix the issue.

[LeroyK]

@tmgalorath I'm quite surprised this is a known issue and that it takes the SF team 50 days to acknowledge this. Users are spending time on trying to figure out why their services hang, thinking it might be caused by their own code. If the Service Fabric team would be more transparent about known issues, it could prevent its users from wasting their time. Even in the release notes of 7.2CU2 no known issues are listed.

I also have a few questions/concerns about the proposed workaround:

1. If CommitAsync takes longer than 10 seconds, it could still complete after the calling method has returned. This will break consistency.
2. If CommitAsync is called in a request via one of the service listeners (e.g. ASP.NET Core Web API), it could block there as well, causing CloseAsync / Abort on the listener to hang.
3. When running with ServicePackageActivationMode="SharedProcess", what is the effect on the StateManager when Primary replicas are switched to ActiveSecondary / IdleSecondary, with "ignored" deadlocked CommitAsync calls?
4. When running with ServicePackageActivationMode="SharedProcess", won't this workaround consume resources such as threads, handles or memory?

[tmgalorath]

@LeroyK , we understand your concern and apologize for any inconvenience the delay might have caused you. We receive feedback, questions, suggestions and issues from multiple users, customers and partners on multiple channels and forums. We try to triage these with equal priority and diligence and route them to the appropriate team for a prompt response. Depending on the number of requests we receive, occasionally there is a delay in our triage/response time. We do appreciate your feedback and we will endeavor to do better.

1.) While this may be a rare situation for commit to take longer than 10 seconds without the Cancellation Token being requested, I agree that the response I provided should have handled this case. Here is an updated example that shows how we can ensure that the commit is finished before moving on.
``` c#
while (true) {
Task commitTask = tx.CommitAsync();

if (await Task.WhenAny(commitTask, Task.Delay(10000)) == commitTask){
    break;
} else {
    cancellationToken.ThrowIfCancellationRequested();
}

}
```

2.) This bug is only specific to the RunAsync method

3.) This is a generic case. You can change role at any time. In this case the transaction will be aborted and there won’t be deadlock.

4.) I don't see any resource issues with this pattern. If you find otherwise let us know.

[jackbond]

What I fail to understand is this... We're told that Service Fabric is the foundation of core Azure services like Cosmos and SQL. How exactly is a bug as COMPLETELY NOT EDGE CASE as this, not been found internally?

It seems like Azure has maybe a dozen people working on Service Fabric. If there isn't MAJOR new functionality in version 8, it's looking more and more like Service Fabric is a completely dead product.

[LeroyK]

@LeroyK , we understand your concern and apologize for any inconvenience the delay might have caused you. We receive feedback, questions, suggestions and issues from multiple users, customers and partners on multiple channels and forums. We try to triage these with equal priority and diligence and route them to the appropriate team for a prompt response. Depending on the number of requests we receive, occasionally there is a delay in our triage/response time. We do appreciate your feedback and we will endeavor to do better.

1.) While this may be a rare situation for commit to take longer than 10 seconds without the Cancellation Token being requested, I agree that the response I provided should have handled this case. Here is an updated example that shows how we can ensure that the commit is finished before moving on.

while (true) {
    Task commitTask = tx.CommitAsync();

    if (await Task.WhenAny(commitTask, Task.Delay(10000)) == commitTask){
        break;
    } else {
        cancellationToken.ThrowIfCancellationRequested();
    }
}

2.) This bug is only specific to the RunAsync method

3.) This is a generic case. You can change role at any time. In this case the transaction will be aborted and there won’t be deadlock.

4.) I don't see any resource issues with this pattern. If you find otherwise let us know.

I don't think there is a way to work around this without breaking consistency. This latest workaround will call CommitAsync() in each iteration, and the second call will likely throw because the transaction state is incorrect. The initial CommitAsync call however will still keep running / blocking.

The issue really needs to be fixed in SF. I would expect a deadlock issue such as this to have the highest priority, but I get the feeling there has not been any progress at all. Is there any update on this?

[LeroyK]

Another month has gone by without any update. Can you please update us on when this is expected to get fixed?

[juho-hanhimaki]

Any updates on the issue?