Google-cloud-dotnet: Grpc.Core.RpcException: Status(StatusCode=Cancelled, Detail="Cancelled") in Spanner, UnobservedTaskException

[tomerpeled]

Hi,

We're getting a weird RpcException message on our servers from time to time:
Grpc.Core.RpcException: Status(StatusCode=Cancelled, Detail="Cancelled")

Also, there is no stacktrace, so we couldn't trace this one... :(

We are working with the Spanner ADO.Net to connect to our db.

What can cause this exception?

We saw that someone else complaint about it in tome grpc thread:
https://github.com/grpc/grpc/issues/9377

[jskeet]

No stack trace at all? Not even from where you catch the exception? That's very surprising. After the exception has been thrown, does the server recover for other requests, or does it fail permanently?

It doesn't sound like you're running into the same problem as the linked gRPC issue, as that results in an InvalidOperationException. I'd have to check the exact gRPC behavior in different scenarios around cancellation, e.g.

• Client cancels a request via a cancellation token but after it's complete
• Client cancels a request via a cancellation token and the server acknowledges the cancellation
• Server decides to cancel the request itself (sending back that status code)

If you could give more information about the kind of operations that you're running when the failure occurs, that would be helpful too - queries, inserts/updates, DDL, something else?

[tomerpeled]

Yes, we don't have any stacktrace.
The server recovers like there was no issue at all...

Before the exception occurs we our doing queries and updates, but all the operations works as expected...

[jskeet]

Just to check what you mean, are you suggesting that none of the operations have actually failed, you're just getting logs of an RpcException which is presumably then retried?

How are you seeing the RpcException - is it in the console output?

[tomerpeled]

Well, we register our app to the UnobservedTaskException via the TaskScheduler and we get the described error from there - with no stacktrace...

Notice, that it seems that even though we get those errors from the UnobservedTaskException event, non of them seems to influence our flows.

[jskeet]

Ah, interesting. I wonder whether it's something to do with the connectivity checker.

@jtattermusch does that sound feasible?

[jskeet]

Out of interest, do you have records of when you receive this exception? Is it at regular intervals on each server?

[tomerpeled]

Well I didn't find any regular interval pattern.

[jtattermusch]

@tomerpeled, just to clarify: you seeing the RpcException when you are invoking calls as a client (i.e. using Grpc.Core.Channel to invoke calls) or on a server (e.g. handling calls using Grpc.Core.Server)?

[jtattermusch]

Btw, if you're calls are using deadlines, you can either get DeadlineExceeded status or Cancelled status if the call times out (it is because both the server and the client see the same deadline and one of them terminates the call by cancelling it a little earlier than the counterpart - which then sees a cancelled call, because the call was indeed cancelled by the peer).

[tomerpeled]

Well, we are using both Spanner SDKs:
https://github.com/GoogleCloudPlatform/google-cloud-dotnet/tree/master/apis/Google.Cloud.Spanner.Data

https://github.com/GoogleCloudPlatform/google-cloud-dotnet/tree/master/apis/Google.Cloud.Spanner.V1

So I believe those use the Grpc.Core.Channel.

[jskeet]

What confuses me is why it's an unobserved exception - I'm not sure how we can find out which call was being made here. @jtattermusch is there anything within an RpcException which would identify the RPC being made?

[jtattermusch]

@tomerpeled on what platform / grpc version are you seeing this problem?
Can you provide a minimal snippet that reproduces the issue?

[tomerpeled]

We're using grpc 1.7.1 on Windows.
I'll try to arrange a snippet, but notice that we're just using the Google Spanner ADO .Net provider, which executes the grpcs commands.

[jskeet]

Hi @tomerpeled - any update on this? Are you still experiencing the issue? If so, have you tried updating to the latest release of Grpc.Core, which is now 1.11.0?

[tomerpeled]

Hi @jskeet, I just tried Grpc.Core 1.11.0 but the issue still occurs.
Sorry for the late response with the snippet, couldn't arrange it easily till now...

[jskeet]

@tomerpeled: Can I check whether you are now able to reproduce this with a small example?

[jskeet]

@tomerpeled: Ping? (Without some guidance on reproducing this, it's going to be hard to fix it.)

[tomerpeled]

Hi,
@jskeet I'm very sorry, again, for not supplying a snippet which reproduce this.
We still see those errors on our servers. Currently we are really under pressure with our project and we couldn't reproduce this with a simple example.
Can you please put this one on hold?

We'll try to reproduce it with a simple example in the near future.

Thanks and sorry again,
Tomer

[jskeet]

No problem at all - will just leave this open for now.

[jskeet]

I've looked at a lot of the Spanner code since May, and I'm wondering whether this is to do with a keep-alive request being cancelled. I'm assuming you're still seeing these errors - could you give any information about how often this is happening?

[jskeet]

I'm back to trying to work out what's going on here, but I've had no luck so far. I assume you're still seeing these exceptions - can you say what kind of frequency they're at? (Once per second, once per day, once per week?)

[tomerpeled]

We still see those errors. In the last day there were approx. 700 errors on one of our server machines.

[jskeet]

Thanks for the information. While obviously it's sad that you're still seeing them, I'm quite glad that it's frequent enough that we'll be able to tell when we have sorted it out!

[YanlongLi]

I got the same problem in my program. Everything is normal in server side bud the client throws exception Grpc.Core.RpcException: Status(StatusCode=Cancelled, Detail="Cancelled").
When I was trying to debug it and found that the problem could be caused by the assignment of a list variable.
In my program, I have a ResponseType with a list attribute, I initialize this attribute with value gotten from DB before returning the ResponseType. But if I remove the assignment or assign it with some static values, the client can get the correct response.

[jskeet]

@Yanlongli: Do you mean you're seeing this with a task returned to the client, or an unobserved task like the one to tomerpeled is seeing? It may be a very different problem. The more detail (and sample code to reproduce if possible) you can give the better.

[YanlongLi]

@jskeet My issue is solved.
Yes, The server returned a task to client, and the exception was happening in client side. The root cause for my case is that one field in some list values is null while it is not nullable according to the IDL (I use bond). The exception gone after I update the IDL.

It is weird that the server seems handled the request successfully but actually not, there are no messages or exceptions saying what was happening and client just got exception.

[jskeet]

@YanlongLi: It sounds like that's very different to the issue in this question - and if you're using Bond, that's probably outside the remit of this repository anyway. I suggest you follow up with the Bond team if you have any further questions.

[jskeet]

Hi @tomerpeled,

The latest version of Google.Cloud.Spanner.Data (2.0.0-beta05) contains an entirely new session pool implementation, as well as updated references to Grpc.Core etc.
There are some breaking changes (as described at https://googleapis.github.io/google-cloud-dotnet/docs/Google.Cloud.Spanner.Data/migration-to-2.html) - but if you could try your code against the new package, that would be great. I'm hoping these exceptions will go away - and if they don't, I'm at least in a better position to investigate (with more understanding of which background tasks are doing what).

[tomerpeled]

Hi @jskeet,

Sounds good!
We will check this ASAP.

I'll let you know the results.
Thanks!

[tomerpeled]

Hi @jskeet,

We've upgraded the lib to 2.0.0-beta05. Unfortunately, the exceptions are still thrown.
Any additional info to look on?

Thanks!

[jskeet]

@tomerpeled: Rats - that's a pity. I've still never seen it, but as it's a background task, I probably wouldn't. It's particularly odd that all your Spanner operations are succeeding.

Could you give a bit more information about what your app is doing? If you have some tasks that only do reads and some that only do writes, it would be particularly interesting to know whether they both see the problem. Likewise, do you have a lot of Spanner code, or are all your requests funneled through a small number of pieces of code in your app?

I'll poke at this a bit more today. If you have any further ideas (knowing your app) that could help us to reproduce this, they'd be much appreciated - this is a really tricky one to get to the bottom of.

[jskeet]

Progress! Adding an unobserved task exception handler in my integration tests, I've now seen this a few times.

Admittedly it will now be somewhat tricky to pin down where it's coming from, but this is definitely progress. Will work on this further today - now that I can reproduce it (even if it's occasional) I should be able to fix it or pass details onto the gRPC team if it turns out to be a problem there. Thanks for your patience on this.

[tomerpeled]

Cool!

Curious to hear about your findings, when you'll have those.

[jskeet]

Just to update the thread: I'm still trying to work out how to reproduce this more reliably. It's frustrating, but I'll get there, I'm sure...

[jskeet]

Good news! I've managed to reproduce it! It can be demonstrated with ExecuteScalar, although I suspect that anything that opens a results stream and starts but then doesn't finish reading it will exhibit the problem.

Sample code:

using Google.Cloud.Spanner.Common.V1;
using Google.Cloud.Spanner.Data;
using System;
using System.Threading;
using System.Threading.Tasks;

class Program
{
    static void Main(string[] args)
    {
        TaskScheduler.UnobservedTaskException += (sender, e) => Console.WriteLine(e.Exception);

        var builder = new SpannerConnectionStringBuilder
        {
            DatabaseName = new DatabaseName("YOUR_PROJECT_ID", "YOUR_INSTANCE_ID", "YOUR_DATABASE_ID")
        };

        for (int i = 0; i < 1000; i++)
        {
            Console.WriteLine($"Starting iteration {i}");
            using (var connection = new SpannerConnection(builder))
            {
                using (var cmd = connection.CreateSelectCommand($"SELECT 1"))
                {
                    cmd.ExecuteScalar();
                }
            }
            Thread.Sleep(1000);
            GC.Collect();
        }
    }
}

Now I need to work out where the actual bug is :)

[jskeet]

Right, it looks like this really is a gRPC bug - I've seen it in Bigtable as well, and I can reproduce it without using any of the Google.Cloud.Spanner.Data code.
I've filed this issue with the gRPC team.

@tomerpeled are you happy to subscribe to that issue, and we'll close this one? Or would you prefer to keep this one open?

[tomerpeled]

Good investigation!

Sure, I'll subscribe that issue and close this one.
BTW, do you think it has any affect?

Thanks for your help!

[jskeet]

I honestly don't know if it has any other effect, I'm afraid :(

[burikus]

I encountered that issue with rpc that returns Empty - so if return null from server method - get that Exception (that doesn't affect server), if return "empty" --> Empty empty = new Empty(); then no Exceptions.

[jskeet]

@burikus: I'm afraid I don't follow that. If you're still running into problems, please file a new issue with details.

[nvdung0616]

Hello,
Warning from Microsoft:
[09/03/2019]
ASP.NET Core gRPC is not currently supported on Azure App Service or IIS. The HTTP/2 implementation of Http.Sys does not support HTTP response trailing headers which gRPC relies on. For more information, see this GitHub issue.

[jskeet]

@nvdung0616: Did that link to this issue? That would be very strange. It's not clear what you're expecting in response to that comment, but please file a new issue with more details.