{"action":"created","issue":{"url":"https://api.github.com/repos/zalando/skipper/issues/652","repository_url":"https://api.github.com/repos/zalando/skipper","labels_url":"https://api.github.com/repos/zalando/skipper/issues/652/labels{/name}","comments_url":"https://api.github.com/repos/zalando/skipper/issues/652/comments","events_url":"https://api.github.com/repos/zalando/skipper/issues/652/events","html_url":"https://github.com/zalando/skipper/issues/652","id":326653000,"node_id":"MDU6SXNzdWUzMjY2NTMwMDA=","number":652,"title":"Kubernetes: 500s when updating deployments.","user":{"login":"mikkeloscar","id":128566,"node_id":"MDQ6VXNlcjEyODU2Ng==","avatar_url":"https://avatars0.githubusercontent.com/u/128566?v=4","gravatar_id":"","url":"https://api.github.com/users/mikkeloscar","html_url":"https://github.com/mikkeloscar","followers_url":"https://api.github.com/users/mikkeloscar/followers","following_url":"https://api.github.com/users/mikkeloscar/following{/other_user}","gists_url":"https://api.github.com/users/mikkeloscar/gists{/gist_id}","starred_url":"https://api.github.com/users/mikkeloscar/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mikkeloscar/subscriptions","organizations_url":"https://api.github.com/users/mikkeloscar/orgs","repos_url":"https://api.github.com/users/mikkeloscar/repos","events_url":"https://api.github.com/users/mikkeloscar/events{/privacy}","received_events_url":"https://api.github.com/users/mikkeloscar/received_events","type":"User","site_admin":false},"labels":[{"id":234268900,"node_id":"MDU6TGFiZWwyMzQyNjg5MDA=","url":"https://api.github.com/repos/zalando/skipper/labels/bug","name":"bug","color":"fc2929","default":true},{"id":666789609,"node_id":"MDU6TGFiZWw2NjY3ODk2MDk=","url":"https://api.github.com/repos/zalando/skipper/labels/kubernetes","name":"kubernetes","color":"0052cc","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-05-25T20:25:10Z","updated_at":"2018-06-06T15:35:10Z","closed_at":null,"author_association":"MEMBER","body":"I discussed this problem with @szuecs and I wanted to document an example of this issue which proves our hypothesis.\r\n\r\nConsider this `500` from ingress skipper:\r\n```\r\n[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\\\"\r\n[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\\\"\r\n[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\\\"\r\n<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\r\n```\r\n\r\nThe 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`)\r\n\r\nLooking at the route configuration logs of skipper we see the following:\r\n```\r\n[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\\\"\"\r\n[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\\\"\"\r\n[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>\"\r\n[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\\\"\"\r\n[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\\\"\"\r\n[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\\\"\"\r\n[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>\"\r\n[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\\\"\"\r\n[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\\\"\"\r\n```\r\n\r\nAt `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.\r\n\r\nAt 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:\r\n\r\n```\r\ntime=\\\"2018-05-25T14:59:45Z\\\" level=info client=<client> duration=5.521511ms method=GET path=\\\"/kubernetes-clusters/<cluster_id>\r\n```\r\n\r\nSo 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`).\r\n\r\nWe see these `500`s 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.\r\n\r\nIt should be noted that this pod gracefully handles `SIGTERM`s 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.\r\n\r\nOne hack around this issue could be to swallow the `SIGTERM` and wait to be `SIGKILL`ed 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.\r\n\r\nWe 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++](https://github.com/kubernetes/community/blob/master/keps/sig-network/0007-pod-ready%2B%2B.md) with the difference being Pod Ready++ doesn't consider the problem of pods terminating."},"comment":{"url":"https://api.github.com/repos/zalando/skipper/issues/comments/395113085","html_url":"https://github.com/zalando/skipper/issues/652#issuecomment-395113085","issue_url":"https://api.github.com/repos/zalando/skipper/issues/652","id":395113085,"node_id":"MDEyOklzc3VlQ29tbWVudDM5NTExMzA4NQ==","user":{"login":"szuecs","id":50872,"node_id":"MDQ6VXNlcjUwODcy","avatar_url":"https://avatars2.githubusercontent.com/u/50872?v=4","gravatar_id":"","url":"https://api.github.com/users/szuecs","html_url":"https://github.com/szuecs","followers_url":"https://api.github.com/users/szuecs/followers","following_url":"https://api.github.com/users/szuecs/following{/other_user}","gists_url":"https://api.github.com/users/szuecs/gists{/gist_id}","starred_url":"https://api.github.com/users/szuecs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/szuecs/subscriptions","organizations_url":"https://api.github.com/users/szuecs/orgs","repos_url":"https://api.github.com/users/szuecs/repos","events_url":"https://api.github.com/users/szuecs/events{/privacy}","received_events_url":"https://api.github.com/users/szuecs/received_events","type":"User","site_admin":false},"created_at":"2018-06-06T15:35:10Z","updated_at":"2018-06-06T15:35:10Z","author_association":"MEMBER","body":"It's now documented at https://opensource.zalando.com/skipper/kubernetes/ingress-backends/"}}
{"actor":{"display_login":"szuecs"}}