Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ingress controller not loaded backend changes in time #3335

Closed
jasonwangnanjing opened this issue Nov 1, 2018 · 13 comments
Closed

Ingress controller not loaded backend changes in time #3335

jasonwangnanjing opened this issue Nov 1, 2018 · 13 comments
Labels
lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.

Comments

@jasonwangnanjing
Copy link

NGINX Ingress controller version:
quay.io/kubernetes-ingress-controller/nginx-ingress-controller:0.19.0

Kubernetes version (use kubectl version):
1.11

Environment:

  • Cloud provider or hardware configuration: Azure
  • OS (e.g. from /etc/os-release):Centos
  • Kernel (e.g. uname -a):
  • Install tools:
  • Others:

What happened:
when one pod deleted, Nginx did not reload backend in time. Which caused it still pass request to died pod.Then 502 error return to user.

What you expected to happen:
when one pod deleted, nginx should be updated in time to stop traffic to it.

How to reproduce it (as minimally and precisely as possible):
Define a service for more than one pods, then put service as backend service inside one ingress object.
After both pod running, delete one.

Anything else we need to know:

@ElvinEfendi
Copy link
Member

@jasonwangnanjing how long of latency are we talking here? The expected delay in update is:

<the time it takes for k8s API to deliver the change> + 1s (internal syncing)

If you're seeing latency of >5s then there's something wrong somewhere, otherwise everything works as expected you just need to make sure your app shutdown gracefully. Kubernetes will send SIGTERM when you delete your app, some apps exits immediately on this signal but they should exit gracefully after draining in flight requests and also waiting around for ~3s after that and only then exit.

I'd suggest you add following in your Deployment spec if you don't have it yet:

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

@jasonwangnanjing
Copy link
Author

@ElvinEfendi
I upgraded nginx version to quay.io/kubernetes-ingress-controller/nginx-ingress-controller:0.20.0
Then i can see it load the configuration in time. But it continues direct request to died pod. As you can see from below log.It try to send request to upstream 10.244.1.83 which is died already.Then it got connecting timeout.

I1108 06:35:24.171423 8 controller.go:175] Changes handled by the dynamic configuration, skipping backend reload.
I1108 06:35:24.172427 8 controller.go:212] Dynamic reconfiguration succeeded.

2018/11/08 06:35:43 [error] 8377#8377: *272836 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /bcp/BCPSite/en/SEK/Open-Catalogue/c/1/ HTTP/1.1", upstream: "https://10.244.1.83:9002/bcp/BCPSite/en/SEK/Open-Catalogue/c/1/", host: "bcp-core-waf.westeurope.cloudapp.azure.com", referrer: "https://bcp-core-waf.westeurope.cloudapp.azure.com/bcp/BCPSite/en/SEK/"
2018/11/08 06:35:48 [error] 8377#8377: *272836 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /bcp/BCPSite/en/SEK/Open-Catalogue/c/1/ HTTP/1.1", upstream: "https://10.244.1.83:9002/bcp/BCPSite/en/SEK/Open-Catalogue/c/1/", host: "bcp-core-waf.westeurope.cloudapp.azure.com", referrer: "https://bcp-core-waf.westeurope.cloudapp.azure.com/bcp/BCPSite/en/SEK/"
2018/11/08 06:35:53 [error] 8377#8377: *272836 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /bcp/BCPSite/en/SEK/Open-Catalogue/c/1/ HTTP/1.1", upstream: "https://10.244.1.83:9002/bcp/BCPSite/en/SEK/Open-Catalogue/c/1/", host: "bcp-core-waf.westeurope.cloudapp.azure.com", referrer: "https://bcp-core-waf.westeurope.cloudapp.azure.com/bcp/BCPSite/en/SEK/"
194.39.218.10 - [194.39.218.10] - - [08/Nov/2018:06:35:53 +0000] "GET /bcp/BCPSite/en/SEK/Open-Catalogue/c/1/ HTTP/1.1" 504 167 "https://bcp-core-waf.westeurope.cloudapp.azure.com/bcp/BCPSite/en/SEK/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0" 1650 15.000 [default-bcp-hybris-https-lb-443] 10.244.1.83:9002, 10.244.1.83:9002, 10.244.1.83:9002 0, 0, 0 5.000, 5.000, 5.000 504, 504, 504 edef417e181ba0ee85ac3fc913050654
2018/11/08 06:35:58 [error] 7506#7506: *291026 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /favicon.ico HTTP/1.1", upstream: "https://10.244.1.83:9002/favicon.ico", host: "bcp-core-waf.westeurope.cloudapp.azure.com"
2018/11/08 06:36:03 [error] 7506#7506: *291026 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /favicon.ico HTTP/1.1", upstream: "https://10.244.1.83:9002/favicon.ico", host: "bcp-core-waf.westeurope.cloudapp.azure.com"
2018/11/08 06:36:08 [error] 7506#7506: *291026 upstream timed out (110: Connection timed out) while connecting to upstream, client: 194.39.218.10, server: _, request: "GET /favicon.ico HTTP/1.1", upstream: "https://10.244.1.83:9002/favicon.ico", host: "bcp-core-waf.westeurope.cloudapp.azure.com"
194.39.218.10 - [194.39.218.10] - - [08/Nov/2018:06:36:08 +0000] "GET /favicon.ico HTTP/1.1" 504 167 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0" 1440 15.000 [default-bcp-hybris-https-lb-443] 10.244.1.83:9002, 10.244.1.83:9002, 10.244.1.83:9002 0, 0, 0 5.001, 5.000, 5.000 504, 504, 504 04e181a5a076a7b47728f430a444a6b5

@ElvinEfendi
Copy link
Member

@jasonwangnanjing ingress-nginx relies on k8s readiness probes, have you confirmed that those pods actually marked as "Not Ready"?

@JordanP
Copy link
Contributor

JordanP commented Dec 6, 2018

This looks like #3070

@timm088
Copy link

timm088 commented Jan 30, 2019

We are seeing similar, even after implementing the suggested sleep preStop hook here, i.e., the ingress controller is trying to send traffic to an upstream pod that is marked as 'Terminating' following a rollingUpdate deployment.

It only does so for a small period of time, but it certainly is repeatable. Struggling to find where to begin with this, but happy to help debug further.

@ElvinEfendi any suggestions for what could assist in debugging? My understanding is that the ingress controller should not be sending traffic to these pods in Terminating status, as they are not active on the service endpoint anymore

@ElvinEfendi
Copy link
Member

@timm088 first thing I'd check would be to make sure you aren't seeing "Dynamic reconfiguration failed" warning messages.

I'd also run ingress-nginx with v=2 flag and check for "Dynamic reconfiguration succeeded" at the time when your pod gets into "terminating" state. Normally when your pod turns into "terminating" state, ingress-nginx should log "Dynamic reconfiguration succeeded" - you can measure the latency here and adjust preStop hook accordingly. Once you see "Dynamic reconfiguration succeeded" it takes up to 1s (https://github.com/kubernetes/ingress-nginx/blob/master/rootfs/etc/nginx/lua/balancer.lua#L15) for all Nginx workers to have the newest endpoints synced.

At a given time you can also inspect what endpoints Nginx has in its memory by looking at

kubectl exec <an ingress-nginx pod> -n <namespace> -- curl -s localhost:18080/configuration/backends

@timm088
Copy link

timm088 commented Jan 30, 2019

Interesting, i'll give that a go and come back. Definitely not seeing 'Dynamic reconfiguration failed' messages.

I'm not quite understanding how the preStop hook helps the ingress controller here...

  1. Pod in terminating status, simultaneously
    4a. preStop hook invoked and executed
    (Paraphrased from https://kubernetes.io/docs/concepts/workloads/pods/pod/#termination-of-pods)

So during the 'terminating' phase, the ingress controller has (1s by default, or 4s if we implement the 3s sleep hook ... likely faster depending on where it is on the 1s counter) to update backends, removing the terminating pods as active endpoints?

I have some internal that receive >10 calls per second, and are somewhat critical to the stack, so getting timeouts on these calls is going to bubble 5xx back up the stack to users.

0robustus1 added a commit to 0robustus1/ingress-nginx that referenced this issue Feb 3, 2019
* related to:
  * kubernetes#3070
  * kubernetes#3335
* add a 503 test
  * test a service that starts out empty
    (a.k.a. ingress-nginx controller (re-)start)
  * test scaling up (should route traffic accordingly)
  * test scaling down to empty service
  * use custom deployments for scaling test.
* provide a fix by updating the lua table (cache) of the configured backends
  to unset the backend if there are no endpoints available.
@perandersson
Copy link

perandersson commented Feb 7, 2019

We are seeing a similar problem at my company as well. We are using version 0.21.0.

We are experimenting with zero-downtime upgrade of the Kubernetes Cluster while running load testing at the same time (i.e. 20 requests / second). The ingress controller returns 502 when it tries to redirect to one of the pods located in a machine we are running kubectl drain on in preparation for the upgrade (it does this for only a few requests).

I understand that there exists some kind of race condition between when a pod is shutting down and the "un-ready" event is being handled by the ingress controller. But I don't think using a "sleep" is a good way of solving this problem. Is there no other event you can listen to that's being sent when a deletion of a pod is being sent? Or perhaps introduce some kind of configurable "retry" functionality for all idempotent (such as GET) requests?

@aledbf
Copy link
Member

aledbf commented Feb 7, 2019

The ingress controller returns 502 when it tries to redirect to one of the pods located in a machine we are running kubectl drain on in preparation for the upgrade (it does this for only a few requests).

Please check https://kubernetes.github.io/ingress-nginx/user-guide/nginx-configuration/configmap/#proxy-next-upstream The default value is error timeout. You can change that setting proxy_next_upstream: "error timeout http_502"  in the configuration configmap.

@perandersson
Copy link

The ingress controller returns 502 when it tries to redirect to one of the pods located in a machine we are running kubectl drain on in preparation for the upgrade (it does this for only a few requests).

Please check https://kubernetes.github.io/ingress-nginx/user-guide/nginx-configuration/configmap/#proxy-next-upstream The default value is error timeout. You can change that setting proxy_next_upstream: "error timeout http_502" in the configuration configmap.

This flag only works if we have more than one server, whatever that means, and it did not solve the problem for me. I can see that the nginx.conf file was updated with the a proxy_next_upstream error timeout http_502; for all server blocks when looking into our nginx pods.

Now, it feels like i hijacked the original issue, so if this seems like a separate problem from the original question at the top then please let me know and I'll create a new issue on it.

@aledbf
Copy link
Member

aledbf commented Feb 7, 2019

@perandersson please open a new issue :)

This flag only works if we have more than one server

This is correct, if your pod dies, there is nothing nginx can do to avoid a 502 response. To avoid this you need to use probes in your app the sleep workaround. Another thing you can configure is
PodDisruptionBudget specifying minAvailable: 1 for the drain scenario

@fejta-bot
Copy link

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

@k8s-ci-robot k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label May 8, 2019
@fejta-bot
Copy link

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten

@k8s-ci-robot k8s-ci-robot added lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed. and removed lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. labels Jun 7, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
lifecycle/rotten Denotes an issue or PR that has aged beyond stale and will be auto-closed.
Projects
None yet
Development

No branches or pull requests

8 participants