Bug 1899349

Let's track the slow requests:
> grep -rni "2020-11-18T19:" must-gather/namespaces/openshift-kube-apiserver/* | grep 'trace.go'

- master-1 seems to be okay, only one slow API response in order of seconds.
- master-0 has a lot of slow requests in order of seconds (up to 30s and quite a few)
- master-3 has no slow log

So focusing on master-0, for master-0 slowness starts around ‘19:35’. This coincides with the incident window.
Also all the slow calls are limited to the following:
> url:/apis/apps/v1/namespaces/openshift-logging/deployments (user-agent:elasticsearch-operator/v0.0.0)
> url:/apis/authentication.k8s.io/v1/tokenreviews (user-agent:oauth-proxy/v0.0.0)

Does not seem to be a smoking gun here, but open questions are:
- is the openshift-logging hitting the apiserver hard? (unlikely but we can do further investigation to rule it out) 
- `tokenreviews` calls were frequent around that time and it was coming from 'oauth-proxy. If we check the audit it will tell us what component is making these calls. Again, does not look like it is the root cause but worth doing further investigation


> There are some ‘bad certificate error’ on master-3
It probably is a different issue that we need to address later.

Now, I want to focus on the following error:
> TLS handshake timeout


There are many of these errors scattered
> $ grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/* | wc -l
> 7807

Let's focus on master-0 around incident window ‘19:35’
> $ grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/* | grep '2020-11-18T19:' | wc -l
> 30

The first incident is at '2020-11-18T19:43:02'. All the ^ errors have the following format:
> controller.go:114] loading OpenAPI spec for "v1.image.openshift.io" failed with: failed to retrieve openAPI spec, http error: ResponseCode: 503, Body: Error trying to reach service: 'net/http: TLS handshake timeout', Header: map[Content-Type:[text/plain; charset=utf-8] X-Content-Type-Options:[nosniff]]

So it seems like kube-apiserver is failing to reach openshift-apiserver (openshift.io) and olm (operators.coreos.com).

BTW, around the same time window, master-1 shows zero ''
> $ grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-1/* | grep '2020-11-18T19:' | wc -l
> 0

This shows that this issue is not prevalent across all kube-apiserver instances at the same time. But we do see the "TLS handshake timeout" error scattered
master-0:
> grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/* | wc -l
> 5454

master-1:
> $ grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-1/* | wc -l
> 2353

master-3:
> $ grep -rni "TLS handshake timeout" must-gather/namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-3/* | wc -l
> 0


Okay, now let's focus on openshift-apiserver log around the same time window:
We see panics:
> grep -rni "2020-11-18T19:" must-gather/namespaces/openshift-apiserver/* | grep "apiserver panic'd" | wc -l
> 6

The panics are symptoms for request taking longer and longer and consequently some of them timing out. If you check for slow requests in oas log:
> grep -rni "2020-11-18T19:" must-gather/namespaces/openshift-apiserver/* | grep 'trace.go'

the first slow request took 31s and happened at "19:39:45". It originated from "elasticsearch-proxy".
> 2020-11-18T19:39:45.6478132Z I1118 19:39:45.647794       1 trace.go:116] Trace[1178114051]: "List" url:/apis/project.openshift.io/v1/projects,user-agent:elasticsearch-proxy/v0.0.0 (linux/amd64) kubernetes/$Format,client:10.150.8.8 (started: 2020-11-18 19:39:13.648768417 +0000 UTC m=+46867.519578922) (total time: 31.998991482s):

There is another interesting thing happening around the same time window in oas log: we see lots of "TLS handshake error from 10.128.2.1:44232: EOF" error
> $ grep -rni "TLS handshake error" must-gather/namespaces/openshift-apiserver/* | grep '2020-11-18T19:' | wc -l
> 1000

So kube-apiserver is getting a "TLS handshake timeout" error from oas and oas is reporting a "TLS handshake error from 10.128.2.1:44232: EOF" error. See the error logs below:
> 2020-11-18T19:59:25.207670281Z E1118 19:59:25.207632       1 controller.go:114] loading OpenAPI spec for "v1.authorization.openshift.io" failed with: failed to retrieve openAPI spec, http error: ResponseCode: 503, Body: Error trying to reach service: 'net/http: TLS handshake timeout', Header: map[Content-Type:[text/plain; charset=utf-8] X-Content-Type-Options:[nosniff]]

> 2020-11-18T19:59:56.559284343Z I1118 19:59:56.559210       1 log.go:172] http: TLS handshake error from 10.128.2.1:44232: EOF


The ^ looks very similar to https://bugzilla.redhat.com/show_bug.cgi?id=1825219 KCS: https://access.redhat.com/solutions/5252831


Hi hgomes,
> Until the moment was not verified any weird values to 'ip show cache'
Have you setup the daemonset suggested by the sdn team?

Next Steps:
- let's ensure that this is not https://bugzilla.redhat.com/show_bug.cgi?id=1825219.
- can openshift-logging be the root cause here? Most of the slow calls originate from the logging operator and its proxy. Need to rule it out, maybe turn it off.
- can we get access to prometheus data dump when the issue occurs next time? It will give us insights into cpu/memory consumption of the cluster and whether it's under any sort of load.

Hi Abu,

Answering your question about the daemonset of the KCS https://access.redhat.com/solutions/5252831.

Yesterday night we saw this situation and applied the workaround creating the daemonset.

Today I've validated the logs of the workaround and on master-1 one had one execution of the flush.

# OpenShift APIs went unavailable for almost an hour, the first entry was at 19:36:42 and the last one at 20:22:55 and the service was available again at 20:22:58
# Here are the relevant logs from OpenShift API Operator

2020-11-18T19:36:42.49437462Z I1118 19:36:42.494336       1 status_controller.go:172] clusteroperator/openshift-apiserver diff {"status":{"conditions":[{"lastTransitionTime":"2020-11-06T02:16:43Z","reason":"AsExpected","status":"False","type":"Degraded"},{"lastTransitionTime":"2020-11-12T21:24:43Z","reason":"AsExpected","status":"False","type":"Progressing"},{"lastTransitionTime":"2020-11-18T19:36:07Z","message":"APIServicesAvailable: \"build.openshift.io.v1\" is not ready: 503 (the server is currently unable to handle the request)\nAPIServicesAvailable: \"image.openshift.io.v1\" is not ready: 503 (the server is currently unable to handle the request)\nAPIServicesAvailable: \"quota.openshift.io.v1\" is not ready: 503 (the server is currently unable to handle the request)","reason":"APIServices_Error","status":"False","type":"Available"},{"lastTransitionTime":"2020-10-10T14:29:24Z","reason":"AsExpected","status":"True","type":"Upgradeable"}]}}


2020-11-18T20:22:55.970515468Z I1118 20:22:55.970478       1 status_controller.go:172] clusteroperator/openshift-apiserver diff {"status":{"conditions":[{"lastTransitionTime":"2020-11-06T02:16:43Z","reason":"AsExpected","status":"False","type":"Degraded"},{"lastTransitionTime":"2020-11-12T21:24:43Z","reason":"AsExpected","status":"False","type":"Progressing"},{"lastTransitionTime":"2020-11-18T20:22:09Z","message":"APIServicesAvailable: \"project.openshift.io.v1\" is not ready: 503 (the server is currently unable to handle the request)","reason":"APIServices_Error","status":"False","type":"Available"},{"lastTransitionTime":"2020-10-10T14:29:24Z","reason":"AsExpected","status":"True","type":"Upgradeable"}]}}


2020-11-18T20:22:58.103282177Z I1118 20:22:58.103242       1 status_controller.go:172] clusteroperator/openshift-apiserver diff {"status":{"conditions":[{"lastTransitionTime":"2020-11-06T02:16:43Z","reason":"AsExpected","status":"False","type":"Degraded"},{"lastTransitionTime":"2020-11-12T21:24:43Z","reason":"AsExpected","status":"False","type":"Progressing"},{"lastTransitionTime":"2020-11-18T20:22:58Z","reason":"AsExpected","status":"True","type":"Available"},{"lastTransitionTime":"2020-10-10T14:29:24Z","reason":"AsExpected","status":"True","type":"Upgradeable"}]}}

# OpenShift API Server Operator goes to KubeAPI for contacting with OpenShift API servers to determine their availability. Unfortunately, we don't log these requests in the audit log.
# Nevertheless a significant number of requests targeted to OpenShift API completed with HTTP 503. From the audit logs, it looks like master-0 reported the most 503 HTTP requests.

cat master-0.all.log| jq 'select(.responseStatus.code >= 500)' | jq -s 'group_by(.responseStatus.code) | .[] | {"count": length, "status":.[0].responseStatus.code}' | jq -s 'sort_by(.count)'
cat master-0.all.log| jq 'select(.responseStatus.code == 503)' | jq -s 'group_by(.responseStatus.code, .requestURI) | .[] | {"count": length, "uri":.[0].requestURI}' | jq -s 'sort_by(.count)'


# Also, inside Kube API server there is a controller that constantly monitors aggregated APIs. Unfortunately, we also don't log these requests in the audit log but I was managed to find a few relevant errors that would suggest
# master-0 was having issues with reaching to OpenShift API servers
❯ grep -rni "failing or missing response from" namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0 | grep '2020-11-18T' | wc -l
      12
❯ grep -rni "failing or missing response from" namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-1 | grep '2020-11-18T' | wc -l
       0
❯ grep -rni "failing or missing response from" namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-3 | grep '2020-11-18T' | wc -l
       2

# It looks like master-0 wasn’t able to reach to 10.128.4.3

namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:165940:2020-11-18T19:47:45.67072588Z E1118 19:47:45.670686       1 available_controller.go:418] v1.authorization.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/authorization.openshift.io/v1: Get https://10.128.4.3:8443/apis/authorization.openshift.io/v1: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:166027:2020-11-18T19:49:45.671986126Z E1118 19:49:45.671934       1 available_controller.go:418] v1.quota.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/quota.openshift.io/v1: Get https://10.128.4.3:8443/apis/quota.openshift.io/v1: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:166389:2020-11-18T20:04:10.76684866Z E1118 20:04:10.766799       1 available_controller.go:418] v1.quota.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/quota.openshift.io/v1: Get https://10.128.4.3:8443/apis/quota.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:167856:2020-11-18T20:08:54.153046414Z E1118 20:08:54.152999       1 available_controller.go:418] v1.quota.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/quota.openshift.io/v1: Get https://10.128.4.3:8443/apis/quota.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:167857:2020-11-18T20:08:54.155318847Z E1118 20:08:54.155257       1 available_controller.go:418] v1.authorization.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/authorization.openshift.io/v1: Get https://10.128.4.3:8443/apis/authorization.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168025:2020-11-18T20:09:54.059540176Z E1118 20:09:54.059488       1 available_controller.go:418] v1.authorization.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/authorization.openshift.io/v1: Get https://10.128.4.3:8443/apis/authorization.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168026:2020-11-18T20:09:54.059720678Z E1118 20:09:54.059697       1 available_controller.go:418] v1.project.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/project.openshift.io/v1: Get https://10.128.4.3:8443/apis/project.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168101:2020-11-18T20:10:24.06164561Z E1118 20:10:24.061607       1 available_controller.go:418] v1.user.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/user.openshift.io/v1: Get https://10.128.4.3:8443/apis/user.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168102:2020-11-18T20:10:24.065635561Z E1118 20:10:24.065599       1 available_controller.go:418] v1.route.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/route.openshift.io/v1: Get https://10.128.4.3:8443/apis/route.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168103:2020-11-18T20:10:24.068584799Z E1118 20:10:24.068543       1 available_controller.go:418] v1.security.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/security.openshift.io/v1: Get https://10.128.4.3:8443/apis/security.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
namespaces/openshift-kube-apiserver/pods/kube-apiserver-cluster-q2rfm-master-0/kube-apiserver/kube-apiserver/logs/current.log:168333:2020-11-18T20:13:54.065919811Z E1118 20:13:54.065858       1 available_controller.go:418] v1.build.openshift.io failed with: failing or missing response from https://10.128.4.3:8443/apis/build.openshift.io/v1: Get https://10.128.4.3:8443/apis/build.openshift.io/v1: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)


# Interestingly, it seems that kubelet was actually able to reach the same IP (10.128.4.3) - that means that the pod was up and ready (but not for master-0)

Nov 18 19:48:39.302929 cluster-q2rfm-master-1 hyperkube[1679]: I1118 19:48:39.302895    1679 prober.go:181] HTTP-Probe Host: https://10.128.4.3, Port: 8443, Path: healthz
Nov 18 19:48:39.302929 cluster-q2rfm-master-1 hyperkube[1679]: I1118 19:48:39.302926    1679 prober.go:184] HTTP-Probe Headers: map[]
Nov 18 19:48:39.307197 cluster-q2rfm-master-1 hyperkube[1679]: I1118 19:48:39.307148    1679 http.go:128] Probe succeeded for https://10.128.4.3:8443/healthz, Response: {200 OK 200 HTTP/2.0 2 0 map[Cache-Control:[no-store] Content-Length:[2] Content-Type:[text/plain; charset=utf-8] Date:[Wed, 18 Nov 2020 19:48:39 GMT] X-Content-Type-Options:[nosniff]] 0xc0029e30c0 2 [] false false map[] 0xc00181fe00 0xc0053de6e0}

Nov 18 19:53:21.318558 cluster-q2rfm-master-1 hyperkube[1679]: I1118 19:53:21.318512    1679 http.go:128] Probe succeeded for https://10.128.4.3:8443/healthz, Response: {200 OK 200 HTTP/2.0 2 0 map[Cache-Control:[no-store] Content-Length:[2] Content-Type:[text/plain; charset=utf-8] Date:[Wed, 18 Nov 2020 19:53:21 GMT] X-Content-Type-Options:[nosniff]] 0xc0024e8640 2 [] false false map[] 0xc001594600 0xc0047913f0}


Nov 18 20:05:41.314362 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:05:41.314239    1679 prober.go:181] HTTP-Probe Host: https://10.128.4.3, Port: 8443, Path: healthz
Nov 18 20:05:41.314362 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:05:41.314277    1679 prober.go:184] HTTP-Probe Headers: map[]
Nov 18 20:05:41.318359 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:05:41.318307    1679 http.go:128] Probe succeeded for https://10.128.4.3:8443/healthz, Response: {200 OK 200 HTTP/2.0 2 0 map[Cache-Control:[no-store] Content-Length:[2] Content-Type:[text/plain; charset=utf-8] Date:[Wed, 18 Nov 2020 20:05:41 GMT] X-Content-Type-Options:[nosniff]] 0xc003413720 2 [] false false map[] 0xc0007e8c00 0xc004001c30}

Nov 18 20:09:01.314402 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:09:01.314189    1679 prober.go:181] HTTP-Probe Host: https://10.128.4.3, Port: 8443, Path: healthz
Nov 18 20:09:01.314402 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:09:01.314222    1679 prober.go:184] HTTP-Probe Headers: map[]
Nov 18 20:09:01.317921 cluster-q2rfm-master-1 hyperkube[1679]: I1118 20:09:01.317879    1679 http.go:128] Probe succeeded for https://10.128.4.3:8443/healthz, Response: {200 OK 200 HTTP/2.0 2 0 map[Cache-Control:[no-store] Content-Length:[2] Content-Type:[text/plain; charset=utf-8] Date:[Wed, 18 Nov 2020 20:09:01 GMT] X-Content-Type-Options:[nosniff]] 0xc003839720 2 [] false false map[] 0xc003abfb00 0xc0046de0b0}



# I suspect that master-0 put OpenShift API service into an unavailable state because it was partitioned possibly due to an underlying network error. To proof that we would have to change the audit policy to log more requests and reproduce the issue. Then we would be able to see exactly 
  which component did that and when.

# I would appreciate if someone from the network team could have a look and give more insights. It seems that the other replicas (master-1 and master-3) were okay and kubelet reported "10.128.4.3" as healthy whereas it was unavailable for master-0.

# I would like to know if applying  https://access.redhat.com/solutions/525283 helped to resolve the TLS errors.

> Interestingly, it seems that kubelet was actually able to reach the same IP (10.128.4.3) - that means that the pod was up and ready (but not for master-0)

This alone is a strong sign that the problem is on the network layer. Kubelet and master-1's kube-apiserver were continuously able to dial to the openshift-apiserver instance, master-0's kube-apiserver was not, and master-3 failed twice. Moving to networking for further investigation.

Hi dsilvaju,

> Yesterday night we saw this situation and applied the workaround creating the daemonset.
>
> Today I've validated the logs of the workaround and on master-1 one had one execution of the flush.

So can you confirm that you saw evidence of mtu cache flush in the logs which affirms that this is similar to https://bugzilla.redhat.com/show_bug.cgi?id=1825219? You can also share the daemonset logs with us.

Thanks!

https://bugzilla.redhat.com/show_bug.cgi?id=1899349#c5 notes that the pods run by the daemonset that monitors for the mtu and flushes it had some log messages.

If that is the case, then this is a duplicate of https://bugzilla.redhat.com/show_bug.cgi?id=1825219 and the fix they are running will completely resolve the issue.

(In reply to Abu Kashem from comment #8)
> Hi dsilvaju,
> 
> > Yesterday night we saw this situation and applied the workaround creating the daemonset.
> >
> > Today I've validated the logs of the workaround and on master-1 one had one execution of the flush.
> 
> So can you confirm that you saw evidence of mtu cache flush in the logs
> which affirms that this is similar to
> https://bugzilla.redhat.com/show_bug.cgi?id=1825219? You can also share the
> daemonset logs with us.
> 
> Thanks!

I've attached the logs of the cachefix from the master nodes.

Yes, we saw a problem with the route cache, but it was the first we saw this evidence since the problem begun.

David, have you seen any problems since you added the workaround?  If you have it applied, you will see the log messages when it fixes the bad cached MTU.

*** This bug has been marked as a duplicate of bug 1825219 ***

I've been informed that the problem has happened with the workaround in place.  Reopening.

(And, even though it seems like https://access.redhat.com/solutions/5448851 apparently that workaround has been applied already too).