ceph / ceph/ceph-csi

e2e: ceph-fuse mounts getting stuck in NodeUnpublishVolume

Open
#2,899 1 comment 0 reactions 0 assignees View on GitHub
keepalive
Dominant language
Go
Stars
1.6k
Forks
617
Avg merge
5d 10h
Merged PRs (30d)
43

Description

# Describe the bug #

I've seen numerous times cephfs-csi CI jobs that use ceph-fuse report this or similar error:

```
• Failure [890.616 seconds]
cephfs
/go/src/github.com/ceph/ceph-csi/e2e/cephfs.go:191
Test CephFS CSI
/go/src/github.com/ceph/ceph-csi/e2e/cephfs.go:279
Test CephFS CSI [It]
/go/src/github.com/ceph/ceph-csi/e2e/cephfs.go:280

Feb 21 17:45:47.576: failed to validate CephFS pvc and application binding: timed out waiting for the condition

/go/src/github.com/ceph/ceph-csi/e2e/cephfs.go:480
```

[Link to the CI run report](https://jenkins-ceph-csi.apps.ocp.ci.centos.org/blue/organizations/jenkins/mini-e2e-helm_k8s-1.21/detail/mini-e2e-helm_k8s-1.21/2871/pipeline/)

[Link to the e2e job](https://github.com/ceph/ceph-csi/blob/f19ca4a473400845704762c92972a917caa8ba3a/e2e/cephfs.go#L470-L486)

Name of the PV it created: `pvc-749160bf-c48f-4bf0-b66a-a96070630c4f`

Excerpt from node plugin logs:

```
I0221 17:35:43.268786 1 utils.go:202] ID: 36 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
I0221 17:35:43.276574 1 utils.go:191] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC call: /csi.v1.Node/NodeStageVolume
I0221 17:35:43.276855 1 utils.go:195] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/globalmount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["debug"]}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"baca99e2-7cad-4d65-b810-49ba97edd7ca","csi.storage.k8s.io/pv/name":"pvc-749160bf-c48f-4bf0-b66a-a96070630c4f","csi.storage.k8s.io/pvc/name":"csi-cephfs-pvc","csi.storage.k8s.io/pvc/namespace":"cephfs-8081","fsName":"myfs","mounter":"fuse","pool":"myfs-replicated","storage.kubernetes.io/csiProvisionerIdentity":"1645464641229-8081-cephfs.csi.ceph.com","subvolumeName":"csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30","subvolumePath":"/volumes/e2e/csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30/133f5346-9b24-475e-92ed-49fdf87f6297"},"volume_id":"0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30"}
I0221 17:35:43.281328 1 omap.go:87] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 got omap values: (pool="myfs-metadata", namespace="csi", name="csi.volume.ac0d7020-933c-11ec-90d2-bee632347b30"): map[csi.imagename:csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30 csi.volname:pvc-749160bf-c48f-4bf0-b66a-a96070630c4f]
I0221 17:35:43.302740 1 mount_linux.go:218] Cannot run systemd-run, assuming non-systemd OS
I0221 17:35:43.302772 1 mount_linux.go:219] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
Failed to create bus connection: Host is down
, failed with: exit status 1
I0221 17:35:43.302953 1 nodeserver.go:164] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 cephfs: mounting volume 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 with Ceph FUSE driver
I0221 17:35:43.387335 1 cephcmds.go:63] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 command succeeded: ceph-fuse [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/globalmount -m rook-ceph-mon-a.rook-ceph.svc.cluster.local:6789 -c /etc/ceph/ceph.conf -n client.cephcsi-cephfs-node --keyfile=***stripped*** -r /volumes/e2e/csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30/133f5346-9b24-475e-92ed-49fdf87f6297 -o nonempty --client_mds_namespace=myfs]
I0221 17:35:43.387495 1 nodeserver.go:140] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 cephfs: successfully mounted volume 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 to /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/globalmount
I0221 17:35:43.387552 1 utils.go:202] ID: 37 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC response: {}
I0221 17:35:43.393738 1 utils.go:191] ID: 38 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0221 17:35:43.393873 1 utils.go:195] ID: 38 GRPC request: {}
I0221 17:35:43.394037 1 utils.go:202] ID: 38 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
I0221 17:35:43.398887 1 utils.go:191] ID: 39 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC call: /csi.v1.Node/NodePublishVolume
I0221 17:35:43.399293 1 utils.go:195] ID: 39 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/globalmount","target_path":"/var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount","volume_capability":{"AccessType":{"Mount":{"mount_flags":["debug"]}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"baca99e2-7cad-4d65-b810-49ba97edd7ca","csi.storage.k8s.io/pv/name":"pvc-749160bf-c48f-4bf0-b66a-a96070630c4f","csi.storage.k8s.io/pvc/name":"csi-cephfs-pvc","csi.storage.k8s.io/pvc/namespace":"cephfs-8081","fsName":"myfs","mounter":"fuse","pool":"myfs-replicated","storage.kubernetes.io/csiProvisionerIdentity":"1645464641229-8081-cephfs.csi.ceph.com","subvolumeName":"csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30","subvolumePath":"/volumes/e2e/csi-vol-ac0d7020-933c-11ec-90d2-bee632347b30/133f5346-9b24-475e-92ed-49fdf87f6297"},"volume_id":"0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30"}
I0221 17:35:43.408303 1 mount_linux.go:218] Cannot run systemd-run, assuming non-systemd OS
I0221 17:35:43.408382 1 mount_linux.go:219] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
Failed to create bus connection: Host is down
, failed with: exit status 1
I0221 17:35:43.413521 1 cephcmds.go:63] ID: 39 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 command succeeded: mount [-o bind,_netdev,debug /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/globalmount /var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount]
I0221 17:35:43.413592 1 nodeserver.go:250] ID: 39 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 cephfs: successfully bind-mounted volume 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 to /var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount
I0221 17:35:43.413749 1 utils.go:202] ID: 39 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC response: {}
I0221 17:35:49.119431 1 utils.go:191] ID: 40 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC call: /csi.v1.Node/NodeUnpublishVolume
I0221 17:35:49.119545 1 utils.go:195] ID: 40 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC request: {"target_path":"/var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount","volume_id":"0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30"}
I0221 17:35:49.129329 1 mount_linux.go:218] Cannot run systemd-run, assuming non-systemd OS
I0221 17:35:49.129357 1 mount_linux.go:219] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
Failed to create bus connection: Host is down
, failed with: exit status 1
I0221 17:36:14.721583 1 utils.go:191] ID: 41 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0221 17:36:14.721662 1 utils.go:195] ID: 41 GRPC request: {}
I0221 17:36:14.721798 1 utils.go:202] ID: 41 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":5}}}]}
I0221 17:36:14.723589 1 utils.go:191] ID: 42 GRPC call: /csi.v1.Node/NodeGetVolumeStats
I0221 17:36:14.723917 1 utils.go:195] ID: 42 GRPC request: {"volume_id":"0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30","volume_path":"/var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount"}
I0221 17:36:14.734975 1 mount_linux.go:218] Cannot run systemd-run, assuming non-systemd OS
I0221 17:36:14.735080 1 mount_linux.go:219] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
Failed to create bus connection: Host is down
, failed with: exit status 1
I0221 17:36:33.638906 1 utils.go:191] ID: 43 GRPC call: /csi.v1.Identity/Probe
I0221 17:36:33.639186 1 utils.go:195] ID: 43 GRPC request: {}
I0221 17:36:33.639319 1 utils.go:202] ID: 43 GRPC response: {}
I0221 17:37:33.638742 1 utils.go:191] ID: 44 GRPC call: /csi.v1.Identity/Probe
I0221 17:37:33.638825 1 utils.go:195] ID: 44 GRPC request: {}
I0221 17:37:33.638853 1 utils.go:202] ID: 44 GRPC response: {}
I0221 17:37:49.713570 1 utils.go:191] ID: 45 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC call: /csi.v1.Node/NodeUnpublishVolume
I0221 17:37:49.713711 1 utils.go:195] ID: 45 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC request: {"target_path":"/var/lib/kubelet/pods/91c1a052-347f-4d43-8f98-0fc8434aa263/volumes/kubernetes.io~csi/pvc-749160bf-c48f-4bf0-b66a-a96070630c4f/mount","volume_id":"0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30"}
I0221 17:37:49.724594 1 mount_linux.go:218] Cannot run systemd-run, assuming non-systemd OS
I0221 17:37:49.724694 1 mount_linux.go:219] systemd-run output: System has not been booted with systemd as init system (PID 1). Can't operate.
Failed to create bus connection: Host is down
, failed with: exit status 1
I0221 17:38:33.638473 1 utils.go:191] ID: 46 GRPC call: /csi.v1.Identity/Probe
I0221 17:38:33.638555 1 utils.go:195] ID: 46 GRPC request: {}
I0221 17:38:33.638701 1 utils.go:202] ID: 46 GRPC response: {}
I0221 17:39:33.638524 1 utils.go:191] ID: 47 GRPC call: /csi.v1.Identity/Probe
I0221 17:39:33.638790 1 utils.go:195] ID: 47 GRPC request: {}
I0221 17:39:33.639088 1 utils.go:202] ID: 47 GRPC response: {}
I0221 17:39:50.816472 1 utils.go:191] ID: 48 Req-ID: 0001-0024-baca99e2-7cad-4d65-b810-49ba97edd7ca-0000000000000001-ac0d7020-933c-11ec-90d2-bee632347b30 GRPC call: /csi.v1.Node/NodeUnpublishVolume
```

You can see that GRPC call ID 40 `NodeUnpublishVolume is the first attempt to unbind the volume. It never finishes however, and kubelet continues to try to unpublish the volume, but none of the calls ever return, making the CI job time out and fail.

Is the cause for this problem known?

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.