Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 2063138

Summary:	Draining failed on 1/3 worker during change in cloud-provider-config
Product:	OpenShift Container Platform	Reporter:	rlobillo
Component:	Node	Assignee:	Elana Hashman <ehashman>
Node sub component:	Kubelet	QA Contact:	Sunil Choudhary <schoudha>
Status:	CLOSED DUPLICATE	Docs Contact:
Severity:	high
Priority:	medium	CC:	aos-bugs
Version:	4.7
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2022-03-14 23:00:36 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description rlobillo 2022-03-11 11:01:18 UTC

Description of problem:

This is observed on D/S CI from Openshift on Openstack QE team.

In the procedure detailed on https://github.com/openshift/installer/tree/release-4.8/docs/user/openstack#enabling-octavia-for-load-balancer-services, it is required to perform a change on the cloud provider config. The configuration change is not successfully applied as one of the workers remains in SchedulingDisabled status. It was not possible to drain the node:

'''
$ omg get nodes
NAME                         STATUS                    ROLES   AGE    VERSION
ostest-mlxzh-master-1        Ready                     master  3h18m  v1.20.14+0d60930
ostest-mlxzh-master-0        Ready                     master  3h18m  v1.20.14+0d60930
ostest-mlxzh-master-2        Ready                     master  3h18m  v1.20.14+0d60930
ostest-mlxzh-worker-0-5n9j9  Ready                     worker  2h57m  v1.20.14+0d60930
ostest-mlxzh-worker-0-r5llw  Ready,SchedulingDisabled  worker  2h58m  v1.20.14+0d60930
ostest-mlxzh-worker-0-clpbp  Ready                     worker  2h56m  v1.20.14+0d60930

$ omg get node/ostest-mlxzh-worker-0-r5llw -o json | jq .metadata.annotations | grep -i drain
  "machineconfiguration.openshift.io/reason": "failed to drain node : ostest-mlxzh-worker-0-r5llw after 1 hour",

$ omg logs -n openshift-machine-config-operator -c machine-config-daemon machine-config-daemon-w45vg  | grep -i draining | head -1
2022-03-11T03:13:37.093197583Z I0311 03:13:37.093085    3200 update.go:266] Draining failed with: error when waiting for pod "ss-1" terminating: global timeout reached: 1m30s, retrying

$ omg logs -n openshift-machine-config-operator -c machine-config-daemon machine-config-daemon-w45vg  | grep -i 'failed to drain node' -B5
2022-03-11T04:05:14.926431641Z I0311 04:05:14.926293    3200 update.go:266] Draining failed with: error when waiting for pod "ss-1" terminating: global timeout reached: 1m30s, retrying
2022-03-11T04:10:15.586768685Z E0311 04:10:15.586557    3200 daemon.go:328] WARNING: ignoring DaemonSet-managed Pods: openshift-cluster-csi-drivers/openstack-cinder-csi-driver-node-jqfzf, openshift-cluster-node-tuning-operator/tuned-jhdzb, openshift-dns/dns-default-8jcnl, openshift-image-registry/node-ca-79w4d, openshift-ingress-canary/ingress-canary-nqbrn, openshift-machine-config-operator/machine-config-daemon-w45vg, openshift-manila-csi-driver/csi-nodeplugin-nfsplugin-82d74, openshift-manila-csi-driver/openstack-manila-csi-nodeplugin-btzzh, openshift-monitoring/node-exporter-jv2hb, openshift-multus/multus-q4ttr, openshift-multus/network-metrics-daemon-vjmmp, openshift-network-diagnostics/network-check-target-js5z2, openshift-sdn/sdn-sws5x
2022-03-11T04:10:15.591238747Z I0311 04:10:15.591198    3200 daemon.go:328] evicting pod e2e-statefulset-2878/ss-1
2022-03-11T04:11:45.611583967Z I0311 04:11:45.611313    3200 update.go:266] Draining failed with: error when waiting for pod "ss-1" terminating: global timeout reached: 1m30s, retrying
2022-03-11T04:12:06.315485126Z I0311 04:12:06.315335    3200 update.go:1998] Removing SIGTERM protection
2022-03-11T04:12:06.315485126Z E0311 04:12:06.315424    3200 writer.go:135] Marking Degraded due to: failed to drain node : ostest-mlxzh-worker-0-r5llw after 1 hour
'''

We obtained the adm-logs too, and we observed below errors in the problematic worker taking place some time before the cloud-config configuration change was triggered in our automation. The automation was running conformance on the cluster at that moment:

Mar 11 02:29:58.824988 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: E0311 02:29:58.824894    1862 kuberuntime_sandbox.go:70] CreatePodSandbox for pod "ss-1_e2e-statefulset-2878(94e0b665-19b5-488f-9983-6a0520cf2210)" failed: rpc error: code = Unknown desc = error reading container (probably exited) json message: EOF
Mar 11 02:29:59.196340 ostest-mlxzh-worker-0-r5llw systemd[1]: var-lib-containers-storage-overlay-081cc45ca306ebba0797107bb38c990dc6437bd0bc1a2ebdf0ce033348705719-merged.mount: Succeeded.
Mar 11 02:29:59.196374 ostest-mlxzh-worker-0-r5llw systemd[1]: run-netns-ff83b39a\x2dd3f0\x2d4afd\x2dbecf\x2dda037fa52f78.mount: Succeeded.
Mar 11 02:29:59.196382 ostest-mlxzh-worker-0-r5llw systemd[1]: run-ipcns-ff83b39a\x2dd3f0\x2d4afd\x2dbecf\x2dda037fa52f78.mount: Succeeded.
Mar 11 02:29:59.196390 ostest-mlxzh-worker-0-r5llw systemd[1]: run-utsns-ff83b39a\x2dd3f0\x2d4afd\x2dbecf\x2dda037fa52f78.mount: Succeeded.
Mar 11 02:29:59.196398 ostest-mlxzh-worker-0-r5llw systemd[1]: run-containers-storage-overlay\x2dcontainers-5ddd115972f3ca7f4ba9f874f787fcd12260404091d17f39e19421c3c34b4a5d-userdata-shm.mount: Succeeded.
Mar 11 02:29:59.540009 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: time="2022-03-11T02:29:59Z" level=warning msg="Timed out while waiting for StopUnit(kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice) completion signal from dbus. Continuing..."
Mar 11 02:29:59.706767 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: W0311 02:29:59.706688    1862 pod_container_manager_linux.go:198] failed to delete cgroup paths for [kubepods besteffort pod94e0b665-19b5-488f-9983-6a0520cf2210] : unable to destroy cgroup paths for cgroup [kubepods besteffort pod94e0b665-19b5-488f-9983-6a0520cf2210] : Failed to remove paths: map[blkio:/sys/fs/cgroup/blkio/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice cpu:/sys/fs/cgroup/cpu,cpuacct/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice cpuacct:/sys/fs/cgroup/cpu,cpuacct/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice cpuset:/sys/fs/cgroup/cpuset/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice devices:/sys/fs/cgroup/devices/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice freezer:/sys/fs/cgroup/freezer/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice hugetlb:/sys/fs/cgroup/hugetlb/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice memory:/sys/fs/cgroup/memory/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice net_cls:/sys/fs/cgroup/net_cls,net_prio/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice net_prio:/sys/fs/cgroup/net_cls,net_prio/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice perf_event:/sys/fs/cgroup/perf_event/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice pids:/sys/fs/cgroup/pids/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice systemd:/sys/fs/cgroup/systemd/kubepods.slice/kubepods-besteffort.slice/kubepods-besteffort-pod94e0b665_19b5_488f_9983_6a0520cf2210.slice]



Version-Release number of selected component (if applicable):
4.7.0-0.nightly-2022-03-10-191639
RHOS-16.1-RHEL-8-20211126.n.1

How reproducible: Sometimes. We observed a similar behaviour in 4.8 too, but last CI run worked fine. So we think the same is happening in 4.8 but the error is not persistent.


Steps to Reproduce:
1. Install OCP4.7 on top of OSP16.1 (RHOS-16.1-RHEL-8-20211126.n.1) with regular IPI intallation.
2. Run conformance tests.
3. Perform a change in cloud provider config.

Actual results: It is not possible to drain the worker and the cloud provider config should be applied in all the cluster. 
Expected results: Cloud provider config changes should be applied to all the workers in the cluster.
Additional info: Attached must-gather and oc adm node logs in the link provided as private command.

Comment 2 Elana Hashman 2022-03-14 22:15:13 UTC

Not a blocker, 4.7 is already released.

Comment 3 Elana Hashman 2022-03-14 23:00:36 UTC

Pod is created and immediately deleted <1s later:

Mar 11 02:29:56.125748 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.124190    1862 kubelet.go:1919] SyncLoop (ADD, "api"): "ss-1_e2e-statefulset-2878(94e0b665-19b5-488f-9983-6a0520cf2210)"
Mar 11 02:29:56.125748 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.124328    1862 topology_manager.go:187] [topologymanager] Topology Admit Handler
Mar 11 02:29:56.125748 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.124650    1862 reflector.go:219] Starting reflector *v1.Secret (0s) from object-"e2e-statefulset-2878"/"default-dockercfg-vsgxz"
Mar 11 02:29:56.125748 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.124977    1862 reflector.go:219] Starting reflector *v1.Secret (0s) from object-"e2e-statefulset-2878"/"default-token-72b9p"
Mar 11 02:29:56.147751 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.145780    1862 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-72b9p" (UniqueName: "kubernetes.io/secret/94e0b665-19b5-488f-9983-6a0520cf2210-default-token-72b9p") pod "ss-1" (UID: "94e0b665-19b5-488f-9983-6a0520cf2210")
Mar 11 02:29:56.233952 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:56.232860    1862 kubelet.go:1935] SyncLoop (DELETE, "api"): "ss-1_e2e-statefulset-2878(94e0b665-19b5-488f-9983-6a0520cf2210)"


Pod never is successfully torn down. DELETE is called but not REMOVE:

Mar 11 02:29:58.429850 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: I0311 02:29:58.427495    1862 kubelet.go:1935] SyncLoop (DELETE, "api"): "ss-1_e2e-statefulset-2878(94e0b665-19b5-488f-9983
-6a0520cf2210)"
Mar 11 02:29:58.824988 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: E0311 02:29:58.824682    1862 remote_runtime.go:116] RunPodSandbox from runtime service failed: rpc error: code = Unknown d
esc = error reading container (probably exited) json message: EOF
Mar 11 02:29:58.824988 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: E0311 02:29:58.824894    1862 kuberuntime_sandbox.go:70] CreatePodSandbox for pod "ss-1_e2e-statefulset-2878(94e0b665-19b5-
488f-9983-6a0520cf2210)" failed: rpc error: code = Unknown desc = error reading container (probably exited) json message: EOF
Mar 11 02:44:58.497743 ostest-mlxzh-worker-0-r5llw hyperkube[1862]: E0311 02:44:58.496900    1862 fsHandler.go:114] failed to collect filesystem stats - rootDiskErr: could not stat "/var/lib/containers/storage/overlay/081cc45ca306ebba0797107bb38c990dc6437bd0bc1a2ebdf0ce033348705719/diff" to get inode usage: stat /var/lib/containers/storage/overlay/081cc45ca306ebba0797107bb38c990dc6437bd0bc1a2ebdf0ce033348705719/diff: no such file or directory, extraDiskErr: could not stat "/var/log/pods/e2e-statefulset-2878_ss-1_94e0b665-19b5-488f-9983-6a0520cf2210/5ddd115972f3ca7f4ba9f874f787fcd12260404091d17f39e19421c3c34b4a5d.log" to get inode usage: stat /var/log/pods/e2e-statefulset-2878_ss-1_94e0b665-19b5-488f-9983-6a0520cf2210/5ddd115972f3ca7f4ba9f874f787fcd12260404091d17f39e19421c3c34b4a5d.log: no such file or directory



This appears to be a duplicate of the behaviour reported in https://bugzilla.redhat.com/show_bug.cgi?id=1912880#c4

This should be fixed in #1915085.

Not ideal, but it is typically safe to force delete the affected pod to get the drain unstuck, per https://bugzilla.redhat.com/show_bug.cgi?id=1915085#c22

Is it possible to avoid creating pods and deleting them <1s later? This would also avoid triggering the race condition that causes the issue.


We did receive a report (https://bugzilla.redhat.com/show_bug.cgi?id=1915085#c34) that the frequency of the bug still occasionally affects workloads, but this should be fully fixed by 1.22/OpenShift 4.9 with the pod lifecycle refactor.

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