Skipper: Kubernetes: 5xxs when updating deployments.

[mikkeloscar]

I discussed this problem with @szuecs and I wanted to document an example of this issue which proves our hypothesis.

Consider this 500 from ingress skipper:

[APP]time=\"2018-05-25T14:59:56Z\" level=error msg=\"error during backend roundtrip: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_0: context canceled\"
[APP]time=\"2018-05-25T14:59:56Z\" level=error msg=\"Failed to do backend request to http://10.2.108.118:8080: proxy error with code 0, dialing failed false, unwrap: context canceled\"
[APP]time=\"2018-05-25T14:59:56Z\" level=error msg=\"error while proxying, route kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry__lb_group, status code 500: proxy error with code 0, dialing failed false, unwrap: context canceled\"
<client> - - [25/May/2018:14:59:46 +0000] \"GET /kubernetes-clusters/<cluster_id>?verbose=false HTTP/1.1\" 500 22 \"\" \"zmon-worker/0.1\" 10010 cluster-registry.stups.zalan.do

The request is made at 14:59:46 and times out after 10s at 14:59:56. (Not visible here, but it tried to route to pod ip 10.2.108.118)

Looking at the route configuration logs of skipper we see the following:

[APP]time="2018-05-25T14:55:29Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_0: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 0) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.108.118:8080\""
[APP]time="2018-05-25T14:55:29Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_1: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 1) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.45.124:8080\""
[APP]time="2018-05-25T14:55:41Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry__lb_group: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBGroup(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\") -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> lbDecide(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 3) -> <loopback>"
[APP]time="2018-05-25T14:55:41Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_1: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 1) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.26.148:8080\""
[APP]time="2018-05-25T14:55:41Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_2: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 2) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.45.124:8080\""
[APP]time="2018-05-25T14:59:37Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_1: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 1) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.45.124:8080\""
[APP]time="2018-05-25T14:59:37Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry__lb_group: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBGroup(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\") -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> lbDecide(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 2) -> <loopback>"
[APP]time="2018-05-25T14:59:48Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_1: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 1) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.118.128:8080\""
[APP]time="2018-05-25T14:59:48Z" level=info msg="route settings, update, route: kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry_0: Host(/^cluster-registry[.]stups[.]zalan[.]do$/) && LBMember(\"kube_default__cluster_registry__cluster_registry_stups_zalan_do____cluster_registry\", 0) -> setResponseHeader(\"Access-Control-Allow-Origin\", \"*\") -> setResponseHeader(\"Access-Control-Allow-Methods\", \"GET, OPTIONS\") -> setResponseHeader(\"Access-Control-Allow-Headers\", \"\") -> dropRequestHeader(\"X-Load-Balancer-Member\") -> \"http://10.2.106.123:8080\""

At 14:55:29 we see route 0 with backend 10.2.108.118 and at 14:59:48 we see route 0 with backend 10.2.106.123. This means that at 14:59:48 the routes of skipper were changed and it's now pointing to a new pod.

At the same time we can see that the last logline of the pod with ip 10.2.108.118 was at 14:59:45 1s before the failed request reached skipper:

time=\"2018-05-25T14:59:45Z\" level=info client=<client> duration=5.521511ms method=GET path=\"/kubernetes-clusters/<cluster_id>

So what happened here was that Kubernetes terminated a pod during a rolling update of a deployment. The pod was gone at 14:59:45, skipper routed a request to the pod at 14:59:46 and updated the routes to remove this pod as backend at 14:59:48. So the application had a 2s downtime which resulted in a 500 (It should probably be a 504).

We see these 500s when applications are updated and during cluster updates. Basically it can happen whenever a pod is terminated and skipper has to remove it from the routes.

It should be noted that this pod gracefully handles SIGTERMs by draining open connections of the internel HTTP server and then shuts down. Since there are not many open connections at a time, it terminates pretty fast.

One hack around this issue could be to swallow the SIGTERM and wait to be SIGKILLed 30s later (default) which should give skipper enough time to update the routes. But it's not very nice to ask every user to implement such a hack.

We have discussed this before but the solution here is really something like connection draining. I.e. we should somehow remove the pod ip from the skipper routes and then signal to Kubernetes that the pod can be terminated after it's not getting traffic anymore. This idea is somehow similar to Pod Ready++ with the difference being Pod Ready++ doesn't consider the problem of pods terminating.

[mikkeloscar]

Another hack which doesn't require custom implementation in the application is to use pod lifecycle hooks:

lifecycle:
  preStop:
    exec:
      command: ["sleep","20"]

https://kubernetes.io/docs/tasks/configure-pod-container/attach-handler-lifecycle-event/#define-poststart-and-prestop-handlers

This works because Kubernetes removes the pod from the endpoints list when the pod is being terminated. This is even though the pod is still ready during the preStop hook execution.

[szuecs]

Thanks for your detailed writing.
One question I have is: the endpoints list in kubernetes is cleaned up before the pod is terminated?
In normal loadbalancers a pool is maintained and the members are health checked every duration, for example 3s, which might be not enough even for graceful shutdown if applications don’t care about the environment. We can try to watch endpoints and update also based on endpoint updates. As far as I tested last time, there’s a lot of noise updates, that have no changes we would need to filter before doing updates of the routing table.
This would also make it only more unlikely to happen, because the race condition exists in kubernetes and can’t be solved in skipper itself.
We should write some docs first and you provided a great workaround which can be used.

[mikkeloscar]

One question I have is: the endpoints list in kubernetes is cleaned up before the pod is terminated?

Yes, when running the pods with the sleep 20 preStop it's very easy to see that the IP gets removed from the endpoints list right when the pod termination is started and not after 30s (which is the default readiness probe config (probe period of 10s and failureThresholdof 3)). I'm still not sure who removes it from the endpoints list, couldn't find the code for this yet).

This would also make it only more unlikely to happen, because the race condition exists in kubernetes and can’t be solved in skipper itself.

Yeah, it's a bit unfair to mark this as a bug in skipper, I just thought it's most relevant here because this is where the 500s are coming from. It's clear that it's a Kubernetes design problem and the same is the case for kube-proxy. Maybe watching instead of polling mitigates this enough, but it's not the perfect solution.

I tested this with a two replica deployment where I ran a load test while doing a rolling update of the deployment:

echo "GET https://sigterm.example.org/" | vegeta attack -duration=30s | tee results.bin | vegeta report 

With the preStop hook in place I never see errors. Without it, I always see around 5% error rate.

The test app I used for this is here: https://github.com/mikkeloscar/kube-sigterm-test

[szuecs]

https://github.com/zalando/skipper/releases/tag/v0.10.16 was released that should convert these errors from 500 to 504 as far as I understand, lets check and https://github.com/zalando/skipper/pull/666 will document termination strategies.

[szuecs]

It's now documented at https://opensource.zalando.com/skipper/kubernetes/ingress-backends/

[szuecs]

This can not be solved by skipper as ingress controller and we have documented in https://opensource.zalando.com/skipper/kubernetes/ingress-backends/ how to circumvent this in deployments.
As agreed with @mikkeloscar I close this issue.