Bug 1934628

Sorry, I haven't looked into this BZ yet. I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint.

Ups, sorry, I haven't looked into this BZ yet. I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint.

This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that.

Sorry, I haven't looked into this BZ yet. I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint.

The LifecycleStale keyword was removed because the bug got commented on recently.
The bug assignee was notified.

I’m adding UpcomingSprint, because I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint.

This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that.

I’m adding UpcomingSprint, because I was occupied by fixing bugs with higher priority/severity, developing new features with higher priority, or developing new features to improve stability at a macro level. I will revisit this bug next sprint.

It looks like /healthz returned non 200 return code because the etcd health check failed.

For example, the check failed for kube-apiserver-ip-10-0-159-123.ec2.internal for about ~1m

2021-03-03T14:17:30.758649313Z [-]etcd failed: error getting data from etcd: context deadline exceeded
…
2021-03-03T14:18:26.813925086Z [-]etcd failed: error getting data from etcd: context deadline exceeded

during that time the API server was restarted by kubelet due to a failed liveness probe


14:18:00	openshift-kube-apiserver	kubelet	kube-apiserver-ip-10-0-159-123.ec2.internal	Killing	Container kube-apiserver failed liveness probe, will be restarted
14:19:17	openshift-kube-apiserver	apiserver	kube-apiserver-ip-10-0-159-123.ec2.internal	TerminationMinimalShutdownDurationFinished	The minimal shutdown duration of 1m10s finished


moving to etcd team to investigate why etcd was unavailable during that time

The LifecycleStale keyword was removed because the bug got commented on recently.
The bug assignee was notified.

This bug hasn't had any activity in the last 30 days. Maybe the problem got resolved, was a duplicate of something else, or became less pressing for some reason - or maybe it's still relevant but just hasn't been looked at yet. As such, we're marking this bug as "LifecycleStale" and decreasing the severity/priority. If you have further information on the current state of the bug, please update it, otherwise this bug can be closed in about 7 days. The information can be, for example, that the problem still occurs, that you still want the feature, that more information is needed, or that the bug is (for whatever reason) no longer relevant. Additionally, you can add LifecycleFrozen into Keywords if you think this bug should never be marked as stale. Please consult with bug assignee before you do that.

# etcd-ip-10-0-140-81.ec2.internal
> 2021-03-03T14:17:20.585755025Z 2021-03-03 14:17:20.585711 N | pkg/osutil: received terminated signal, shutting down...

# etcd-ip-10-0-159-123.ec2.internal
2021-03-03T14:17:27.738750499Z 2021-03-03 14:17:27.738708 W | etcdserver/api/etcdhttp: /health error; QGET failed etcdserver: request timed out (status code 503)

# etcd-ip-10-0-175-171.ec2.internal
> 2021-03-03T14:17:26.862141318Z 2021-03-03 14:17:26.862127 W | etcdserver: read-only range request "key:\"/kubernetes.io/controlplane.operator.openshift.io/podnetworkconnectivitychecks/ci-op-vjx98ktb/\" range_end:\"/kubernetes.io/controlplane.operator.openshift.io/podnetworkconnectivitychecks/ci-op-vjx98ktb0\" " with result "range_response_count:0 size:8" took too long (6.187236627s) to execute
2021-03-03T14:17:26.862263572Z 2021-03-03 14:17:26.862243 W | etcdserver: read-only range request "key:\"/kubernetes.io/poddisruptionbudgets/ci-op-nshpn573/ci-operator-created-by-ci\" " with result "range_response_count:1 size:541" took too long (6.177427407s) to execute
2021-03-03T14:17:26.872591815Z 2021-03-03 14:17:26.872533 W | etcdserver: read-only range request "key:\"/kubernetes.io/ingress/\" range_end:\"/kubernetes.io/ingress0\" limit:10000 " with result "range_response_count:1 size:1528" took too long (5.179564511s) to execute

The theory here is that kube-apiserver going down for upgrade put excessive CPU pressure on the other 2 nodes resulting in a high iowait condition. This resulted in etcd unable to make progress and timing out. The latency observed in logs is very high with many records over 2 seconds.


Another data point is the etcd instance was having to work much harder than it needed to as the backend was heavily defragmented. Defragmentation would of reclaimed about 3 GB. This would have improved write efficiency and reduced memory utilization. In 4.9 we introduced the defragmentation controller[1] to mitigate this risk.

```
$ cat etcd_info/endpoint_status.json | jq '(.[0].Status.dbSize - .[0].Status.dbSizeInUse)/1000/1000' 
3095.384064
```

Without metrics and deeper look I am not sure if we can get a true RCA, But at this point I am not sure it could be actionable. Hongkai how would you like to proceed?

[1] https://github.com/openshift/enhancements/pull/836

The LifecycleStale keyword was removed because the bug got commented on recently.
The bug assignee was notified.

Sam, Thanks for digging it up.
The issue in the bug has not happened ever since.
build01 is now with `4.8.5`.

With that being said, let us wait for the new controller from 4.9 (we are not far away from it).
I am fine with closing it now.