Google-cloud-dotnet: Create a pubsub integration test to repeatedly start and stop a subscriber

[chrisdunelm]

There are reports of issues shutting down the subscriber.

[fromm1990]

I have experienced this issue, however only on a single cored machine ( 1 cored GKE node and 1 cored GAE) and i am not sure if that has anything to do with the bug so far. I will try investigate this assumption further.

[chrisdunelm]

@fromm1990 thanks for the information. Being on a single-core machine should not cause any change in behaviour; the subscriber should still shutdown properly.

[fromm1990]

@chrisdunelm I have this issue where it hangs and does not continue, however, this only happens when i test it on a GKE pod.

Here is a picture where the application is run locally using the docker-compose run pubsubstabilitytest command.

This works as intended where the application shuts down gracefully.

Running the same environment on a GKE pod resolves in problems though. The following picture shows how it hangs at the PubSubStabilityTest-e60c8573-c367-414a-b19b-5342bdddac96 subscription is stopping... state.

I have attached the solution for reproducing the issue.

PubSubStabilityTest.zip

P.S. I made a controller, that makes a graceful shutdown of the application. The controller works flawless locally and on GKE. The bug seems to occur only while scaling down the workload on GKE.

(The API is http://host:port/api/shutdown.)

[chrisdunelm]

@fromm1990 Thanks very much for the logs and code for reproduction. I won't be able to get to it this week, but next week I will see if I can reproduce the problem.

Does it fail every time on GKE pod shutdown? If not, do you approximately know what proportions of shutdowns result in the error?

[chrisdunelm]

And if you can easily re-run the local (successful) shutdown, but with timestamps in the log entries, that'd be useful. Thanks.

[fromm1990]

@chrisdunelm thanks for testing it out. As you can see, It hinders a unique subscription clean up on shutdown. This should be done, in my opinion, when auto scaling an application to avoid unused subscriptions floating around (will also increase the cost of Pub/Sub over time).

Yes, it fails consistently every time a GKE pod shuts down. I run the cluster with 1 replica of the application and then scales it down to 0 replicas. The cluster size is 3 nodes of type _n1-standard-1 (1 vCPU, 3.75 GB memory)_

Here you have the local re-run with timestamps.

[chrisdunelm]

I've just been speaking to some people who understand the Kubernetes pod shutdown process. Apparently a SIGTERM is sent to the process, and then by default the process is given 30 seconds to clean up and exit before a SIGKILL is sent. During that 30 seconds the pod is still fully enabled (except it won't receive any further traffic). It may be possible to "emulate" this shutdown on local Linux by sending SIGTERM by hand; although this certainly doesn't emulate the entire kubernetes/pod context.
How in C# are you catching the SIGTERM shutdown event?

Thanks for the timestamped log, and as I said, I'll see if I can repro this next week.

[fromm1990]

The SIGTERM signal should be handled by default since .NET Core 1.1 if i am correct? Also as you can see in the screenshot from Stackdriver logging, the shutdown process does get triggered by Kubernetes.

I also tried to extend the 30 second period to 10 minutes in the workload yaml file but without luck. The service, however, does shutdown before the 10 minutes, but without deleting the Pub/Sub subscription, indicating that an exception forced the process to terminate.

Do you know if it is both ingress and egress traffic that is blocked for the pod?

[chrisdunelm]

I've added an integration test that does a lot of stopping/starting of subscribers, but I have not seen any problems when running it many times.
I have only run it on a Windows desktop (full framework and core) though, so if the problem is much more related to Docker I will not have seen it. I'll experiment with Docker containers and Kubernetes shortly.

And as far as I know only ingress traffic is blocked; and it's not exactly blocked, it's just that the load-balancer will not send any further new connections to the pod.

[chrisdunelm]

I've reproduced this on GKE.

The call to StopAsync() when shutdown by a GKE pod shutdown throws the following exception:

System.InvalidOperationException: Shutdown has already been called
         at Grpc.Core.Internal.CompletionQueueSafeHandle.BeginOp()
         at Grpc.Core.Internal.CallSafeHandle.StartSendMessage(ISendCompletionCallback callback, Byte[] payload, WriteFlags writeFlags, Boolean sendEmptyInitialMetadata)
         at Grpc.Core.Internal.AsyncCallBase`2.SendMessageInternalAsync(TWrite msg, WriteFlags writeFlags)
         at Google.Api.Gax.Grpc.BufferedClientStreamWriter`1.Request.WriteTo(IClientStreamWriter`1 writer)
         at Google.Api.Gax.Grpc.BufferedClientStreamWriter`1.WriteAsyncImpl(T message, WriteOptions options, Boolean modifyOptions, Boolean throwOnError)
         at Google.Cloud.PubSub.V1.SubscriberClientImpl.SingleChannel.<Push>d__22.MoveNext()

So it looks like gRPC has already shutdown. I don't yet know why, I'll investigate.

[chrisdunelm]

This is because gRPC registers its own shutdown hook which closes all channels, as discussed in https://github.com/grpc/grpc/issues/14856

I'll see if there's a way to work around this, or whether we need to request a change to gRPC to support this.

[fromm1990]

Thanks for the effort you have put into reproducing this issue. I'm glad to see that the problem is now detected (at least fairly certain). I'm surprised that gRPC has flagged this as P2 and not P1 since it currently does not comply with ASP.NET Core life cycles.

Do you have an idea of when we can expect a fix? (we currently have to clean up subscriptions manually)

[chrisdunelm]

@fromm1990 I suspect the gRPC issue hasn't considered this in relation with the ASP.NET Core life-cycle. I'll chat with @jtattermusch and see how we can make progress on this. I'm not sure how long this will take, but I'll keep this issue updated.

[chrisdunelm]

This is definitely caused by the gRPC shutdown code. @jtattermusch and I have discussed it, and will work to get a fix done in gRPC as soon as possible. gRPC shutdown is moderately complex however, so this may take a week or two.
Unfortunately we don't know of a workaround to use in the meantime.

[chrisdunelm]

A gRPC fix is being reviewed now: https://github.com/grpc/grpc/pull/15975
If no unexpected problems occur, then we expect to have a new gRPC release, and a new pubsub release by early next week.

[chrisdunelm]

Version 1.13.1 of gRPC has just been released which should fix this problem.
I will test and prepare a new beta release of pubsub tomorrow.
(And it appears that somone has already tried it successfully: https://github.com/grpc/grpc/issues/14856#issuecomment-405378149 )

[chrisdunelm]

Grpc version 1.13.1 does fix the Kubernetes shutdown problem. I will release a new version of pubsub with this new dependency.

[chrisdunelm]

Google.Cloud.PubSub.V1 1.0.0-beta19 released which fixes the kubernetes shutdown issue.

[fromm1990]

Thanks @chrisdunelm for the effort you have put into solving this issue!