istio: Service stops receive readiness prob requests from Kubernetes

Bug description

I have about 20 pods running on Kubernetes cluster. After about 3 days, they begin to refuse Readiness prob HTTP requests.

This is an example of “kubectl describe pod” output:

Warning Unhealthy 4m41s (x104971 over 4d21h) kubelet, digi (combined from similar events): Readiness probe failed: Get http://10.1.1.139:8080/v1/readiness: read tcp 10.1.1.1:35178->10.1.1.139:8080: read: connection reset by peer

Output of same pod after few minutes:

Warning Unhealthy 2m32s (x105570 over 4d21h) kubelet, digi (combined from similar events): Readiness probe failed: Get http://10.1.1.139:8080/v1/readiness: read tcp 10.1.1.1:35028->10.1.1.139:8080: read: connection reset by peer

Seems like process itself inside container is not aware about any issues. Logs look just normally. If I opening ssh into container (e.g. “kubectl exec -it”) - I do able to perform http call to the readiness URL (curl on localhost) - so the issue is only when making requests from the outside, which makes me thinks it somehow related to networking --> Istio.

Trying to make readiness request from another pod fails as well with the following output:

curl 10.1.1.139:8080/v1/readiness -v Trying 10.1.1.139... TCP_NODELAY set Connected to 10.1.1.139 (10.1.1.139) port 8080 (#0) GET /v1/readiness HTTP/1.1 Host: 10.1.1.139:8080 User-Agent: curl/7.58.0 Accept: */* HTTP/1.1 503 Service Unavailable content-length: 95 content-type: text/plain date: Sun, 28 Jul 2019 10:48:37 GMT server: envoy Connection #0 to host 10.1.1.139 left intact upstream connect error or disconnect/reset before headers. reset reason: connection termination

There is no restarts nor on my pods nor on Istio pods.

Deleting pod (which causing Kubernetes to recreate it) will solve the issue, for about next 3 days. After that, the issue starts over again.

Mutual TLS is not enabled.

Affected product area (please put an X in all that apply)

[ ] Configuration Infrastructure [ ] Docs [ ] Installation [X] Networking [ ] Performance and Scalability [ ] Policies and Telemetry [ ] Security [ ] Test and Release [ ] User Experience [ ] Developer Infrastructure

Expected behavior Readiness probs will work as intended

Steps to reproduce the bug I not doing anything special… Running pod on Kubernetes with http readiness prob enabled.

Version (include the output of istioctl version --remote and kubectl version) I was able to reproduce this issue in the following platforms / versions: Istio: 1.1.1 / 1.1.8/ 1.2.2 Kubernetes: 1.12 / 1.13 / 1.15 Platform: AWS EKS / local Microk8s

How was Istio installed? Using “Helm template” option

Environment where bug was observed (cloud vendor, OS, etc) on cloud: AWS EKS \ on local: Ubuntu 18.04.02

About this issue

Original URL
State: closed
Created 5 years ago
Comments: 20 (5 by maintainers)

Most upvoted comments

The TLDR is that treating HTTP as TCP does not work when the connection is short-lived, and created frequently.

incfly on Sep 16, 2019

I successfully reproduced that indeed with http service port treated as tcp, the pod will end-up with many sockets in TIME_WAIT state.

I then did some networking basics study. If we have many short-lived sockets, then the other side has to wait for a while and during that the socket is in TIME_WAIT state.

The http prober requests from the kubelet matches the criteria. And eventually we accumulated enough TIME_WAIT socket, exceeds the system limit[], and thus unable to create the socket for a while.

# in the pod
istio-proxy@liveness-http-tcp-7f86d45bb9-fbl66:/$ sudo ss -atp | grep 8002 
LISTEN     0      128       :::8002                    :::*                    
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33590                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33620                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33562                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33438                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33466                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33316                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33416                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33510                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33338                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:33368                
TIME-WAIT  0      0      ::ffff:10.56.5.95:8002                  ::ffff:10.56.5.1:3348

in the node network

jianfeih@gke-istio-perf-default-pool-a1d6b087-1vw6 ~ $ sudo netstat -atpw | grep 10.56.5.95:8002                                                                                                                              [30/1826]
tcp        0      0 10.56.5.1:37744         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37704         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37832         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37842         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37810         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37760         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37808         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37782         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37894         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37906         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37722         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37852         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37910         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37774         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37790         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37826         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37752         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37858         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37846         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37890         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37836         10.56.5.95:8002         TIME_WAIT   -
tcp        0      0 10.56.5.1:37872         10.56.5.95:8002         TIME_WAIT   -

incfly on Sep 16, 2019

Without taking a look of the Envoy configuration dump and the Pod/Deployment YAML, I have a very random guess.

The application port is declared as TCP, even though the prober is a HTTP request.
Kubelet —(http) —> Envoy --(TCP_PROXY) --> App.
Every HTTP prober request establishes a new TCP connection.
The app itself does not close the socket correspondingly.
App runs out of the socket available.

From a past incident, a customer reports many CLOSE_WAIT socket is hanging on the app pod. I think if we ensure the inbound cluster is configured as http_connection_manager, that might solve the issue.

Can you check your corresponding service port is named as http.* per istio port name convention? And then the inbound serving listeners in the end is using http connection manager rather than tcp proxy filter?

incfly on Sep 9, 2019