after update to 4.9.0-0.okd-2022-01-29-035536 oc sometimes returns stale data

[ibotty]

Describe the bug
Many things in the cluster behave strangely. I have many CrashLoopBackoffs in openshift namespaces and not pods not starting. I assume the reason is the following phenomenon.

When getting any data via the apiserver (e.g. via oc) I sometimes get stale results.

Example:

❯ oc get node
NAME                                  STATUS   ROLES           AGE   VERSION
compute1.cluster.<redacted>   Ready    worker          71d   v1.22.3+2cb6068
compute2.cluster.<redacted>   Ready    worker          71d   v1.22.3+2cb6068
control1.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
control2.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
control3.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
❯ oc get node
NAME                                  STATUS                     ROLES           AGE   VERSION
compute1.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
compute2.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
control1.cluster.<redacted>   Ready,SchedulingDisabled   master          84d   v1.22.3+2cb6068
control2.cluster.<redacted>   Ready,SchedulingDisabled   master,worker   84d   v1.22.3+2cb6068
control3.cluster.<redacted>   Ready                      master,worker   84d   v1.22.3+2cb6068

When watching for changes, I immediatly see whether the data is stale, because I run into a too old resource version:

❯ oc get node -w
NAME                                  STATUS                     ROLES           AGE   VERSION
compute1.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
compute2.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
control1.cluster.<redacted>   Ready,SchedulingDisabled   master          84d   v1.22.3+2cb6068
control2.cluster.<redacted>   Ready,SchedulingDisabled   master,worker   84d   v1.22.3+2cb6068
control3.cluster.<redacted>   Ready                      master,worker   84d   v1.22.3+2cb6068
STATUS                                REASON                     MESSAGE
Failure                               Expired                    too old resource version: 54106678 (54439732)

This also happens when only speaking to specific nodes:

❯ oc --tls-server-name api.cluster.<redacted> -s https://control2.cluster.<redacted>:6443 get node  -w
NAME                                  STATUS   ROLES           AGE   VERSION
compute1.cluster.<redacted>   Ready    worker          71d   v1.22.3+2cb6068
compute2.cluster.<redacted>   Ready    worker          71d   v1.22.3+2cb6068
control1.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
control2.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
control3.cluster.<redacted>   Ready    master,worker   84d   v1.22.3+2cb6068
❯ oc --tls-server-name api.cluster.<redacted> -s https://control2.cluster.<redacted>:6443 get node -w
NAME                                  STATUS                     ROLES           AGE   VERSION
compute1.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
compute2.cluster.<redacted>   Ready                      worker          71d   v1.22.3+2cb6068
control1.cluster.<redacted>   Ready,SchedulingDisabled   master          84d   v1.22.3+2cb6068
control2.cluster.<redacted>   Ready,SchedulingDisabled   master,worker   84d   v1.22.3+2cb6068
control3.cluster.<redacted>   Ready                      master,worker   84d   v1.22.3+2cb6068
STATUS                                REASON                     MESSAGE
Failure                               Expired                    too old resource version: 54107742 (54442257)

(The same happens on the other control plane nodes.)

The too old resource version keeps increasing.

Version
4.9.0-0.okd-2022-01-29-035536

Log bundle

[vrutkovs]

Please attach (or upload to the public file sharing service) must-gather archive

[ibotty]

I uploaded oc logs -n openshift-cluster-version cluster-version-operator-5b857b666-g2p5l to https://fedorapeople.org/~ibotty/cluster-version-operator-5b857b666-g2p5l.log.

[vrutkovs]

Right, now it shows that kube-api is degraded. From the failing log:

2022-02-22T14:42:44.097090050Z F0222 14:42:44.096986      20 controller.go:161] Unable to perform initial IP allocation check: Operation cannot be fulfilled on serviceipallocations "": the provided resource version does not match
2022-02-22T14:42:44.218112491Z goroutine 4026 [running]:
2022-02-22T14:42:44.218112491Z k8s.io/kubernetes/vendor/k8s.io/klog/v2.stacks(0xc000010001, 0xc0013bcc30, 0xc7, 0xc9)
2022-02-22T14:42:44.218112491Z 	/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:1026 +0xb9
2022-02-22T14:42:44.218112491Z k8s.io/kubernetes/vendor/k8s.io/klog/v2.(*loggingT).output(0x87b17a0, 0xc000000003, 0x0, 0x0, 0xc000a9e230, 0x0, 0x7094558, 0xd, 0xa1, 0x0)
2022-02-22T14:42:44.218112491Z 	/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:975 +0x1e5
2022-02-22T14:42:44.218112491Z k8s.io/kubernetes/vendor/k8s.io/klog/v2.(*loggingT).printf(0x87b17a0, 0xc000000003, 0x0, 0x0, 0x0, 0x0, 0x56c646d, 0x31, 0xc00fcf4ec0, 0x1, ...)
2022-02-22T14:42:44.218112491Z 	/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:753 +0x19a

That looks like a genuine bug, please file one for kube-apiserver - https://bugzilla.redhat.com/enter_bug.cgi?product=OpenShift%20Container%20Platform&component=kube-apiserver&version=4.9 and attach the must-gather to this issue.

Try rebooting the control1 node as well, this might bring kapi up to speed?

[ibotty]

it cannot schedule many pods

That's weird, the cluster looks healthy, all nodes are running. Are they overprovisioned? Another weird thing I noticed - masters are labelled as workers, so this might put them into additional stress. With dedicated workers this is usually not advised. Try removing non-control-plane components for upgrade to complete?

I don't think that's the case.

[core@control1 ~]$ free -h
               total        used        free      shared  buff/cache   available
Mem:            15Gi       4.8Gi       3.1Gi       208Mi       7.3Gi       9.9Gi
Swap:             0B          0B          0B

The two worker nodes are running a DB that sees some heavy usage, the rest of the cluster is not doing much.

Now that I restarted the control1 node, kube-apiserver is running on that node again. It still sometimes returns stale data (as described above) though.

The openshift-machine-config-operator also crashes often. The logs can be found at https://fedorapeople.org/~ibotty/machine-config-operator-6754676c8d-5fss9.log.

[vrutkovs]

It still sometimes returns stale data (as described above) though.

This might be the result of DB pods on master :( Could you monitor for ~hour and see if it recovers?

MCD pods are crashing with:

failed to renew lease openshift-machine-config-operator/machine-config: timed out waiting for the condition

which is expected, as the API is not fully up

[ibotty]

Which API is not up? The kube-apiserver pods are Running since the reboot of that node. Anything else I can debug?

[ibotty]

Oh, the DBs are not used now that the cluster is not running and they are running not on the masters.