Bug 1990662

In the controller pod logs I can see leader election timeout in the CSI sidecars. Not sure how it can happen 283 times, when leader election times out after 1 minute and the test ran for 2 hours, incl. installation.

E0805 19:50:20.438042       1 leaderelection.go:325] error retrieving resource lock openshift-cluster-csi-drivers/external-attacher-leader-ebs-csi-aws-com: context deadline exceeded
I0805 19:50:20.438080       1 leaderelection.go:278] failed to renew lease openshift-cluster-csi-drivers/external-attacher-leader-ebs-csi-aws-com: timed out waiting for the condition
F0805 19:50:20.438091       1 leader_election.go:209] stopped leading
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0xc000010001, 0xc0000e0100, 0x46, 0x100)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/klog/v2/klog.go:1021 +0xb9
k8s.io/klog/v2.(*loggingT).output(0x27ccaa0, 0xc000000003, 0x0, 0x0, 0xc000484540, 0x20676c8, 0x12, 0xd1, 0x40e000)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/klog/v2/klog.go:970 +0x191
k8s.io/klog/v2.(*loggingT).printDepth(0x27ccaa0, 0xc000000003, 0x0, 0x0, 0x0, 0x0, 0x1, 0xc0005ae680, 0x1, 0x1)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/klog/v2/klog.go:733 +0x16f
k8s.io/klog/v2.(*loggingT).print(...)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/klog/v2/klog.go:715
k8s.io/klog/v2.Fatal(...)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/klog/v2/klog.go:1489
github.com/kubernetes-csi/csi-lib-utils/leaderelection.(*leaderElection).Run.func2()
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/github.com/kubernetes-csi/csi-lib-utils/leaderelection/leader_election.go:209 +0xb3
k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run.func1(0xc00022eea0)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:199 +0x29
k8s.io/client-go/tools/leaderelection.(*LeaderElector).Run(0xc00022eea0, 0x1cb96a8, 0xc000308bc0)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:209 +0x167
k8s.io/client-go/tools/leaderelection.RunOrDie(0x1cb96a8, 0xc0000420a0, 0x1cc2b28, 0xc0002023c0, 0x37e11d600, 0x2540be400, 0x12a05f200, 0xc00036c1d0, 0x1b3de78, 0x1b3de80, ...)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go:222 +0x9f
github.com/kubernetes-csi/csi-lib-utils/leaderelection.(*leaderElection).Run(0xc0001f5830, 0x1c84b60, 0xc00061ef80)
	/go/src/github.com/kubernetes-csi/external-attacher/vendor/github.com/kubernetes-csi/csi-lib-utils/leaderelection/leader_election.go:222 +0x578
main.main()
	/go/src/github.com/kubernetes-csi/external-attacher/cmd/csi-attacher/main.go:264 +0x123e

Anyway, we need to tune CSI sidecar leader election for SNO.

In the linked example, but the time gathering is over there are 352 instances of restart backoffs.  Fixing leader election is good, but I'm surprised it could fail that often.

There are two issues:

1. CSI sidecars do leader election every 15 seconds. We should configure it to the new library-go defaults. That will help with upgrades and API server not available for 60 seconds.
2. We should investigate why the leader election is failing so much here, there is no upgrade in the job.

Found it. Filtering events in openshift-cluster-csi-drivers namespace, this one is the root cause:

      "count": 352,
      "involvedObject": {
        "apiVersion": "v1",
        "fieldPath": "spec.containers{resizer-kube-rbac-proxy}",
        ...
      }
      "message": "Back-off restarting failed container",

resizer-kube-rbac-proxy logs:

> failed to listen on secure address: listen tcp 0.0.0.0:9204: bind: address already in use

This was easy to miss in all other container restarts there.

Filed https://github.com/openshift/enhancements/pull/861 to declare 9200-9219 "ours".

In https://prow.ci.openshift.org/view/gs/origin-ci-test/logs/periodic-ci-openshift-release-master-ci-4.9-e2e-aws-compact/1422272449570934784, port 9205 is used

            "count": 258,
            "involvedObject": {
                "fieldPath": "spec.containers{snapshotter-kube-rbac-proxy}",
                "kind": "Pod",
                "name": "aws-ebs-csi-driver-controller-59457b97c-pdrwt",
                "namespace": "openshift-cluster-csi-drivers",
            },
            "message": "Back-off restarting failed container",

I0802 20:16:42.572187       1 main.go:315] Starting TCP socket on 0.0.0.0:9205
F0802 20:16:42.572376       1 main.go:318] failed to listen on secure address: listen tcp 0.0.0.0:9205: bind: address already in use

In https://prow.ci.openshift.org/view/gs/origin-ci-test/logs/periodic-ci-openshift-release-master-ci-4.9-e2e-aws-serial/1425261298060365824, localhost port 8205 is used

            "count": 389,
            "involvedObject": {
                "fieldPath": "spec.containers{csi-snapshotter}",
                "kind": "Pod",
                "name": "aws-ebs-csi-driver-controller-c9b6588d4-pzbdb",
                "namespace": "openshift-cluster-csi-drivers",
            },
            "message": "Back-off restarting failed container",

I0811 02:46:31.663015       1 main.go:156] ServeMux listening at "localhost:8205"
F0811 02:46:31.663425       1 main.go:159] Failed to start HTTP server at specified address ("localhost:8205") and metrics path ("/metrics"): listen tcp 127.0.0.1:8205: bind: address already in use

event happened 37 times, something is wrong: ns/openshift-cluster-csi-drivers pod/aws-ebs-csi-driver-controller-fd57888f9-9btmt node/ip-10-0-177-92.us-east-2.compute.internal - reason/BackOff Back-off restarting failed container

Happened here as well:
https://prow.ci.openshift.org/view/gs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.9-e2e-aws-single-node/1430687532244275200

Filed https://github.com/openshift/library-go/pull/1192 to get library-go changes.

We fixed leader election to be less aggressive as part of https://bugzilla.redhat.com/show_bug.cgi?id=1993931. Marking as modified for retest.
Who sometimes occupies CSI driver ports is still a mystery though.

*** Bug 2012978 has been marked as a duplicate of this bug. ***

Observed again in https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-nightly-4.8-e2e-aws-canary/1447120191006707712/artifacts/e2e-aws-canary/gather-extra/artifacts/

The container "resizer-kube-rbac-proxy":

> failed to listen on secure address: listen tcp 0.0.0.0:9204: bind: address already in use

*** Bug 2025742 has been marked as a duplicate of this bug. ***

I'm dropping 'single node' from the summary and rolling back the impacted version to 4.8, because as discussed in the dup bug 2025742, this happened in a three-control-plane, three-compute 4.8 run as well [1].

[1]: https://prow.ci.openshift.org/view/gs/origin-ci-test/pr-logs/pull/26635/pull-ci-openshift-origin-release-4.8-e2e-aws/1462876690232381440

I'm adding list of used ports on all nodes to gather-extra in https://github.com/openshift/release/pull/24908

Moving to Node team, it's something between kubelet and cri-o - some container(s) in a larger pod are started twice (or at least the symptoms look so).

A recent CI failure: https://prow.ci.openshift.org/view/gs/origin-ci-test/logs/periodic-ci-openshift-release-master-ci-4.9-upgrade-from-stable-4.8-e2e-aws-upgrade-workload/1489755737339990016

csi-liveness-probe probe can't start because port 10301 is taken: 
https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-ci-4.9-upgrade-from-stable-4.8-e2e-aws-upgrade-workload/1489755737339990016/artifacts/e2e-aws-upgrade-workload/gather-extra/artifacts/pods/openshift-cluster-csi-drivers_aws-ebs-csi-driver-controller-5b79497d8c-fskbr_csi-liveness-probe.log

> failed to start http server with error: listen tcp 0.0.0.0:10301: bind: address already in use 

The pod runs on node ip-10-0-177-78.ec2.internal. In gather-extra I can see that port 10301 is taken by the liveness probe process itself: https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/logs/periodic-ci-openshift-release-master-ci-4.9-upgrade-from-stable-4.8-e2e-aws-upgrade-workload/1489755737339990016/artifacts/e2e-aws-upgrade-workload/gather-extra/artifacts/network/ss-sdn-4cdkp

> tcp   LISTEN     0      128                                                         *:10301                           *:*      users:(("livenessprobe",pid=10338,fd=3))                                                                                                                     

There is only pod aws-ebs-csi-driver-controller-5b79497d8c-fskbr that uses the port 10301 on the node and that's the one that is crashlooping. It looks like that the csi-liveness-probe container in the pod blocks itself from starting, almost as if there were two of these containers running.

In cri-o logs, I can see that the container is indeed started twice and the second one keeps crashlooping:

$ grep  "ip-10-0-177-78.*aws-ebs-csi-driver-controller.*liveness" crio_service.log 
Feb 05 00:37:05.248511 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:05.248402817Z" level=info msg="Creating container: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=ad8ff5b3-465d-40be-8492-322a49dd07ea name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:05.375552 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:05.375513122Z" level=info msg="Created container 2356f2fc236f04d74ddde6b966cb4a91c94ed269f465d1ad0180290cfeaddc99: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=ad8ff5b3-465d-40be-8492-322a49dd07ea name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:05.386190 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:05.386150940Z" level=info msg="Started container 2356f2fc236f04d74ddde6b966cb4a91c94ed269f465d1ad0180290cfeaddc99: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=eef6ee0c-7125-435a-9e8e-504c672195b0 name=/runtime.v1alpha2.RuntimeService/StartContainer
Feb 05 00:37:33.185026 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:33.185001624Z" level=info msg="Creating container: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=9a43d77d-a783-4f55-818d-0b01f5279f73 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:33.300151 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:33.300117255Z" level=info msg="Created container 21aac6d65a008ee508df9b03f33a3df7fb27d7417dac5603b73abc5f6b1c9b82: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=9a43d77d-a783-4f55-818d-0b01f5279f73 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:33.310477 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:33.310440885Z" level=info msg="Started container 21aac6d65a008ee508df9b03f33a3df7fb27d7417dac5603b73abc5f6b1c9b82: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=c83184e0-9b4a-4208-8cab-b925d8fbdd12 name=/runtime.v1alpha2.RuntimeService/StartContainer
Feb 05 00:37:34.009279 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:34.009255014Z" level=info msg="Creating container: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=3dc1b291-95a1-49be-891f-57c94c70cb84 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:34.152139 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:34.152104506Z" level=info msg="Created container fe297b2353eae402e10af42935bf128b0c4330b6011f4b7f4dc015231d7ce2ac: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=3dc1b291-95a1-49be-891f-57c94c70cb84 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:34.161898 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:34.161851618Z" level=info msg="Started container fe297b2353eae402e10af42935bf128b0c4330b6011f4b7f4dc015231d7ce2ac: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=46058ba3-deeb-4142-9905-9e0a3079519a name=/runtime.v1alpha2.RuntimeService/StartContainer
Feb 05 00:37:35.052665 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:35.052631695Z" level=info msg="Removed container 21aac6d65a008ee508df9b03f33a3df7fb27d7417dac5603b73abc5f6b1c9b82: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=2053be4f-27d0-4621-98d4-ee34387bd5e7 name=/runtime.v1alpha2.RuntimeService/RemoveContainer
Feb 05 00:37:47.166861 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:47.166835415Z" level=info msg="Creating container: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=cfe7067e-dde5-4d1c-be12-339f5500f8f6 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:47.322769 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:47.322735645Z" level=info msg="Created container 2777c81f52297f91cb99c925acbbe5f2a162d8ccc305ace2935c4e7c1196d777: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=cfe7067e-dde5-4d1c-be12-339f5500f8f6 name=/runtime.v1alpha2.RuntimeService/CreateContainer
Feb 05 00:37:47.335170 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:47.335129196Z" level=info msg="Started container 2777c81f52297f91cb99c925acbbe5f2a162d8ccc305ace2935c4e7c1196d777: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=de1b0abd-e53b-43d5-8b59-736110284cc5 name=/runtime.v1alpha2.RuntimeService/StartContainer
Feb 05 00:37:48.113745 ip-10-0-177-78 crio[1331]: time="2022-02-05 00:37:48.113712295Z" level=info msg="Removed container fe297b2353eae402e10af42935bf128b0c4330b6011f4b7f4dc015231d7ce2ac: openshift-cluster-csi-drivers/aws-ebs-csi-driver-controller-5b79497d8c-fskbr/csi-liveness-probe" id=e07d3f0c-2b9c-4e6e-93ed-92d9a3860db6 name=/runtime.v1alpha2.RuntimeService/RemoveContainer

The first container, 2356f2fc236f04d74ddde6b966cb4a91c94ed269f465d1ad0180290cfeaddc99, never stops. The other containers are always Started and Removed quickly. Why are the other containers created at all?

There is a second aws-ebs-csi-driver-controller-5b79497d8c-hgr6x pod that uses the same port, but that one runs on node ip-10-0-192-49. Here I can see only one csi-liveness-probe container is created and everything works there.

Note that the pod itself is quite big, it has 11 containers inside. ~5 of them export a port on the node. Check the reports above, it looks like the port (= container that's started twice) is quite random.

Note to self: this shows all installations where cluster-storage-operator did not succeed: https://search.ci.openshift.org/?search=timed+out+waiting+for+the+condition+on+clusteroperators%2Fstorage&maxAge=48h&context=1&type=bug%2Bjunit&name=&excludeName=&maxMatches=5&maxBytes=20971520&groupBy=job

It needs to be filtered manually to get failed installations because of "bind: address already in use".

All I can see in the past 2 weeks is the one in comment #17 (i.e. OCP 4.8).

I haven't found any failed job in past two weeks, closing. Feel free to reopen with a link to a failed job.