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

Service stops receive readiness prob requests from Kubernetes #15881

Closed
illidan80 opened this issue Jul 28, 2019 · 20 comments

Comments

@illidan80
Copy link

commented Jul 28, 2019

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

@hzxuzhonghu

This comment has been minimized.

Copy link
Member

commented Jul 30, 2019

Did you set sidecarInjectorWebhook.rewriteAppHTTPProbe ? I just noticed it is still disabled by default.

@hzxuzhonghu

This comment has been minimized.

Copy link
Member

commented Jul 30, 2019

@incfly I think it's time to enable it by default

@illidan80

This comment has been minimized.

Copy link
Author

commented Jul 30, 2019

@hzxuzhonghu: I start to experience issues with readiness checks only after running a while (about 3 days). Could you please elaborate how disabled "sidecarInjectorWebhook.rewriteAppHTTPProbe" can cause such behavior?

BTW, I want to point your attention that I not using mutual TLS.

@hzxuzhonghu

This comment has been minimized.

Copy link
Member

commented Jul 30, 2019

BTW, I want to point your attention that I not using mutual TLS

OK, then it is not this cause.

Check your inbound xds configuration then.

@illidan80

This comment has been minimized.

Copy link
Author

commented Jul 31, 2019

@hzxuzhonghu Appreciate your help, but could you please explain how whatsoever configuration may lead to such inconsistent behavior, as described above (e.g. everything works during few days, after that begin to reject requests from time to time)?

@hzxuzhonghu

This comment has been minimized.

Copy link
Member

commented Jul 31, 2019

Inbound listener、 cluster with the probe port

@illidan80

This comment has been minimized.

Copy link
Author

commented Aug 4, 2019

Update: I disabled sidecar injection on one of the environments (which was previously having the issue). All pods are running already for 5.5 days - without any problem.

Looks like indeed there is some issue related to the Istio sidecar...

Anyone has ideas?

@crhuber

This comment has been minimized.

Copy link

commented Sep 6, 2019

We are also experiencing similar issue

@illidan80

This comment has been minimized.

Copy link
Author

commented Sep 8, 2019

@crhuber: do you have any progress on this?

@duderino duderino added this to the 1.3 milestone Sep 9, 2019

@duderino

This comment has been minimized.

Copy link
Contributor

commented Sep 9, 2019

@incfly any ideas?

@incfly

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

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

  1. The application port is declared as TCP, even though the prober is a HTTP request.
  2. Kubelet ---(http) ---> Envoy --(TCP_PROXY) --> App.
  3. Every HTTP prober request establishes a new TCP connection.
  4. The app itself does not close the socket correspondingly.
  5. 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?

@illidan80

This comment has been minimized.

Copy link
Author

commented Sep 9, 2019

@incfly Hi, first - thank you for your effort helping on this.

Here is a deployment yaml ("obfuscated") of one of the trouble makers:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: deployment-xxx
  namespace: product  
spec:
  selector:
    matchLabels:
      app: xxx
  replicas: {{.Values.replicas}}
  template:
    metadata:
      labels:
        app: xxx
        kind: deployment
        version: "{{.Values.service.docker.image.version}}"
        context: "{{.Values.context}}"
    spec:
      serviceAccountName: xxx
      volumes:
        - name: volume1
          secret:
            secretName: secret1
        - name: volume2
          secret:
            secretName: secret2
      containers:
        - name: container-xxx
          image: {{.Values.service.docker.imageRegistry}}/xxx:{{.Values.service.docker.image.version}}
          ports:
            - containerPort: 8080
            - containerPort: 5005
          volumeMounts:
            - name: volume1
              mountPath: "/secrets/secret1"
              subPath: secret1
              readOnly: true
            - name: volume2
              mountPath: "/secrets/secret2"
              subPath: secret2
              readOnly: true
          readinessProbe:
            httpGet:
              path: /v1/readiness
              port: 8080
            initialDelaySeconds: 1
            periodSeconds: 1

...and a corresponding service yaml:

kind: Service
apiVersion: v1
metadata:
  name: xxx
  namespace: product
spec:
  selector:
    app: xxx
  ports:
    - protocol: TCP
      port: 80
      targetPort: 8080

Yes, you are right. Indeed, we declaring TCP. But I would expect it will either work always or work never . How it can work for about 3 days, and then stop working?

Also, for the future, could you please give some tips where to look for getting more info for resolving similar issues? I was trying to set logging level of the sidecar for most verbose (I think that was a "debug" level) - but there was still nothing suspicious. Thanks!

@incfly

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

@illidan80

This comment has been minimized.

Copy link
Author

commented Sep 9, 2019

sure, i can try it. but unfortunetly, usually it takes about 3 days until issue starts to appear... so it will take some time to confirm (or not) this direction.

is there any dumps / logs / something i can look into it?

@incfly

This comment has been minimized.

Copy link
Member

commented Sep 9, 2019

@illidan80

This comment has been minimized.

Copy link
Author

commented Sep 15, 2019

Yep, that's it. Missing service port name causing pods side car to die after several days. As soon as I added port name ("http") - issue resolved.

My suggestion is to explicitly note in the Istio documentation about consequences of not naming ports. Even better, if possible, to issue a warning about missing port name.

@illidan80

This comment has been minimized.

Copy link
Author

commented Sep 15, 2019

P.S. Now I see this in 1.3 release notes:

Added automatic determination of HTTP or TCP for outbound traffic when ports are not named according to Istio’s conventions.

Well done

@incfly

This comment has been minimized.

Copy link
Member

commented Sep 15, 2019

@illidan80 note the inbound port protocol detection is disabled by default. This does not work with mTLS.

For 1.3, we still have to require users to declare container port w.r.t to use case here.

fyi @lambdai

@incfly

This comment has been minimized.

Copy link
Member

commented 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 incfly closed this Sep 16, 2019

@incfly

This comment has been minimized.

Copy link
Member

commented Sep 16, 2019

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
6 participants
You can’t perform that action at this time.