Unable to avoid unhealthy backend / 502s on rolling deployments

[rocketraman]

I have a GCE ingress in front of an HPA-managed deployment (at this time, with a single replica).

On a rolling deployment, I sometimes run into the backend being marked as unhealthy and resulting 502 errors, usually for about 15-20 seconds.

According to the pod events, the neg-readiness-reflector appears to mark cloud.google.com/load-balancer-neg-ready to True for the pod before it is actually ready:

Normal   LoadBalancerNegNotReady            18m                neg-readiness-reflector                Waiting for pod to become healthy in at least one of the NEG(s): [k8s1-600f13cf-default-my-svc-8080-f82bf741]
Normal   LoadBalancerNegWithoutHealthCheck  16m                neg-readiness-reflector                Pod is in NEG "Key{\"k8s1-600f13cf-default-my-svc-8080-f82bf741\", zone: \"europe-west1-c\"}". NEG is not attached to any Backend Service with health checking. Marking condition "cloud.google.com/load-balancer-neg-ready" to True.
Warning  Unhealthy                          16m                kubelet                                Readiness probe failed: Get "http://10.129.128.130:8080/healthz": dial tcp 10.129.128.130:8080: connect: connection refused

While in this state, the previous pod terminates, but the load balancer does not route requests to the new pod, resulting in 502s.

I do have the deployment strategy set that should not allow this but I guess the neg being set to Ready is subverting this:

  strategy:
    rollingUpdate:
      maxSurge: 1
      maxUnavailable: 0

My deployment does also define a readiness probe as can be seen in the events above.

I do also have a health check configuration defined for the backend:

apiVersion: v1
kind: Service
metadata:
  name: my-svc
  labels:
    app.kubernetes.io/name: mysvc
  annotations:
    cloud.google.com/backend-config: '{"ports": {"8080":"my-backendconfig"}}'
    cloud.google.com/neg: '{"ingress": true}'
spec:
  type: ClusterIP
  selector:
    app.kubernetes.io/name: mysvc
  ports:
    - port: 8080
      protocol: TCP
      targetPort: 8080
---
apiVersion: cloud.google.com/v1
kind: BackendConfig
metadata:
  name: my-backendconfig
spec:
  timeoutSec: 45
  connectionDraining:
    drainingTimeoutSec: 0
  healthCheck:
    checkIntervalSec: 5
    timeoutSec: 5
    healthyThreshold: 1
    unhealthyThreshold: 2
    type: HTTP
    requestPath: /healthz
    port: 8080

I found this stackoverflow in which the user works around the issue with delaying the pod stop with a sleep on the lifecycle.preStop, but that seems more like a hack than a proper solution to this issue: https://stackoverflow.com/questions/71127572/neg-is-not-attached-to-any-backendservice-with-health-checking.

[rocketraman]

May also be related to #1656.

[rocketraman]

The NEG is not attached to any Backend Service with health checking message seems to be a red herring. The problem happens on every update, and I haven't seen that message again.

  Normal   Started                  7m49s                  kubelet                                Started container my-server
  Warning  Unhealthy                7m34s (x3 over 7m44s)  kubelet                                Readiness probe failed: Get "http://10.129.128.66:8080/healthz": dial tcp 10.129.128.66:8080: connect: connection refused
  Normal   LoadBalancerNegReady     7m31s                  neg-readiness-reflector                Pod has become Healthy in NEG "Key{\"k8s1-600f13cf-default-my-svc-8080-f82bf741\", zone: \"europe-west1-b\"}" attached to BackendService "Key{\"k8s1-600f13cf-default-my-svc-8080-f82bf741\"}". Marking condition "cloud.google.com/load-balancer-neg-ready" to True. 

As soon as the LoadBalancerNegReady event occurred, the 502s started happening, and kept happening (intermittently) for about 15-20 seconds.

[swetharepakula]

/kind support

A clarification question. Are you seeing that the requests are going to the pod that has been deleted when you get 502s or are seeing that the requests are going to the new pod?

I am wondering if the issue you are facing is that the old pod on termination has not been removed from the NEG yet, so there is a latency between the pod being removed in Kubernetes and the pod being removed from the NEG.

[rocketraman]

A clarification question. Are you seeing that the requests are going to the pod that has been deleted when you get 502s or are seeing that the requests are going to the new pod?

I am wondering if the issue you are facing is that the old pod on termination has not been removed from the NEG yet, so there is a latency between the pod being removed in Kubernetes and the pod being removed from the NEG.

I can see that the 502 responses are interspersed with valid responses from the new pod, so I think you are right -- the load balancer 502 errors are because the load balancer is still sending requests to the pod that has terminated in k8s.

I thought the issue was with my setting of unhealthyThreshold: 10 on the health check, overriding the default of 2 causing the system to take too long to detect the terminated pod is unhealthy, but that wasn't the case. I've reset all configurations to what I believe are the defaults and still the 502s are unavoidable on a deployment update.

[rocketraman]

Forcing the stopping container to stick around for a few extra seconds via lifecycle.preStop hook that sleeps for 30 seconds seems to be the only valid workaround I've found so far. This does also confirm the problem is with requests being sent to the terminating pod, not the new pod.

[rocketraman]

Even lifecycle.preStop does not appear to be a 100% consistent workaround -- today during a deployment I saw two 502 errors while pinging the endpoint every 2s, even though the old pod was still in "Terminating" state due to lifecycle.preStop.

The new pod did have the error message I originally mentioned above:

  Normal   LoadBalancerNegWithoutHealthCheck  2m14s                  neg-readiness-reflector                Pod is in NEG "Key{\"k8s1-600f13cf-default-my-svc-8080-f82bf741\", zone: \"europe-west1-b\"}". NEG is not attached to any Backend
Service with health checking. Marking condition "cloud.google.com/load-balancer-neg-ready" to True.

in which the "cloud.google.com/load-balancer-neg-ready" condition appears to be marked True before it should be.

So, to summarize, it seems there are actually two problems contributing to 502 errors during rolling deployments:

1. The load balancer is hitting the old pod even though it is being shut down (using lifecycle.preStop does seem to workaround this issue). This is consistent and easily reproduced.
2. The load balancer is hitting the new pod even though it is not ready yet due to the "NEG is not attached to any Backend Service with health checking." error. This is intermittent and more difficult to reproduce, but not uncommon.

[swetharepakula]

@rocketraman, as this pod changes are occurring, are there any node or zone changes that are occurring?

[rocketraman]

@swetharepakula Yes, this cluster is an autopilot cluster. When I deploy this update, the deployment generally requires a new node to be created to host the new pod.

[rocketraman]

In addition, usually a few minutes later the pod is migrated back to the original node, and the new node is shutdown. That process rarely completes without some 502s as well.

[swetharepakula]

@rocketraman, is that node being created in a new zone? Is the autopilot cluster a regional cluster?

[rocketraman]

is that node being created in a new zone? Is the autopilot cluster a regional cluster?

@swetharepakula I haven't checked specifically on the zone of the new node. It is a regional cluster (my understanding is that all autopilot clusters are regional clusters), so I presume autopilot is indeed balancing the new node across zones.

[rocketraman]

Yes, I just confirmed the new node is in a different zone than the existing node that hosts that pod.

[swetharepakula]

So I believe the following is what is happening:

1. The load balancer is hitting the old pod even though it is being shut down (using lifecycle.preStop does seem to workaround this issue). This is consistent and easily reproduced.

Neg controller does immediately respond to endpoint changes. However, there can be latency due to the time it takes for a detach operation to complete. In the time it takes the detach operation to complete, the load balancer may still route traffic to the terminating pod. There are a few options to mitigate this:

1. The lifecycle.preStop as you are already using.
2. use terminationGracePeriodSeconds so that your application will continue to accept traffic for a little longer.
3. Adjust health checks to be sensitive enough to recognize that the endpoint is gone. This option will only reduce the frequency of 502s but won't necessarily eliminate them.

Since you are already doing (1), that is probably the easiest approach.

2.The load balancer is hitting the new pod even though it is not ready yet due to the "NEG is not attached to any Backend Service with health checking." error. This is intermittent and more difficult to reproduce, but not uncommon.

This is a race between the Ingress controller and a workload being scheduled/started on a new node. The NEG controller sees the update before the Ingress controller and adds the endpoint. However if this is on a node in a new zone, the NEG controller creates a new NEG in the new zone. The Ingress controller then needs to attach that NEG to the backend service. However if the Ingress controller doesn't finish that before the workloads are scheduled on the node, those new pods will have their readiness gates switched to ready immediately since the NEG will not be in any BackendService.

For non auto-pilot clusters our recommendation is to reduce the number of zone changes and try to run workloads in every zone the cluster is in. Since this is an autopilot cluster, your options may be limited in this regard.

At this time we are still looking into how to make the experience better for both of these cases.

[rocketraman]

• use terminationGracePeriodSeconds so that your application will continue to accept traffic for a little longer.

FYI I actually don't think this works -- at least it didn't when I tried it. I actually wouldn't expect it to: terminationGracePeriodSeconds tells k8s that if the workload takes longer to stop, to give it that extra time before forcefully terminating the pod. Changing the value to a larger value doesn't actually delay termination if the pod exits quickly on its own, which is what we want in this case. I believe the GKE docs on this are incorrect, and should recommend the lifecycle.preStop solution instead (with a corresponding increase in terminationGracePeriodSeconds if the default isn't high enough to deal with the normal shutdown plus preStop sleep time).

For non auto-pilot clusters our recommendation is to reduce the number of zone changes and try to run workloads in every zone the cluster is in. Since this is an autopilot cluster, your options may be limited in this regard.

That is too bad, but it does suggest a work-around. Scale up the deployment so that there is at least one pod per zone. That does raise system cost significantly when only one pod is required to meet load/redundancy requirements.

Will this become the tracking issue for improving this behavior, or can you reference me the issue I should follow?