Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CephFS PVs cannot unmount when the same volume is mounted twice on the same node. #2238

Closed
ikogan opened this issue Jul 1, 2021 · 34 comments
Assignees
Labels
component/cephfs Issues related to CephFS dependency/k8s depends on Kubernetes features wontfix This will not be worked on

Comments

@ikogan
Copy link

ikogan commented Jul 1, 2021

Describe the bug

When two (or possibly more) ReadWriteMany PVs are used to attach the same CephFS volume or subvolume on the same node, these volumes will be stuck unable to unmount due to:

3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-25 01:12:35.184818115 +0000 UTC m=+773997.882937495 (durationBeforeRetry 2m2s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/89b628b6-b78a-4cb3-bea4-ada4ce6d0ea2/volumes/kubernetes.io~csi/offsite-backup/mount

In my case, here are the two mounts:

10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)
10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/pods/89b628b6-b78a-4cb3-bea4-ada4ce6d0ea2/volumes/kubernetes.io~csi/cephfs-snapshot/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)

This also happens with subvolumes. So when I try to mount /volumes/shared twice on the same node, the same problem occurs when one of those workloads stops. This is most obvious with cronjobs but replicas will do this too the moment the pod using the PV is stopped.

Environment details

  • Image/version of Ceph CSI driver : quay.io/cephcsi/cephcsi:v3.3.1
  • Helm chart version : rook-ceph:1.6.5
  • Kernel version : Linux k8s-worker-5 5.4.0-42-generic #46-Ubuntu SMP Fri Jul 10 00:24:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
  • Mounter used for mounting PVC (for cephfs its fuse or kernel. for rbd its
    krbd or rbd-nbd) : kernel
  • Kubernetes cluster version : Server Version: version.Info{Major:"1", Minor:"19", GitVersion:"v1.19.7", GitCommit:"1dd5338295409edcfff11505e7bb246f0d325d15", GitTreeState:"clean", BuildDate:"2021-01-13T13:15:20Z", GoVersion:"go1.15.5", Compiler:"gc", Platform:"linux/amd64"}
  • Ceph cluster version : ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable)

Steps to reproduce

Steps to reproduce the behavior:

  1. Create a CephFS Volume
  2. Create two ReadWriteMany PVs and associated PVCs and workloads such that they both schedule on the same node.
  3. Delete the workloads. You shouldn't have to delete the PVCs and PVs but deleting them will not fix the issue.
  4. Check the mounts on the node and notice that they're still there. Look in the kubelet log and notice the "The device mount path X is still mounted by other references".

Actual results

The CephFS mounts on the node remain forever and the log message appears continually as the kubelet tries to unmount each volume repeatedly. Notably, this does not prevent starting these workloads again on the same node as far as I've seen. The VolumeAttachment the PVs were using remain forever as well.

Expected behavior

The CephFS mounts should be properly unmounted from the node when they are no longer needed and the VolumeAttachment objects should be properly removed. Errors should not continue to appear forever in logs.

Logs

Unfortunately I don't have the csi logs at the moment but I'll try to update with those when I have a chance to replicate this. Here are some relevant Kubelet logs:

{"log":"I0624 23:00:00.377256    3568 topology_manager.go:233] [topologymanager] Topology Admit Handler\n","stream":"stderr","time":"2021-06-24T23:00:00.377925868Z"}
{"log":"I0624 23:00:00.454567    3568 kubelet.go:1830] SyncLoop (ADD, \"api\"): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\"\n","stream":"stderr","time":"2021-06-24T23:00:00.454795089Z"}
{"log":"I0624 23:00:00.454724    3568 topology_manager.go:233] [topologymanager] Topology Admit Handler\n","stream":"stderr","time":"2021-06-24T23:00:00.455041084Z"}
{"log":"I0624 23:00:00.454763    3568 reflector.go:207] Starting reflector *v1.Secret (0s) from object-\"rook-ceph\"/\"local\"\n","stream":"stderr","time":"2021-06-24T23:00:00.45506415Z"}
{"log":"I0624 23:00:00.454884    3568 reflector.go:207] Starting reflector *v1.ConfigMap (0s) from object-\"rook-ceph\"/\"ceph-snapshot-schedule\"\n","stream":"stderr","time":"2021-06-24T23:00:00.455257507Z"}
{"log":"I0624 23:00:00.454777    3568 reflector.go:207] Starting reflector *v1.Secret (0s) from object-\"rook-ceph\"/\"default-token-75rjf\"\n","stream":"stderr","time":"2021-06-24T23:00:00.455272909Z"}
{"log":"I0624 23:00:01.078168    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"default-token-75rjf\" (UniqueName: \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:01.078440245Z"}
{"log":"I0624 23:00:01.078404    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:01.078512328Z"}
{"log":"E0624 23:00:01.078569    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:01.578480045 +0000 UTC m=+766044.276599415 (durationBeforeRetry 500ms). Error: \"Volume has not been added to the list of VolumesInUse in the node's volume status for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") pod \\\"cephfs-snapshot-1624575600-v8ntn\\\" (UID: \\\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\\\") \"\n","stream":"stderr","time":"2021-06-24T23:00:01.078742012Z"}
{"log":"I0624 23:00:01.178864    3568 reconciler.go:269] operationExecutor.MountVolume started for volume \"default-token-75rjf\" (UniqueName: \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:01.179141074Z"}
{"log":"I0624 23:00:01.181734    3568 operation_generator.go:663] MountVolume.SetUp succeeded for volume \"default-token-75rjf\" (UniqueName: \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:01.181873756Z"}
{"log":"I0624 23:00:01.581055    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:01.581311826Z"}
{"log":"E0624 23:00:01.581300    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:02.581228609 +0000 UTC m=+766045.279347994 (durationBeforeRetry 1s). Error: \"Volume has not been added to the list of VolumesInUse in the node's volume status for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") pod \\\"cephfs-snapshot-1624575600-v8ntn\\\" (UID: \\\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\\\") \"\n","stream":"stderr","time":"2021-06-24T23:00:01.581403135Z"}
{"log":"E0624 23:00:01.643637    3568 dns.go:135] Nameserver limits were exceeded, some nameservers have been omitted, the applied nameserver line is: 10.1.42.11 10.1.42.12 10.10.0.7\n","stream":"stderr","time":"2021-06-24T23:00:01.643878511Z"}
{"log":"I0624 23:00:02.586441    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:02.586703322Z"}
{"log":"E0624 23:00:02.586745    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:04.586676834 +0000 UTC m=+766047.284796230 (durationBeforeRetry 2s). Error: \"Volume has not been added to the list of VolumesInUse in the node's volume status for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") pod \\\"cephfs-snapshot-1624575600-v8ntn\\\" (UID: \\\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\\\") \"\n","stream":"stderr","time":"2021-06-24T23:00:02.586899124Z"}
{"log":"I0624 23:00:03.207012    3568 streamwatcher.go:114] Unexpected EOF during watch stream event decoding: unexpected EOF\n","stream":"stderr","time":"2021-06-24T23:00:03.207553539Z"}
{"log":"I0624 23:00:03.590178    3568 topology_manager.go:219] [topologymanager] RemoveContainer - Container ID: 18896cc9a298dcfe65634509eb6deb59923f0484b5097b115aa6ba43a3052df3\n","stream":"stderr","time":"2021-06-24T23:00:03.59032184Z"}
{"log":"I0624 23:00:04.594904    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:04.595143553Z"}
{"log":"E0624 23:00:04.595066    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:08.595004779 +0000 UTC m=+766051.293124152 (durationBeforeRetry 4s). Error: \"Volume has not been added to the list of VolumesInUse in the node's volume status for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") pod \\\"cephfs-snapshot-1624575600-v8ntn\\\" (UID: \\\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\\\") \"\n","stream":"stderr","time":"2021-06-24T23:00:04.595195735Z"}
{"log":"I0624 23:00:05.656736    3568 topology_manager.go:219] [topologymanager] RemoveContainer - Container ID: 18896cc9a298dcfe65634509eb6deb59923f0484b5097b115aa6ba43a3052df3\n","stream":"stderr","time":"2021-06-24T23:00:05.656820926Z"}
{"log":"I0624 23:00:05.656907    3568 topology_manager.go:219] [topologymanager] RemoveContainer - Container ID: cb709eb507aa01e55c9d02395f209322dff81b73d9d54ba2778b246c2f67033e\n","stream":"stderr","time":"2021-06-24T23:00:05.657041529Z"}
{"log":"I0624 23:00:05.801135    3568 reconciler.go:196] operationExecutor.UnmountVolume started for volume \"default-token-8c5pm\" (UniqueName: \"kubernetes.io/secret/e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3-default-token-8c5pm\") pod \"e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3\" (UID: \"e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3\") \n","stream":"stderr","time":"2021-06-24T23:00:05.8013881Z"}
{"log":"I0624 23:00:05.804318    3568 operation_generator.go:788] UnmountVolume.TearDown succeeded for volume \"kubernetes.io/secret/e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3-default-token-8c5pm\" (OuterVolumeSpecName: \"default-token-8c5pm\") pod \"e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3\" (UID: \"e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3\"). InnerVolumeSpecName \"default-token-8c5pm\". PluginName \"kubernetes.io/secret\", VolumeGidValue \"\"\n","stream":"stderr","time":"2021-06-24T23:00:05.804518659Z"}
{"log":"I0624 23:00:05.902020    3568 reconciler.go:319] Volume detached for volume \"default-token-8c5pm\" (UniqueName: \"kubernetes.io/secret/e8b91d55-3f78-4cbc-85ff-be24eb5ed6a3-default-token-8c5pm\") on node \"k8s-worker-5\" DevicePath \"\"\n","stream":"stderr","time":"2021-06-24T23:00:05.902186937Z"}
{"log":"I0624 23:00:06.648903    3568 kuberuntime_container.go:635] Killing container \"docker://cb709eb507aa01e55c9d02395f209322dff81b73d9d54ba2778b246c2f67033e\" with a 30 second grace period\n","stream":"stderr","time":"2021-06-24T23:00:06.649028417Z"}
{"log":"W0624 23:00:06.683357    3568 pod_container_deletor.go:79] Container \"72f62eaeaa73627aa0b59a2bcf063da9e9e59b917f06939ca7508a4b24fab131\" not found in pod's containers\n","stream":"stderr","time":"2021-06-24T23:00:06.683536023Z"}
{"log":"I0624 23:00:08.611624    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:08.61186974Z"}
{"log":"E0624 23:00:08.611764    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:16.611705925 +0000 UTC m=+766059.309825395 (durationBeforeRetry 8s). Error: \"Volume has not been added to the list of VolumesInUse in the node's volume status for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") pod \\\"cephfs-snapshot-1624575600-v8ntn\\\" (UID: \\\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\\\") \"\n","stream":"stderr","time":"2021-06-24T23:00:08.61189224Z"}
{"log":"I0624 23:00:15.872682    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:15.873009605Z"}
{"log":"I0624 23:00:15.872704    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:15.873049345Z"}
{"log":"I0624 23:00:15.872743    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.rbd.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.873057553Z"}
{"log":"I0624 23:00:15.872753    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:15.873064906Z"}
{"log":"I0624 23:00:15.872794    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:15.873069483Z"}
{"log":"I0624 23:00:15.872812    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002328c30, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.873073407Z"}
{"log":"I0624 23:00:15.873155    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002328c30, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.873318882Z"}
{"log":"I0624 23:00:15.873887    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:15.874025185Z"}
{"log":"I0624 23:00:15.873907    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:15.874048718Z"}
{"log":"I0624 23:00:15.873924    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.rbd.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.874056883Z"}
{"log":"I0624 23:00:15.873932    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:15.874064326Z"}
{"log":"I0624 23:00:15.873955    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:15.874070659Z"}
{"log":"I0624 23:00:15.873893    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:15.874081657Z"}
{"log":"I0624 23:00:15.874100    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0023290b0, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.874218667Z"}
{"log":"I0624 23:00:15.874274    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0023290b0, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:15.874396242Z"}
{"log":"I0624 23:00:15.882636    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:15.882778379Z"}
{"log":"I0624 23:00:16.644814    3568 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:16.645100842Z"}
{"log":"I0624 23:00:16.649652    3568 operation_generator.go:1348] Controller attach succeeded for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") device path: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.649792261Z"}
{"log":"I0624 23:00:16.745284    3568 reconciler.go:269] operationExecutor.MountVolume started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:16.745544683Z"}
{"log":"I0624 23:00:16.745626    3568 operation_generator.go:558] MountVolume.WaitForAttach entering for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") DevicePath \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.745794718Z"}
{"log":"I0624 23:00:16.750017    3568 operation_generator.go:567] MountVolume.WaitForAttach succeeded for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") DevicePath \"csi-225af1b82c928c791922af9189702d68cbd12844b13a32dd8458a635aff88dff\"\n","stream":"stderr","time":"2021-06-24T23:00:16.750220225Z"}
{"log":"I0624 23:00:16.750272    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.750467649Z"}
{"log":"I0624 23:00:16.750303    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:16.750485603Z"}
{"log":"I0624 23:00:16.750320    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.cephfs.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.750492187Z"}
{"log":"I0624 23:00:16.750330    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:16.750513769Z"}
{"log":"I0624 23:00:16.750374    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:16.750519618Z"}
{"log":"I0624 23:00:16.750412    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002666a40, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.750524834Z"}
{"log":"I0624 23:00:16.750983    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002666a40, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.751150652Z"}
{"log":"I0624 23:00:16.751918    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:16.752029379Z"}
{"log":"I0624 23:00:16.759246    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.759427933Z"}
{"log":"I0624 23:00:16.759279    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:16.75944273Z"}
{"log":"I0624 23:00:16.759294    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.cephfs.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.759446981Z"}
{"log":"I0624 23:00:16.759300    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:16.759451276Z"}
{"log":"I0624 23:00:16.759356    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:16.759467142Z"}
{"log":"I0624 23:00:16.759410    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0026670b0, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.759481715Z"}
{"log":"I0624 23:00:16.759773    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0026670b0, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.759883849Z"}
{"log":"I0624 23:00:16.789406    3568 operation_generator.go:596] MountVolume.MountDevice succeeded for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") device mount path \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\"\n","stream":"stderr","time":"2021-06-24T23:00:16.789641707Z"}
{"log":"I0624 23:00:16.789516    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:16.789681224Z"}
{"log":"I0624 23:00:16.794440    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.794656349Z"}
{"log":"I0624 23:00:16.794463    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:16.794680954Z"}
{"log":"I0624 23:00:16.794497    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.cephfs.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.794685778Z"}
{"log":"I0624 23:00:16.794506    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:16.794690818Z"}
{"log":"I0624 23:00:16.794576    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:16.79476636Z"}
{"log":"I0624 23:00:16.794774    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0031e3440, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.794804153Z"}
{"log":"I0624 23:00:16.795164    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc0031e3440, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.795427525Z"}
{"log":"I0624 23:00:16.795808    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:16.795985696Z"}
{"log":"I0624 23:00:16.799595    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:16.799801855Z"}
{"log":"I0624 23:00:16.799630    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:16.799829354Z"}
{"log":"I0624 23:00:16.799647    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.cephfs.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.799833817Z"}
{"log":"I0624 23:00:16.799654    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:16.799838692Z"}
{"log":"I0624 23:00:16.799720    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:16.799842903Z"}
{"log":"I0624 23:00:16.799758    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002667630, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.799860207Z"}
{"log":"I0624 23:00:16.800061    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc002667630, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:16.80016665Z"}
{"log":"I0624 23:00:16.809482    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:16.810761097Z"}
{"log":"I0624 23:00:16.811821    3568 operation_generator.go:663] MountVolume.SetUp succeeded for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"cephfs-snapshot-1624575600-v8ntn\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:16.812026872Z"}
{"log":"I0624 23:00:17.009534    3568 kuberuntime_manager.go:425] No sandbox for pod \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\" can be found. Need to start a new one\n","stream":"stderr","time":"2021-06-24T23:00:17.009715553Z"}
{"log":"I0624 23:00:17.501848    3568 kubelet.go:1837] SyncLoop (UPDATE, \"api\"): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\"\n","stream":"stderr","time":"2021-06-24T23:00:17.502200708Z"}
{"log":"I0624 23:00:17.941428    3568 kubelet.go:1868] SyncLoop (PLEG): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\", event: \u0026pleg.PodLifecycleEvent{ID:\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\", Type:\"ContainerStarted\", Data:\"ba3366af8e95d11262c370dc1171ca1b92b46aacffad57716073777a9a5c1032\"}\n","stream":"stderr","time":"2021-06-24T23:00:17.941719981Z"}
{"log":"I0624 23:00:17.941497    3568 kubelet.go:1868] SyncLoop (PLEG): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\", event: \u0026pleg.PodLifecycleEvent{ID:\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\", Type:\"ContainerStarted\", Data:\"c1243bc4df3c2ca2fdc6f65dc808c2a54e2ed34bc3960c3bc8da0704045ade04\"}\n","stream":"stderr","time":"2021-06-24T23:00:17.941745252Z"}
{"log":"E0624 23:00:18.643466    3568 dns.go:135] Nameserver limits were exceeded, some nameservers have been omitted, the applied nameserver line is: 10.1.42.11 10.1.42.12 10.10.0.7\n","stream":"stderr","time":"2021-06-24T23:00:18.643920992Z"}
{"log":"I0624 23:00:23.072398    3568 kubelet.go:1868] SyncLoop (PLEG): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\", event: \u0026pleg.PodLifecycleEvent{ID:\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\", Type:\"ContainerDied\", Data:\"ba3366af8e95d11262c370dc1171ca1b92b46aacffad57716073777a9a5c1032\"}\n","stream":"stderr","time":"2021-06-24T23:00:23.072547469Z"}
{"log":"I0624 23:00:23.072655    3568 topology_manager.go:219] [topologymanager] RemoveContainer - Container ID: ba3366af8e95d11262c370dc1171ca1b92b46aacffad57716073777a9a5c1032\n","stream":"stderr","time":"2021-06-24T23:00:23.07273424Z"}
{"log":"I0624 23:00:23.093082    3568 reflector.go:213] Stopping reflector *v1.Secret (0s) from object-\"rook-ceph\"/\"local\"\n","stream":"stderr","time":"2021-06-24T23:00:23.093263612Z"}
{"log":"I0624 23:00:23.093132    3568 reflector.go:213] Stopping reflector *v1.Secret (0s) from object-\"rook-ceph\"/\"default-token-75rjf\"\n","stream":"stderr","time":"2021-06-24T23:00:23.093286641Z"}
{"log":"I0624 23:00:23.093162    3568 reflector.go:213] Stopping reflector *v1.ConfigMap (0s) from object-\"rook-ceph\"/\"ceph-snapshot-schedule\"\n","stream":"stderr","time":"2021-06-24T23:00:23.093291584Z"}
{"log":"I0624 23:00:23.169781    3568 reconciler.go:196] operationExecutor.UnmountVolume started for volume \"default-token-75rjf\" (UniqueName: \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\") pod \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:23.170047527Z"}
{"log":"I0624 23:00:23.170028    3568 reconciler.go:196] operationExecutor.UnmountVolume started for volume \"cephfs-volume\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") pod \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\") \n","stream":"stderr","time":"2021-06-24T23:00:23.170136534Z"}
{"log":"I0624 23:00:23.170368    3568 clientconn.go:106] parsed scheme: \"\"\n","stream":"stderr","time":"2021-06-24T23:00:23.170507608Z"}
{"log":"I0624 23:00:23.170472    3568 clientconn.go:106] scheme \"\" not registered, fallback to default scheme\n","stream":"stderr","time":"2021-06-24T23:00:23.170515955Z"}
{"log":"W0624 23:00:23.170545    3568 empty_dir.go:469] Warning: Failed to clear quota on /var/lib/kubelet/pods/18e0a947-1b51-4b6b-81f5-25ce75a276ed/volumes/kubernetes.io~configmap/schedule: ClearQuota called, but quotas disabled\n","stream":"stderr","time":"2021-06-24T23:00:23.170759433Z"}
{"log":"I0624 23:00:23.170690    3568 passthrough.go:48] ccResolverWrapper: sending update to cc: {[{/var/lib/kubelet/plugins/rook-ceph.cephfs.csi.ceph.com/csi.sock  \u003cnil\u003e 0 \u003cnil\u003e}] \u003cnil\u003e \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:23.170848643Z"}
{"log":"I0624 23:00:23.170748    3568 clientconn.go:948] ClientConn switching balancer to \"pick_first\"\n","stream":"stderr","time":"2021-06-24T23:00:23.17086775Z"}
{"log":"I0624 23:00:23.170829    3568 clientconn.go:897] blockingPicker: the picked transport is not ready, loop back to repick\n","stream":"stderr","time":"2021-06-24T23:00:23.171009697Z"}
{"log":"I0624 23:00:23.170987    3568 kubelet.go:1837] SyncLoop (UPDATE, \"api\"): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\"\n","stream":"stderr","time":"2021-06-24T23:00:23.171080255Z"}
{"log":"I0624 23:00:23.171048    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc00086f080, {CONNECTING \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:23.171172188Z"}
{"log":"I0624 23:00:23.172231    3568 balancer_conn_wrappers.go:78] pickfirstBalancer: HandleSubConnStateChange: 0xc00086f080, {READY \u003cnil\u003e}\n","stream":"stderr","time":"2021-06-24T23:00:23.172374644Z"}
{"log":"I0624 23:00:23.173657    3568 operation_generator.go:788] UnmountVolume.TearDown succeeded for volume \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\" (OuterVolumeSpecName: \"default-token-75rjf\") pod \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\"). InnerVolumeSpecName \"default-token-75rjf\". PluginName \"kubernetes.io/secret\", VolumeGidValue \"\"\n","stream":"stderr","time":"2021-06-24T23:00:23.173775218Z"}
{"log":"I0624 23:00:23.177282    3568 controlbuf.go:508] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"\n","stream":"stderr","time":"2021-06-24T23:00:23.177436718Z"}
{"log":"I0624 23:00:23.177338    3568 operation_generator.go:788] UnmountVolume.TearDown succeeded for volume \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\" (OuterVolumeSpecName: \"cephfs-volume\") pod \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\" (UID: \"18e0a947-1b51-4b6b-81f5-25ce75a276ed\"). InnerVolumeSpecName \"cephfs-snapshot\". PluginName \"kubernetes.io/csi\", VolumeGidValue \"\"\n","stream":"stderr","time":"2021-06-24T23:00:23.177463897Z"}
{"log":"I0624 23:00:23.270789    3568 reconciler.go:319] Volume detached for volume \"default-token-75rjf\" (UniqueName: \"kubernetes.io/secret/18e0a947-1b51-4b6b-81f5-25ce75a276ed-default-token-75rjf\") on node \"k8s-worker-5\" DevicePath \"\"\n","stream":"stderr","time":"2021-06-24T23:00:23.270918375Z"}
{"log":"I0624 23:00:23.270847    3568 reconciler.go:312] operationExecutor.UnmountDevice started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") on node \"k8s-worker-5\" \n","stream":"stderr","time":"2021-06-24T23:00:23.271024161Z"}
{"log":"E0624 23:00:23.273372    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:23.773314049 +0000 UTC m=+766066.471433424 (durationBeforeRetry 500ms). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/7a6446c6-23ff-4fab-83ec-82ca8734212e/volumes/kubernetes.io~csi/offsite-backup/mount]\"\n","stream":"stderr","time":"2021-06-24T23:00:23.273554569Z"}
{"log":"I0624 23:00:23.873342    3568 reconciler.go:312] operationExecutor.UnmountDevice started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") on node \"k8s-worker-5\" \n","stream":"stderr","time":"2021-06-24T23:00:23.873669334Z"}
{"log":"E0624 23:00:23.876231    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:24.876203861 +0000 UTC m=+766067.574323244 (durationBeforeRetry 1s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/7a6446c6-23ff-4fab-83ec-82ca8734212e/volumes/kubernetes.io~csi/offsite-backup/mount]\"\n","stream":"stderr","time":"2021-06-24T23:00:23.876403236Z"}
{"log":"I0624 23:00:24.106389    3568 kubelet.go:1868] SyncLoop (PLEG): \"cephfs-snapshot-1624575600-v8ntn_rook-ceph(18e0a947-1b51-4b6b-81f5-25ce75a276ed)\", event: \u0026pleg.PodLifecycleEvent{ID:\"18e0a947-1b51-4b6b-81f5-25ce75a276ed\", Type:\"ContainerDied\", Data:\"c1243bc4df3c2ca2fdc6f65dc808c2a54e2ed34bc3960c3bc8da0704045ade04\"}\n","stream":"stderr","time":"2021-06-24T23:00:24.106657417Z"}
{"log":"W0624 23:00:24.106499    3568 pod_container_deletor.go:79] Container \"c1243bc4df3c2ca2fdc6f65dc808c2a54e2ed34bc3960c3bc8da0704045ade04\" not found in pod's containers\n","stream":"stderr","time":"2021-06-24T23:00:24.10670478Z"}
{"log":"I0624 23:00:24.877177    3568 reconciler.go:312] operationExecutor.UnmountDevice started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") on node \"k8s-worker-5\" \n","stream":"stderr","time":"2021-06-24T23:00:24.877464859Z"}
{"log":"E0624 23:00:24.879452    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:26.879426251 +0000 UTC m=+766069.577545621 (durationBeforeRetry 2s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/7a6446c6-23ff-4fab-83ec-82ca8734212e/volumes/kubernetes.io~csi/offsite-backup/mount]\"\n","stream":"stderr","time":"2021-06-24T23:00:24.879652128Z"}
{"log":"I0624 23:00:25.678865    3568 log.go:181] http: superfluous response.WriteHeader call from k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader (httplog.go:217)\n","stream":"stderr","time":"2021-06-24T23:00:25.679154228Z"}
{"log":"I0624 23:00:26.884764    3568 reconciler.go:312] operationExecutor.UnmountDevice started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") on node \"k8s-worker-5\" \n","stream":"stderr","time":"2021-06-24T23:00:26.88499332Z"}
{"log":"E0624 23:00:26.887115    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:30.887062205 +0000 UTC m=+766073.585181621 (durationBeforeRetry 4s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/7a6446c6-23ff-4fab-83ec-82ca8734212e/volumes/kubernetes.io~csi/offsite-backup/mount]\"\n","stream":"stderr","time":"2021-06-24T23:00:26.887284993Z"}
{"log":"I0624 23:00:27.754074    3568 kubelet.go:1846] SyncLoop (DELETE, \"api\"): \"offsite-backup-t8fwm_local-system(7a6446c6-23ff-4fab-83ec-82ca8734212e)\"\n","stream":"stderr","time":"2021-06-24T23:00:27.754365613Z"}
{"log":"I0624 23:00:27.754397    3568 kuberuntime_container.go:635] Killing container \"docker://80aa928fd4a820b22de51a5b4aeeeb2e26fe116b6d85e992930b7d6cb47f58a9\" with a 30 second grace period\n","stream":"stderr","time":"2021-06-24T23:00:27.754525375Z"}
{"log":"I0624 23:00:30.834883    3568 kubelet.go:1846] SyncLoop (DELETE, \"api\"): \"cephfs-snapshot-1624564800-nr5dc_rook-ceph(fcf13dcb-d099-4112-a816-6ebe50910070)\"\n","stream":"stderr","time":"2021-06-24T23:00:30.835180164Z"}
{"log":"I0624 23:00:30.845859    3568 kubelet.go:1840] SyncLoop (REMOVE, \"api\"): \"cephfs-snapshot-1624564800-nr5dc_rook-ceph(fcf13dcb-d099-4112-a816-6ebe50910070)\"\n","stream":"stderr","time":"2021-06-24T23:00:30.84602745Z"}
{"log":"I0624 23:00:30.845914    3568 kubelet.go:2034] Failed to delete pod \"cephfs-snapshot-1624564800-nr5dc_rook-ceph(fcf13dcb-d099-4112-a816-6ebe50910070)\", err: pod not found\n","stream":"stderr","time":"2021-06-24T23:00:30.846045057Z"}
{"log":"I0624 23:00:30.899760    3568 reconciler.go:312] operationExecutor.UnmountDevice started for volume \"cephfs-snapshot\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\") on node \"k8s-worker-5\" \n","stream":"stderr","time":"2021-06-24T23:00:30.899891514Z"}
{"log":"E0624 23:00:30.901883    3568 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot podName: nodeName:}\" failed. No retries permitted until 2021-06-24 23:00:38.901854069 +0000 UTC m=+766081.599973434 (durationBeforeRetry 8s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-snapshot\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-snapshot\\\") on node \\\"k8s-worker-5\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-snapshot/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/offsite-backup/globalmount /var/lib/kubelet/pods/7a6446c6-23ff-4fab-83ec-82ca8734212e/volumes/kubernetes.io~csi/offsite-backup/mount]\"\n","stream":"stderr","time":"2021-06-24T23:00:30.902065359Z"}

Additional Context

The Ceph cluster is deployed and managed by Proxmox and configured in k8s by Rook. Here's the cluster CRD's status:

status:
  ceph:
    capacity:
      bytesAvailable: 42977436372992
      bytesTotal: 76110897348608
      bytesUsed: 33133460975616
      lastUpdated: "2021-07-01T15:16:19Z"
    health: HEALTH_OK
    lastChanged: "2021-07-01T08:47:01Z"
    lastChecked: "2021-07-01T15:16:19Z"
    previousHealth: HEALTH_WARN
    versions:
      mds:
        ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable): 5
      mgr:
        ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable): 5
      mon:
        ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable): 3
      osd:
        ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable): 16
      overall:
        ceph version 15.2.13 (1f5c7871ec0e36ade641773b9b05b6211c308b9d) octopus (stable): 29
  conditions:
  - lastHeartbeatTime: "2021-07-01T07:41:52Z"
    lastTransitionTime: "2021-07-01T07:41:52Z"
    message: Attempting to connect to an external Ceph cluster
    reason: ClusterConnecting
    status: "True"
    type: Connecting
  - lastHeartbeatTime: "2021-07-01T15:16:20Z"
    lastTransitionTime: "2021-04-26T03:27:20Z"
    message: Cluster connected successfully
    reason: ClusterConnected
    status: "True"
    type: Connected
  message: Cluster connected successfully
  phase: Connected
  state: Connected
  version:
    image: ceph/ceph:v15.2.13
    version: 15.2.13-0 

While rook is using an admin secret, I've added another secret for lower privilege access for CephFS CSI mounting, here's one of the volumes from the logs above. The other is nearly identical except for the name, uid, handle, and claimRef:

apiVersion: v1
kind: PersistentVolume
annotations:
  pv.kubernetes.io/bound-by-controller: "yes"
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  labels:
    app: cephfs-snapshot
  name: cephfs-snapshot
  resourceVersion: "194940716"
  selfLink: /api/v1/persistentvolumes/cephfs-snapshot
  uid: 7cc3698d-f4b4-4d05-8259-476bf47ffb22
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  claimRef:
    apiVersion: v1
    kind: PersistentVolumeClaim
    name: cephfs-snapshot
    namespace: rook-ceph
    resourceVersion: "189756705"
    uid: 056edc02-c1f5-44fe-b3f7-f416139eb638
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-snapshot
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
status:
  phase: Bound

And here is the scrubbed node secret:

apiVersion: v1
data:
  userID: rook-k8s
  userKey: foo
kind: Secret
metadata:
  creationTimestamp: "2021-06-06T04:49:56Z"
  name: rook-csi-cephfs-node-static
  namespace: rook-ceph
  resourceVersion: "182934314"
  selfLink: /api/v1/namespaces/rook-ceph/secrets/rook-csi-cephfs-node-static
  uid: 823a7b2f-9ea6-4a99-ad89-dc052ddc4910
type: kubernetes.io/rook

And finally, the cephx permissions:

client.rook-k8s
	key: foo
	caps: [mds] allow rws
	caps: [mon] allow r
	caps: [osd] allow rw tag cephfs data=clusterfs-capacity

For now, I've worked around this by using pod antiaffinity to ensure the jobs don't run on the same node but I'll start running out of nodes eventually.

@ikogan
Copy link
Author

ikogan commented Jul 1, 2021

Here's the bug report @humblec, thanks for helping me out last week!

@humblec humblec self-assigned this Jul 2, 2021
@humblec
Copy link
Collaborator

humblec commented Jul 2, 2021

@ikogan Thanks for reverting here!! much appreciated.. I wanted to ask you that, is this cluster running in production? because recently I have been revisiting the 'locking operation' we do in various code paths and working on some improvements in the same area as mentioned or tracked under #2149.

I have a feeling that, this bug fix could take care of this scenario. so just wanted to ask if it possible to give a try with test image (quay.io/humble/cephcsi:publish) with the fix at your end.

Meanwhile I am taking some AIs here to reproduce it in my end and also RCAing it . Please revert with your thoughts.

@ikogan
Copy link
Author

ikogan commented Jul 5, 2021

I can give it a shot, this is in my homelab so the definition of "production" varies depending on who's inconvenienced at the moment .

I'm assuming, to test this, I can just set csi.cephcsi.image in the Rook values.yaml to quay.io/humble/cephcsi:publish?

@humblec
Copy link
Collaborator

humblec commented Jul 5, 2021

I can give it a shot, this is in my homelab so the definition of "production" varies depending on who's inconvenienced at the moment .

I'm assuming, to test this, I can just set csi.cephcsi.image in the Rook values.yaml to quay.io/humble/cephcsi:publish?

@ikogan That should do, if you already have a running cluster, you can directly edit the deamonset ( also deployment) and change the plugin/driver image path:

#kubectl edit <below resourcename> -n <namespace>
NAME                              DESIRED   CURRENT   READY   UP-TO-DATE   AVAILABLE   NODE SELECTOR   AGE
daemonset.apps/csi-cephfsplugin   5         5         5       5            5           <none>          42h
daemonset.apps/csi-rbdplugin      5         5         5       5            5           <none>          42h

.....

deployment.apps/csi-rbdplugin-provisioner      2/2     2            2           42h
deployment.apps/csi-cephfsplugin-provisioner   2/2     2            2           42h

@ikogan
Copy link
Author

ikogan commented Jul 15, 2021

Sorry for taking so long to get to this! Unfortunately, the only thing that changed after using quay.io/humble/cephcsi:publish was that everything happened significantly faster, which, as I understand it, is an important goal of the changes in that image, so that's great:

# kubectl get pod -n rook-ceph -o jsonpath="{.items[*].spec.containers[*].image}" | tr -s '[[:space:]]' '\n' | sort | uniq
k8s.gcr.io/sig-storage/csi-attacher:v3.2.1
k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.2.0
k8s.gcr.io/sig-storage/csi-provisioner:v2.2.2
k8s.gcr.io/sig-storage/csi-resizer:v1.2.0
k8s.gcr.io/sig-storage/csi-snapshotter:v4.1.1
quay.io/humble/cephcsi:publish

So it looks like I'm correctly running quay.io/humble/cephcsi:publish. I then try to deploy:

---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test1
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test1
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test2
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test2
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test1
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test1
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test2
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test2
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test1
  namespace: default
spec:
  containers:
  - image: registry.kubernetes.local/docker-diagnostics:2021-05-12
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test1
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  imagePullSecrets:
  - name: gaea
  nodeName: worker1.kubernetes.local
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test1
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test2
  namespace: default
spec:
  containers:
  - image: registry.kubernetes.local/docker-diagnostics:2021-05-12
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test2
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  imagePullSecrets:
  - name: gaea
  nodeName: worker1.kubernetes.local
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test2

Once those pods are running I then delete them, their PVs and PVCs. Shortly thereafter (much quicker than before):

{
    "log": "E0715 04:04:23.623704    1470 nestedpendingoperations.go:301] Operation for \"{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test2 podName: nodeName:}\" failed. No retries permitted until 2021-07-15 04:04:24.623686457 +0000 UTC m=+2548665.069510895 (durationBeforeRetry 1s). Error: \"GetDeviceMountRefs check failed for volume \\\"cephfs-samenode-test2\\\" (UniqueName: \\\"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test2\\\") on node \\\"worker1.kubernetes.local\\\" : The device mount path \\\"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount\\\" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount]\"\n",
    "stream": "stderr",
    "time": "2021-07-15T04:04:23.623743031Z"
}

Also, it looks like my method to change the image in the Rook Helm chart won't work. Those workloads are deployed by the rook operator which bombs because it can't parse the version publish. I had to use your method of modifying the workloads manually after scaling down the orchestrator, which isn't ideal but it works.

@nixpanic nixpanic added the component/cephfs Issues related to CephFS label Aug 5, 2021
@github-actions
Copy link

github-actions bot commented Sep 4, 2021

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in a week if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the wontfix This will not be worked on label Sep 4, 2021
@ikogan
Copy link
Author

ikogan commented Sep 5, 2021

This is still an issue and the only workaround I can see so far is to ensure CephFS workloads using the same volume don't start on the same node. I'm running out of nodes.

@github-actions github-actions bot removed the wontfix This will not be worked on label Sep 5, 2021
@godber
Copy link

godber commented Sep 5, 2021

We've gone back to gluster.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 7, 2021

@ikogan am planning to work on this one. please provide the below details for now

  • The issue is only with the static PVC not with dynamic PVC?
  • If the issue exists for dynamic PVC what are the reproducer steps?
  • Did you try to reproduce the latest cephcsi v3.4.0 version?

@ikogan
Copy link
Author

ikogan commented Sep 8, 2021

Hi, thanks for working on this!

  1. I've only tried this with static PVCs. I think it likely wouldn't happen with dynamic ones as the volume path would be different for each PVC, right? That is, if you did a mount | grep ceph, you'd see a different "device" for each PVC because the path on the CephFS volume would be different, right?
  2. I'm not sure how it could happen with dynamic PVCs, you'd have to generate the same volume path for each PVC.
  3. Yes, I just upgraded to Pacific this past weekend and have the v3.4.0 CSI driver installed, the following YAML will create the problem and deleting the two pods will trigger the log spam. The PVCs will not be unmounted:
---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test1
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test1
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test2
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test2
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test1
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test1
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test2
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test2
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test1
  namespace: default
spec:
  containers:
  - image: alpine:latest
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test1
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  nodeName: kubernetes-lada.gaea.private
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test1
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test2
  namespace: default
spec:
  containers:
  - image: alpine:latest
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test2
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  nodeName: kubernetes-lada.gaea.private
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test2

If I then manually unmount one of the volumes from the node, eventually the other will get unmounted cleanly as well. Here's what my list of mounts looks like after shutting down the pods:

10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)
10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)

Then I umount /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount. The other hangs around for a while but then eventually goes away.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 14, 2021

Hi, thanks for working on this!

  1. I've only tried this with static PVCs. I think it likely wouldn't happen with dynamic ones as the volume path would be different for each PVC, right? That is, if you did a mount | grep ceph, you'd see a different "device" for each PVC because the path on the CephFS volume would be different, right?
  2. I'm not sure how it could happen with dynamic PVCs, you'd have to generate the same volume path for each PVC.
  3. Yes, I just upgraded to Pacific this past weekend and have the v3.4.0 CSI driver installed, the following YAML will create the problem and deleting the two pods will trigger the log spam. The PVCs will not be unmounted:
---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test1
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test1
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolume
metadata:
  finalizers:
  - kubernetes.io/pv-protection
  name: cephfs-samenode-test2
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 50Ti
  csi:
    driver: rook-ceph.cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: rook-csi-cephfs-node-static
      namespace: rook-ceph
    volumeAttributes:
      clusterID: rook-ceph
      fsName: clusterfs-capacity
      rootPath: /
      staticVolume: "true"
    volumeHandle: cephfs-samenode-test2
  persistentVolumeReclaimPolicy: Retain
  volumeMode: Filesystem
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test1
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test1
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  finalizers:
  - kubernetes.io/pvc-protection
  name: cephfs-samenode-test2
  namespace: default
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 50Ti
  volumeMode: Filesystem
  volumeName: cephfs-samenode-test2
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test1
  namespace: default
spec:
  containers:
  - image: alpine:latest
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test1
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  nodeName: kubernetes-lada.gaea.private
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test1
---
apiVersion: v1
kind: Pod
metadata:
  name: cephfs-samenode-test2
  namespace: default
spec:
  containers:
  - image: alpine:latest
    imagePullPolicy: IfNotPresent
    name: cephfs-samenode-test2
    stdin: True
    tty: true
    securityContext:
      runAsNonRoot: false
    volumeMounts:
    - mountPath: /mnt/test
      name: test
  nodeName: kubernetes-lada.gaea.private
  restartPolicy: Never
  volumes:
  - name: test
    persistentVolumeClaim:
      claimName: cephfs-samenode-test2

If I then manually unmount one of the volumes from the node, eventually the other will get unmounted cleanly as well. Here's what my list of mounts looks like after shutting down the pods:

Okay, one thing am failing to understand is why do you need multiple PV with the same RootPath: / as CephFS supports RWX volumes you need only one PVC/PV with RootPath: / if the RootPath is pointing to different paths then you need different PVC/PV can you be more specific about creating of multiple PV with same RootPath?

10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)
10.10.0.1:6789,10.10.0.2:6789,10.10.0.3:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount type ceph (rw,relatime,name=k8s-static,secret=<hidden>,acl,mds_namespace=clusterfs-capacity,_netdev)

Then I umount /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount. The other hangs around for a while but then eventually goes away.

@ikogan
Copy link
Author

ikogan commented Sep 17, 2021

Okay, one thing am failing to understand is why do you need multiple PV with the same RootPath: / as CephFS supports RWX volumes you need only one PVC/PV with RootPath: / if the RootPath is pointing to different paths then you need different PVC/PV can you be more specific about creating of multiple PV with same RootPath?

While I can re-use the same PVC if my workloads are in the same namespace, since a PVC is a namespaced object, I cannot use it across namespaces. I can also only have one PVC bound to a single PV. The only way to have two different namespaces use the same underlying filesystem path is to have two different PVs.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 28, 2021

got it. Let me see what can be done here.

@Madhu-1 Madhu-1 assigned Madhu-1 and unassigned humblec Sep 28, 2021
@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 28, 2021

okay am seeing different problem on this one 🗡️

Create static PVC, PV and pods

[root@dhcp53-170 ceph]# kubectl create -f demo.yaml 
persistentvolume/cephfs-samenode-test1 created
persistentvolume/cephfs-samenode-test2 created
persistentvolumeclaim/cephfs-samenode-test1 created
persistentvolumeclaim/cephfs-samenode-test2 created
pod/cephfs-samenode-test1 created
pod/cephfs-samenode-test2 created
I0928 07:57:24.047636       1 utils.go:176] ID: 191 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:24.047814       1 utils.go:180] ID: 191 GRPC request: {}
I0928 07:57:24.051488       1 utils.go:187] ID: 191 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:24.065483       1 utils.go:176] ID: 192 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:24.067945       1 utils.go:180] ID: 192 GRPC request: {}
I0928 07:57:24.068733       1 utils.go:187] ID: 192 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:24.073076       1 utils.go:176] ID: 193 Req-ID: cephfs-samenode-test2 GRPC call: /csi.v1.Node/NodeStageVolume
I0928 07:57:24.073555       1 utils.go:180] ID: 193 Req-ID: cephfs-samenode-test2 GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"rook-ceph","fsName":"myfs","rootPath":"/","staticVolume":"true"},"volume_id":"cephfs-samenode-test2"}
I0928 07:57:24.091170       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:57:24.091233       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:57:24.091245       1 mount_linux.go:175] 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
I0928 07:57:24.091567       1 volumemounter.go:134] requested mounter: , chosen mounter: kernel
I0928 07:57:24.091635       1 nodeserver.go:157] ID: 193 Req-ID: cephfs-samenode-test2 cephfs: mounting volume cephfs-samenode-test2 with Ceph kernel client
I0928 07:57:24.098491       1 cephcmds.go:60] ID: 193 Req-ID: cephfs-samenode-test2 command succeeded: modprobe [ceph]
I0928 07:57:24.199544       1 cephcmds.go:60] ID: 193 Req-ID: cephfs-samenode-test2 command succeeded: mount [-t ceph 192.168.121.246:6789:/ /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount -o name=csi-cephfs-node,secretfile=/tmp/csi/keys/keyfile-619020135,mds_namespace=myfs,_netdev]
I0928 07:57:24.203689       1 nodeserver.go:133] ID: 193 Req-ID: cephfs-samenode-test2 cephfs: successfully mounted volume cephfs-samenode-test2 to /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount
I0928 07:57:24.203758       1 utils.go:187] ID: 193 Req-ID: cephfs-samenode-test2 GRPC response: {}
I0928 07:57:24.218833       1 utils.go:176] ID: 194 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:24.221786       1 utils.go:180] ID: 194 GRPC request: {}
I0928 07:57:24.223464       1 utils.go:187] ID: 194 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:24.240349       1 utils.go:176] ID: 195 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:24.240492       1 utils.go:180] ID: 195 GRPC request: {}
I0928 07:57:24.240573       1 utils.go:187] ID: 195 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:24.244220       1 utils.go:176] ID: 196 Req-ID: cephfs-samenode-test2 GRPC call: /csi.v1.Node/NodePublishVolume
I0928 07:57:24.244387       1 utils.go:180] ID: 196 Req-ID: cephfs-samenode-test2 GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount","target_path":"/var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"rook-ceph","fsName":"myfs","rootPath":"/","staticVolume":"true"},"volume_id":"cephfs-samenode-test2"}
I0928 07:57:24.266003       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:57:24.266060       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:57:24.266071       1 mount_linux.go:175] 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
I0928 07:57:24.274432       1 cephcmds.go:60] ID: 196 Req-ID: cephfs-samenode-test2 command succeeded: mount [-o bind,_netdev /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount /var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount]
I0928 07:57:24.274470       1 nodeserver.go:266] ID: 196 Req-ID: cephfs-samenode-test2 cephfs: successfully bind-mounted volume cephfs-samenode-test2 to /var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount
I0928 07:57:24.274578       1 utils.go:187] ID: 196 Req-ID: cephfs-samenode-test2 GRPC response: {}
I0928 07:57:35.244365       1 utils.go:176] ID: 197 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:35.257221       1 utils.go:180] ID: 197 GRPC request: {}
I0928 07:57:35.257418       1 utils.go:187] ID: 197 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:35.277685       1 utils.go:176] ID: 198 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:35.278179       1 utils.go:180] ID: 198 GRPC request: {}
I0928 07:57:35.283239       1 utils.go:187] ID: 198 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:35.291280       1 utils.go:176] ID: 199 Req-ID: cephfs-samenode-test1 GRPC call: /csi.v1.Node/NodeStageVolume
I0928 07:57:35.297765       1 utils.go:180] ID: 199 Req-ID: cephfs-samenode-test1 GRPC request: {"secrets":"***stripped***","staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"rook-ceph","fsName":"myfs","rootPath":"/","staticVolume":"true"},"volume_id":"cephfs-samenode-test1"}
I0928 07:57:35.318289       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:57:35.318592       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:57:35.318917       1 mount_linux.go:175] 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
I0928 07:57:35.320769       1 volumemounter.go:134] requested mounter: , chosen mounter: kernel
I0928 07:57:35.320898       1 nodeserver.go:157] ID: 199 Req-ID: cephfs-samenode-test1 cephfs: mounting volume cephfs-samenode-test1 with Ceph kernel client
I0928 07:57:35.331165       1 cephcmds.go:60] ID: 199 Req-ID: cephfs-samenode-test1 command succeeded: modprobe [ceph]
I0928 07:57:35.397909       1 cephcmds.go:60] ID: 199 Req-ID: cephfs-samenode-test1 command succeeded: mount [-t ceph 192.168.121.246:6789:/ /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount -o name=csi-cephfs-node,secretfile=/tmp/csi/keys/keyfile-173437338,mds_namespace=myfs,_netdev]
I0928 07:57:35.397970       1 nodeserver.go:133] ID: 199 Req-ID: cephfs-samenode-test1 cephfs: successfully mounted volume cephfs-samenode-test1 to /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount
I0928 07:57:35.398472       1 utils.go:187] ID: 199 Req-ID: cephfs-samenode-test1 GRPC response: {}
I0928 07:57:35.411433       1 utils.go:176] ID: 200 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:35.411554       1 utils.go:180] ID: 200 GRPC request: {}
I0928 07:57:35.411681       1 utils.go:187] ID: 200 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:35.419366       1 utils.go:176] ID: 201 GRPC call: /csi.v1.Node/NodeGetCapabilities
I0928 07:57:35.419474       1 utils.go:180] ID: 201 GRPC request: {}
I0928 07:57:35.419603       1 utils.go:187] ID: 201 GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}}]}
I0928 07:57:35.424389       1 utils.go:176] ID: 202 Req-ID: cephfs-samenode-test1 GRPC call: /csi.v1.Node/NodePublishVolume
I0928 07:57:35.425307       1 utils.go:180] ID: 202 Req-ID: cephfs-samenode-test1 GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount","target_path":"/var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount","volume_capability":{"AccessType":{"Mount":{}},"access_mode":{"mode":5}},"volume_context":{"clusterID":"rook-ceph","fsName":"myfs","rootPath":"/","staticVolume":"true"},"volume_id":"cephfs-samenode-test1"}
I0928 07:57:35.447200       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:57:35.447227       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:57:35.447237       1 mount_linux.go:175] 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
I0928 07:57:35.451755       1 cephcmds.go:60] ID: 202 Req-ID: cephfs-samenode-test1 command succeeded: mount [-o bind,_netdev /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount /var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount]
I0928 07:57:35.451786       1 nodeserver.go:266] ID: 202 Req-ID: cephfs-samenode-test1 cephfs: successfully bind-mounted volume cephfs-samenode-test1 to /var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount
I0928 07:57:35.451848       1 utils.go:187] ID: 202 Req-ID: cephfs-samenode-test1 GRPC response: {}
sh-4.4# mount |grep ceph
/dev/vda1 on /etc/ceph-csi-config type ext4 (ro,relatime)
tmpfs on /var/lib/kubelet/pods/e3558812-0e04-4f8d-91cc-74698fe52684/volumes/kubernetes.io~secret/rook-ceph-mons-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/f20569b9-0528-4e05-ba98-5437a363fd5e/volumes/kubernetes.io~secret/rook-ceph-mgr-a-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/f438f726-5b77-48a8-acc3-fad0fb67a7ad/volumes/kubernetes.io~secret/rook-ceph-admin-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/9092ffd5-50b6-482f-99c3-286a82692df3/volumes/kubernetes.io~secret/rook-ceph-mds-myfs-a-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/1355947a-0010-4d0d-9521-297844fc50f9/volumes/kubernetes.io~secret/rook-ceph-mds-myfs-b-keyring type tmpfs (rw,relatime,size=5952284k)
192.168.121.246:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)
192.168.121.246:6789:/ on /var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)
192.168.121.246:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)
192.168.121.246:6789:/ on /var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)

Delete static PVC, PV, and pods

[root@dhcp53-170 ceph]# kubectl delete -f demo.yaml 
persistentvolume "cephfs-samenode-test1" deleted
persistentvolume "cephfs-samenode-test2" deleted
persistentvolumeclaim "cephfs-samenode-test1" deleted
persistentvolumeclaim "cephfs-samenode-test2" deleted
pod "cephfs-samenode-test1" deleted
pod "cephfs-samenode-test2" deleted
I0928 07:58:20.893063       1 utils.go:176] ID: 209 Req-ID: cephfs-samenode-test2 GRPC call: /csi.v1.Node/NodeUnpublishVolume
I0928 07:58:20.893076       1 utils.go:176] ID: 209 Req-ID: cephfs-samenode-test1 GRPC call: /csi.v1.Node/NodeUnpublishVolume
I0928 07:58:20.893223       1 utils.go:180] ID: 209 Req-ID: cephfs-samenode-test2 GRPC request: {"target_path":"/var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount","volume_id":"cephfs-samenode-test2"}
I0928 07:58:20.893314       1 utils.go:180] ID: 209 Req-ID: cephfs-samenode-test1 GRPC request: {"target_path":"/var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount","volume_id":"cephfs-samenode-test1"}
I0928 07:58:20.909863       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:58:20.909908       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:58:20.909917       1 mount_linux.go:175] 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
I0928 07:58:20.910845       1 mount_linux.go:173] Cannot run systemd-run, assuming non-systemd OS
I0928 07:58:20.910856       1 mount_linux.go:174] systemd-run failed with: exit status 1
I0928 07:58:20.910864       1 mount_linux.go:175] 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
I0928 07:58:20.925273       1 cephcmds.go:60] ID: 209 Req-ID: cephfs-samenode-test2 command succeeded: umount [/var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount]
I0928 07:58:20.925438       1 nodeserver.go:311] ID: 209 Req-ID: cephfs-samenode-test2 cephfs: successfully unbinded volume cephfs-samenode-test2 from /var/lib/kubelet/pods/8f5d58c9-be10-47e4-b225-62aaae3081ea/volumes/kubernetes.io~csi/cephfs-samenode-test2/mount
I0928 07:58:20.925506       1 utils.go:187] ID: 209 Req-ID: cephfs-samenode-test2 GRPC response: {}
I0928 07:58:20.926045       1 cephcmds.go:60] ID: 209 Req-ID: cephfs-samenode-test1 command succeeded: umount [/var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount]
I0928 07:58:20.926216       1 nodeserver.go:311] ID: 209 Req-ID: cephfs-samenode-test1 cephfs: successfully unbinded volume cephfs-samenode-test1 from /var/lib/kubelet/pods/7535a38d-d8a7-43d4-8d30-6e3421da3cd1/volumes/kubernetes.io~csi/cephfs-samenode-test1/mount
I0928 07:58:20.926242       1 utils.go:187] ID: 209 Req-ID: cephfs-samenode-test1 GRPC response: {}

I0928 07:59:05.304618       1 utils.go:176] ID: 210 GRPC call: /csi.v1.Identity/Probe
I0928 07:59:05.304771       1 utils.go:180] ID: 210 GRPC request: {}
I0928 07:59:05.304850       1 utils.go:187] ID: 210 GRPC response: {}
sh-4.4# mount |grep ceph
/dev/vda1 on /etc/ceph-csi-config type ext4 (ro,relatime)
tmpfs on /var/lib/kubelet/pods/e3558812-0e04-4f8d-91cc-74698fe52684/volumes/kubernetes.io~secret/rook-ceph-mons-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/f20569b9-0528-4e05-ba98-5437a363fd5e/volumes/kubernetes.io~secret/rook-ceph-mgr-a-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/f438f726-5b77-48a8-acc3-fad0fb67a7ad/volumes/kubernetes.io~secret/rook-ceph-admin-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/9092ffd5-50b6-482f-99c3-286a82692df3/volumes/kubernetes.io~secret/rook-ceph-mds-myfs-a-keyring type tmpfs (rw,relatime,size=5952284k)
tmpfs on /var/lib/kubelet/pods/1355947a-0010-4d0d-9521-297844fc50f9/volumes/kubernetes.io~secret/rook-ceph-mds-myfs-b-keyring type tmpfs (rw,relatime,size=5952284k)
192.168.121.246:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)
192.168.121.246:6789:/ on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount type ceph (rw,relatime,name=csi-cephfs-node,secret=<hidden>,acl,mds_namespace=myfs,_netdev)

The strange thing here is kubelet is not sending any NodeUnstage Request and i can see the mounts still exists on the node.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 28, 2021

Kubelet logs

Sep 28 09:38:30 minicluster2 kubelet[106285]: I0928 09:38:30.185443  106285 reconciler.go:312] "operationExecutor.UnmountDevice started for volume \"cephfs-samenode-test2\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test2\") on node \"minicluster2\" "
Sep 28 09:38:30 minicluster2 kubelet[106285]: E0928 09:38:30.188735  106285 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test2 podName: nodeName:}" failed. No retries permitted until 2021-09-28 09:39:34.188711093 +0000 UTC m=+580.217658964 (durationBeforeRetry 1m4s). Error: GetDeviceMountRefs check failed for volume "cephfs-samenode-test2" (UniqueName: "kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test2") on node "minicluster2" : the device mount path "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount" is still mounted by other references [/mnt/vda1/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount /var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount /mnt/vda1/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount]
Sep 28 09:38:30 minicluster2 kubelet[106285]: I0928 09:38:30.188798  106285 reconciler.go:312] "operationExecutor.UnmountDevice started for volume \"cephfs-samenode-test1\" (UniqueName: \"kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test1\") on node \"minicluster2\" "
Sep 28 09:38:30 minicluster2 kubelet[106285]: E0928 09:38:30.193237  106285 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test1 podName: nodeName:}" failed. No retries permitted until 2021-09-28 09:39:34.193213728 +0000 UTC m=+580.222161605 (durationBeforeRetry 1m4s). Error: GetDeviceMountRefs check failed for volume "cephfs-samenode-test1" (UniqueName: "kubernetes.io/csi/rook-ceph.cephfs.csi.ceph.com^cephfs-samenode-test1") on node "minicluster2" : the device mount path "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount" is still mounted by other references [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount /mnt/vda1/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test2/globalmount /mnt/vda1/var/lib/kubelet/plugins/kubernetes.io/csi/pv/cephfs-samenode-test1/globalmount]

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 28, 2021

@ikogan this looks more of a kubernetes issue as cephcsi side we do mount/umount operations as requested from the kubelet. the kubelet is not sending any request for cephcsi to UnStage the volume. because of that, the volumes are left stale on the node.

@ikogan
Copy link
Author

ikogan commented Sep 28, 2021

@Madhu-1 that's what I was thinking...possibly. Based on my very naive and inexperienced look at the kubelet source code, it's asking the, I think, the CSI driver for the device for the mount in GetDeviceMountRefs. If the device is mounted more than once, it will not make the UnStage request because it assumes the device is in use by another volume. In this case, the "device" is a CephFS URI, mounted twice to two different places.

So I'm really not sure whether the issue is that CephCSI is reporting the same device or that the kubelet is behaving in this way. I wonder what the NFS driver does since I didn't have this problem there...

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Sep 29, 2021

@ikogan NFS driver doesn't implement NodeStage and Unstage API maybe because of that things are working fine. As per the CSI spec, cephcsi is mounting the volume to a stagingPath and in this case, we are getting two stagingPath's (one stagingPath per PVC) as there are two PVC's but a common volume.

@ikogan
Copy link
Author

ikogan commented Oct 11, 2021

Looks like this is being talked about on the k8s GitHub here: kubernetes/kubernetes#105323.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Oct 12, 2021

Looks like this is being talked about on the k8s GitHub here: kubernetes/kubernetes#105323.

Yes opened an issue in kubernetes to check Is this expected or not. but looks like no response

@nixpanic nixpanic added the dependency/k8s depends on Kubernetes features label Oct 12, 2021
@github-actions
Copy link

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in a week if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the wontfix This will not be worked on label Nov 11, 2021
@ikogan
Copy link
Author

ikogan commented Nov 12, 2021

This issue is still relevant, just waiting on work on the kubelet side. If folks thinks we should close the one here, that's fine by me.

@github-actions github-actions bot removed the wontfix This will not be worked on label Nov 12, 2021
@github-actions
Copy link

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in a week if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the wontfix This will not be worked on label Dec 13, 2021
@Madhu-1
Copy link
Collaborator

Madhu-1 commented Dec 14, 2021

@ikogan even am more inclined towards closing this one as nothing can be done at cephcsi for this one.

@Madhu-1 Madhu-1 closed this as completed Dec 14, 2021
@ikogan
Copy link
Author

ikogan commented Dec 18, 2021

I think it makes sense to close this if we think that it must be fixed in the kubelet. I was wondering why Ceph doesn't choose to stage a CephFS mount once on a given node rather than mounting it multiple times? That seems a bit more logical given what it is. Wouldn't that also work around this issue?

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Jan 7, 2022

I think it makes sense to close this if we think that it must be fixed in the kubelet. I was wondering why Ceph doesn't choose to stage a CephFS mount once on a given node rather than mounting it multiple times? That seems a bit more logical given what it is. Wouldn't that also work around this issue?

As the stagingPaths are different as per the CSI standard we need to make sure the volume is mounted to the given staging path. if it was a single stagingPath we don't have any problem.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Jun 2, 2022

@gman0 can you please check do we have this problem for shallow cephfs pvc? Just making sure we are good.

@gman0
Copy link
Contributor

gman0 commented Jun 2, 2022

@Madhu-1 sure, I'll give it a go tomorrow.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Jun 6, 2022

@Madhu-1 sure, I'll give it a go tomorrow.

I tested this one with shallow support PR i don't see any issue. good to get some confirmation on this one.

@gman0
Copy link
Contributor

gman0 commented Jun 6, 2022

@Madhu-1

apiVersion: v1
kind: PersistentVolume
metadata:
  name: pv-snapbacked-1
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 2Gi
  csi:
    driver: cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: csi-cephfs-microosd
      namespace: default
    volumeAttributes:
      clusterID: microosd
      fsName: cephfs
      rootPath: /volumes/csi/csi-vol-d256e2c1-e0f5-11ec-82db-0242ac110003/65f292b3-8fdb-4822-aa13-61e8cea40fd6
      backingSnapshotID: de550711-e0f5-11ec-82db-0242ac110003
      staticVolume: "true"
    volumeHandle: pv-snapbacked-1
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: pvc-snapbacked-1
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 2Gi
  volumeName: pv-snapbacked-1
  storageClassName: ""
---
---
apiVersion: v1
kind: PersistentVolume
metadata:
  name: pv-snapbacked-2
spec:
  accessModes:
  - ReadWriteMany
  capacity:
    storage: 2Gi
  csi:
    driver: cephfs.csi.ceph.com
    nodeStageSecretRef:
      name: csi-cephfs-microosd
      namespace: default
    volumeAttributes:
      clusterID: microosd
      fsName: cephfs
      rootPath: /volumes/csi/csi-vol-d256e2c1-e0f5-11ec-82db-0242ac110003/65f292b3-8fdb-4822-aa13-61e8cea40fd6
      backingSnapshotID: de550711-e0f5-11ec-82db-0242ac110003
      staticVolume: "true"
    volumeHandle: pv-snapbacked-2
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: pvc-snapbacked-2
spec:
  accessModes:
  - ReadWriteMany
  resources:
    requests:
      storage: 2Gi
  volumeName: pv-snapbacked-2
  storageClassName: ""
---
apiVersion: v1
kind: Pod
metadata:
  name: backingsnap-1
spec:
  containers:
    - name: web-server
      image: docker.io/library/nginx:latest
      volumeMounts:
        - name: mypvc
          mountPath: /var/lib/www
  volumes:
    - name: mypvc
      persistentVolumeClaim:
        claimName: pvc-snapbacked-1
        readOnly: false
---
apiVersion: v1
kind: Pod
metadata:
  name: backingsnap-2
spec:
  containers:
    - name: web-server
      image: docker.io/library/nginx:latest
      volumeMounts:
        - name: mypvc
          mountPath: /var/lib/www
  volumes:
    - name: mypvc
      persistentVolumeClaim:
        claimName: pvc-snapbacked-2
        readOnly: false
  • ceph version 16.2.9 (4c3647a322c0ff5a1dd2344e039859dcbd28c830) pacific (stable)
  • k8s 1.23.4

Deleting both Pods seems to work fine, and I couldn't find the error message from the original post in kubelet logs.

@Madhu-1
Copy link
Collaborator

Madhu-1 commented Jun 6, 2022

@gman0 Thanks for confirming 🚀

hfeng101 referenced this issue in kubernetes/kubernetes Sep 19, 2022
Cann MountDevice only when the volume was not device-mounted before.
@ADustyOldMuffin
Copy link

So just chiming in here, this will happen anytime you have a pod mount the same cephfs volume on the same node. IE I have 2 pods on the same node both using the same sharedfs PVC. It also causes issues as the globalmount has a kernel client and can sometimes acquire an exclusive lock on files/folders which it will then never let go until manually unmounted.

@gotohx
Copy link

gotohx commented Feb 28, 2024

@ADustyOldMuffin Hi, did you find any solution to this problem, I'm stuck with it right now too.

@ADustyOldMuffin
Copy link

ADustyOldMuffin commented Feb 28, 2024

Our issue turned out to be something different I believe. We bind mounted the kubelet directory and Kubelet had a bug (that someone fixed) where it thought the bind mounts were references for a pod so it never removed the staging mount.

If all pods are off the machine you can umount the staging mount to get rid of it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
component/cephfs Issues related to CephFS dependency/k8s depends on Kubernetes features wontfix This will not be worked on
Projects
None yet
Development

No branches or pull requests

8 participants