kubernetes: Umount intree volume failed when csiMigrationRBD enabled.

What happened?

Volume couldn’t be umount successfuly for an intree rbd volume when csi migratation enabled.

With kubelet loglevel=4, can see the csi plugin volume path is unmounted.

Jan 29 07:41:36 node-10-200-112-221 kubelet[75663]: I0129 07:41:36.986617   75663 csi_mounter.go:463] kubernetes.io/csi: deleting volume path [/var/lib/kubelet/pods/c6aaef09-ce5b-44b2-944c-7a8a72bafb26/volumes/kubernetes.io~csi/pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2]
Jan 29 07:41:36 node-10-200-112-221 kubelet[75663]: I0129 07:41:36.986649   75663 csi_mounter.go:392] kubernetes.io/csi: Unmounter.TearDownAt successfully unmounted dir [/var/lib/kubelet/pods/c6aaef09-ce5b-44b2-944c-7a8a72bafb26/volumes/kubernetes.io~csi/pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2/mount]
Jan 29 07:41:36 node-10-200-112-221 kubelet[75663]: I0129 07:41:36.986658   75663 operation_generator.go:910] UnmountVolume.TearDown succeeded for volume "kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-997efca5-80cd-11ec-b4c5-0a7342eb7f81_7475303239" (OuterVolumeSpecName: "www") pod "c6aaef09-ce5b-44b2-944c-7a8a72bafb26" (UID: "c6aaef09-ce5b-44b2-944c-7a8a72bafb26"). InnerVolumeSpecName "pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2". PluginName "kubernetes.io/csi", VolumeGidValue ""
Jan 29 07:41:37 node-10-200-112-221 kubelet[75663]: I0129 07:41:37.083403   75663 reconciler.go:293] "operationExecutor.UnmountDevice started for volume \"pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-997efca5-80cd-11ec-b4c5-0a7342eb7f81_7475303239\") on node \"node-10-200-112-221\" "

The pv is still mounted to the intree plugin path(the line of rbd2)/var/lib/kubelet/pods/c6aaef09-ce5b-44b2-944c-7a8a72bafb26/volumes/kubernetes.io~rbd:

# lsblk
NAME        MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
rbd0        252:0    0   1G  0 disk /var/lib/kubelet/pods/b5545cd8-8b4b-43b8-80f6-0af1b3bbb189/volumes/kubernetes.io~csi/pvc-eec34c
rbd1        252:16   0   1G  0 disk /var/lib/kubelet/pods/88af1bae-7111-472f-b462-e8240d2a03d2/volumes/kubernetes.io~csi/pvc-7ec9ab
rbd2        252:32   0   1G  0 disk /var/lib/kubelet/pods/c6aaef09-ce5b-44b2-944c-7a8a72bafb26/volumes/kubernetes.io~rbd/pvc-a4b929
nvme0n1     259:0    0  64G  0 disk
├─nvme0n1p1 259:1    0   1M  0 part
├─nvme0n1p2 259:2    0   1G  0 part /boot
└─nvme0n1p3 259:3    0  63G  0 part
  └─ubuntu--vg-ubuntu--lv
            253:0    0  63G  0 lvm  /

Because the volume still mounted in intree plugin, so umap failed.

Jan 29 07:41:37 node-10-200-112-221 kubelet[75663]: I0129 07:41:37.890779   75663 csi_client.go:458] kubernetes.io/csi: calling NodeUnstageVolume rpc [volid=mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-997efca5-80cd-11ec-b4c5-0a7342eb7f81_7475303239,staging_target_path=/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2/globalmount]
Jan 29 07:41:38 node-10-200-112-221 kubelet[75663]: E0129 07:41:38.171151   75663 nestedpendingoperations.go:335] Operation for "{volumeName:kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-997efca5-80cd-11ec-b4c5-0a7342eb7f81_7475303239 podName: nodeName:}" failed. No retries permitted until 2022-01-29 07:41:39.171129913 +0100 CET m=+331.218776784 (durationBeforeRetry 1s). Error: UnmountDevice failed for volume "pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2" (UniqueName: "kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-997efca5-80cd-11ec-b4c5-0a7342eb7f81_7475303239") on node "node-10-200-112-221" : kubernetes.io/csi: attacher.UnmountDevice failed: rpc error: code = Internal desc = rbd: unmap for spec (tu029/kubernetes-dynamic-pvc-997efca5-80cd-11ec-b4c5-0a7342eb7f81) failed (an error (exit status 16) occurred while running rbd args: [unmap tu029/kubernetes-dynamic-pvc-997efca5-80cd-11ec-b4c5-0a7342eb7f81 --device-type krbd --options noudev]): (rbd: sysfs write failed
Jan 29 07:41:38 node-10-200-112-221 kubelet[75663]: I0129 07:41:38.281225   75663 kubelet_volumes.go:92] "Pod found, but volumes are still mounted on disk" podUID=c6aaef09-ce5b-44b2-944c-7a8a72bafb26 paths=[/var/lib/kubelet/pods/c6aaef09-ce5b-44b2-944c-7a8a72bafb26/volumes/kubernetes.io~rbd/pvc-a4b929be-9114-4d26-a15c-3a4fa40711b2

If manually do “umount /dev/rbd0”, it worked.

What did you expect to happen?

The volume created by intree plugin could be umounted by csi.

How can we reproduce it (as minimally and precisely as possible)?

  1. Create statefulset with intree rbd plugin.
  2. Enable csiMigrationRBD and deploy ceph csi 3.5.1.
  3. Scale-down statefulset, found that the pod stuck in Terminating, as the volume failed to detach.

Anything else we need to know?

No response

Kubernetes version

# kubectl version
Client Version: version.Info{Major:"1", Minor:"23", GitVersion:"v1.23.3", GitCommit:"816c97ab8cff8a1c72eccca1026f7820e93e0d25", GitTreeState:"clean", BuildDate:"2022-01-25T21:25:17Z", GoVersion:"go1.17.6", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"23", GitVersion:"v1.23.3", GitCommit:"816c97ab8cff8a1c72eccca1026f7820e93e0d25", GitTreeState:"clean", BuildDate:"2022-01-25T21:19:12Z", GoVersion:"go1.17.6", Compiler:"gc", Platform:"linux/amd64"}

Cloud provider

Private cluster

OS version

# On Linux:
$ cat /etc/os-release
NAME="Ubuntu"
VERSION="18.04.5 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.5 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic

$ uname -a
Linux node-10-210-171-221 5.4.0-70-generic #78~18.04.1-Ubuntu SMP Sat Mar 20 14:10:07 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here

Install tools

Container runtime (CRI) and and version (if applicable)

Containerd

Related plugins (CNI, CSI, …) and versions (if applicable)

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 30 (16 by maintainers)

Most upvoted comments

Hi @Jiawei0227, it did work by rolling upgrade as you suggested. Thank you. @humblec, Thanks a lot for your time to follow up this issue.

kubelet-pod-before-migration.log kubelet-pod-after-migration.log

Hi @humblec , I collected the kubelet log that pod was created before or after migration enabled.

For the pod created after migration, then scale-down sts, the volume detached successfully, Log as below:

# cat kubelet-pod-after-migration.log|grep pvc-db77597c-4f07-4b51-b794-ee5e31fedb05
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.151468     955 desired_state_of_world_populator.go:258] "Removing volume from desired state" pod="default/web-intree-0" podUID=fdbfba11-12fe-4dad-811d-d9d11f4c622c volumeName="pvc-db77597c-4f07-4b51-b794-ee5e31fedb05"
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195583     955 csi_plugin.go:486] kubernetes.io/csi: setting up unmounter for [name=pvc-db77597c-4f07-4b51-b794-ee5e31fedb05, podUID=fdbfba11-12fe-4dad-811d-d9d11f4c622c]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195611     955 csi_mounter.go:87] kubernetes.io/csi: mounter.GetPath generated [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195619     955 csi_util.go:80] kubernetes.io/csi: loading volume data file [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195828     955 subpath_linux.go:244] Cleaning up subpath mounts for /var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volume-subpaths/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195882     955 csi_mounter.go:87] kubernetes.io/csi: mounter.GetPath generated [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195889     955 csi_mounter.go:368] kubernetes.io/csi: Unmounter.TearDownAt(/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount)
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.195903     955 csi_client.go:361] kubernetes.io/csi: calling NodeUnpublishVolume rpc: [volid=mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239, target_path=/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200432     955 csi_mounter.go:444] kubernetes.io/csi: removing mount path [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200444     955 csi_mounter.go:451] kubernetes.io/csi: dir not mounted, deleting it [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200457     955 csi_mounter.go:458] kubernetes.io/csi: also deleting volume info data file [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200490     955 csi_mounter.go:463] kubernetes.io/csi: deleting volume path [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200515     955 csi_mounter.go:392] kubernetes.io/csi: Unmounter.TearDownAt successfully unmounted dir [/var/lib/kubelet/pods/fdbfba11-12fe-4dad-811d-d9d11f4c622c/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.200522     955 operation_generator.go:910] UnmountVolume.TearDown succeeded for volume "kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239" (OuterVolumeSpecName: "www") pod "fdbfba11-12fe-4dad-811d-d9d11f4c622c" (UID: "fdbfba11-12fe-4dad-811d-d9d11f4c622c"). InnerVolumeSpecName "pvc-db77597c-4f07-4b51-b794-ee5e31fedb05". PluginName "kubernetes.io/csi", VolumeGidValue ""
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.296003     955 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.296079     955 reconciler.go:293] "operationExecutor.UnmountDevice started for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.296343     955 csi_attacher.go:260] kubernetes.io/csi: attacher.GetDeviceMountPath(&{nil &PersistentVolume{ObjectMeta:{pvc-db77597c-4f07-4b51-b794-ee5e31fedb05   /api/v1/persistentvolumes/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05 542b3387-710c-4dc2-8499-bf06b8b312d4 8713994 0 2022-01-29 11:38:52 +0100 CET <nil> <nil> map[] map[kubernetes.io/createdby:rbd-dynamic-provisioner pv.kubernetes.io/bound-by-controller:yes pv.kubernetes.io/migrated-to:rbd.csi.ceph.com pv.kubernetes.io/provisioned-by:kubernetes.io/rbd] [] [kubernetes.io/pv-protection]  [{kube-controller-manager Update v1 2022-01-29 11:38:52 +0100 CET FieldsV1 {"f:status":{"f:phase":{}}} status} {kube-controller-manager Update v1 2022-02-08 03:07:49 +0100 CET FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubernetes.io/createdby":{},"f:pv.kubernetes.io/bound-by-controller":{},"f:pv.kubernetes.io/migrated-to":{},"f:pv.kubernetes.io/provisioned-by":{}}},"f:spec":{"f:accessModes":{},"f:capacity":{".":{},"f:storage":{}},"f:claimRef":{},"f:persistentVolumeReclaimPolicy":{},"f:rbd":{".":{},"f:fsType":{},"f:image":{},"f:keyring":{},"f:monitors":{},"f:pool":{},"f:secretRef":{},"f:user":{}},"f:storageClassName":{},"f:volumeMode":{}}} }]},Spec:PersistentVolumeSpec{Capacity:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},PersistentVolumeSource:PersistentVolumeSource{GCEPersistentDisk:nil,AWSElasticBlockStore:nil,HostPath:nil,Glusterfs:nil,NFS:nil,RBD:nil,ISCSI:nil,Cinder:nil,CephFS:nil,FC:nil,Flocker:nil,FlexVolume:nil,AzureFile:nil,VsphereVolume:nil,Quobyte:nil,AzureDisk:nil,PhotonPersistentDisk:nil,PortworxVolume:nil,ScaleIO:nil,Local:nil,StorageOS:nil,CSI:&CSIPersistentVolumeSource{Driver:rbd.csi.ceph.com,VolumeHandle:mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239,ReadOnly:false,FSType:xfs,VolumeAttributes:map[string]string{clusterID: 8b203a321c465f2b57b3c11c38e4644c,imageFeatures: layering,imageFormat: ,imageName: kubernetes-dynamic-pvc-5b55e739-056b-49b0-85eb-077a3ed47e1e,journalPool: ,migration: true,pool: tu029,staticVolume: true,tryOtherMounters: true,},ControllerPublishSecretRef:nil,NodeStageSecretRef:&SecretReference{Name:ceph-secret-user,Namespace:kube-system,},NodePublishSecretRef:nil,ControllerExpandSecretRef:&SecretReference{Name:ceph-secret-user,Namespace:kube-system,},},},AccessModes:[ReadWriteOnce],ClaimRef:&ObjectReference{Kind:PersistentVolumeClaim,Namespace:default,Name:www-web-intree-0,UID:db77597c-4f07-4b51-b794-ee5e31fedb05,APIVersion:v1,ResourceVersion:4240112,FieldPath:,},PersistentVolumeReclaimPolicy:Delete,StorageClassName:intree-rbd,MountOptions:[],VolumeMode:*Filesystem,NodeAffinity:nil,},Status:PersistentVolumeStatus{Phase:Bound,Message:,Reason:,},} false false true})
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.296376     955 csi_attacher.go:265] attacher.GetDeviceMountPath succeeded, deviceMountPath: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.297275     955 csi_attacher.go:574] kubernetes.io/csi: attacher.UnmountDevice(/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount)
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.297294     955 csi_util.go:80] kubernetes.io/csi: loading volume data file [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.298471     955 csi_client.go:458] kubernetes.io/csi: calling NodeUnstageVolume rpc [volid=mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239,staging_target_path=/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363250     955 csi_mounter.go:444] kubernetes.io/csi: removing mount path [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363267     955 csi_mounter.go:451] kubernetes.io/csi: dir not mounted, deleting it [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363310     955 csi_mounter.go:458] kubernetes.io/csi: also deleting volume info data file [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363337     955 csi_mounter.go:463] kubernetes.io/csi: deleting volume path [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363364     955 csi_attacher.go:634] kubernetes.io/csi: attacher.UnmountDevice successfully requested NodeUnStageVolume [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount]
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.363395     955 operation_generator.go:1018] UnmountDevice succeeded for volume "pvc-db77597c-4f07-4b51-b794-ee5e31fedb05" (UniqueName: "kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239") on node "node-10-200-112-220"
Feb 09 03:57:05 node-10-200-112-220 kubelet[955]: I0209 03:57:05.396485     955 reconciler.go:300] "Volume detached for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" DevicePath \"csi-79fa48103ca8942650af06cb097d0db4dcf667d5742c2a18bdcc8ab87b3e6e24\""

For pod created before migration, volume failed to umount/detach, log as belwo:

# cat kubelet.log|grep pvc-db77597c-4f07-4b51-b794-ee5e31fedb05
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.918521   13357 desired_state_of_world_populator.go:258] "Removing volume from desired state" pod="default/web-intree-0" podUID=9639c524-88b3-4be2-9f45-86ef13231225 volumeName="pvc-db77597c-4f07-4b51-b794-ee5e31fedb05"
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947538   13357 csi_plugin.go:486] kubernetes.io/csi: setting up unmounter for [name=pvc-db77597c-4f07-4b51-b794-ee5e31fedb05, podUID=9639c524-88b3-4be2-9f45-86ef13231225]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947550   13357 csi_mounter.go:87] kubernetes.io/csi: mounter.GetPath generated [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947557   13357 csi_util.go:80] kubernetes.io/csi: loading volume data file [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947699   13357 subpath_linux.go:244] Cleaning up subpath mounts for /var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volume-subpaths/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947719   13357 csi_mounter.go:87] kubernetes.io/csi: mounter.GetPath generated [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947724   13357 csi_mounter.go:368] kubernetes.io/csi: Unmounter.TearDownAt(/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount)
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.947734   13357 csi_client.go:361] kubernetes.io/csi: calling NodeUnpublishVolume rpc: [volid=mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239, target_path=/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955742   13357 csi_mounter.go:444] kubernetes.io/csi: removing mount path [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955757   13357 csi_mounter.go:451] kubernetes.io/csi: dir not mounted, deleting it [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955771   13357 csi_mounter.go:458] kubernetes.io/csi: also deleting volume info data file [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955806   13357 csi_mounter.go:463] kubernetes.io/csi: deleting volume path [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955832   13357 csi_mounter.go:392] kubernetes.io/csi: Unmounter.TearDownAt successfully unmounted dir [/var/lib/kubelet/pods/9639c524-88b3-4be2-9f45-86ef13231225/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount]
Feb 09 04:00:30 node-10-200-112-220 kubelet[13357]: I0209 04:00:30.955839   13357 operation_generator.go:910] UnmountVolume.TearDown succeeded for volume "kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239" (OuterVolumeSpecName: "www") pod "9639c524-88b3-4be2-9f45-86ef13231225" (UID: "9639c524-88b3-4be2-9f45-86ef13231225"). InnerVolumeSpecName "pvc-db77597c-4f07-4b51-b794-ee5e31fedb05". PluginName "kubernetes.io/csi", VolumeGidValue ""
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.048303   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.048369   13357 reconciler.go:293] "operationExecutor.UnmountDevice started for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.048543   13357 csi_attacher.go:260] kubernetes.io/csi: attacher.GetDeviceMountPath(&{nil &PersistentVolume{ObjectMeta:{pvc-db77597c-4f07-4b51-b794-ee5e31fedb05   /api/v1/persistentvolumes/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05 542b3387-710c-4dc2-8499-bf06b8b312d4 10769709 0 2022-01-29 11:38:52 +0100 CET <nil> <nil> map[] map[kubernetes.io/createdby:rbd-dynamic-provisioner pv.kubernetes.io/bound-by-controller:yes pv.kubernetes.io/provisioned-by:kubernetes.io/rbd] [] [kubernetes.io/pv-protection]  [{kube-controller-manager Update v1 2022-01-29 11:38:52 +0100 CET FieldsV1 {"f:status":{"f:phase":{}}} status} {kube-controller-manager Update v1 2022-02-08 03:07:49 +0100 CET FieldsV1 {"f:metadata":{"f:annotations":{".":{},"f:kubernetes.io/createdby":{},"f:pv.kubernetes.io/bound-by-controller":{},"f:pv.kubernetes.io/provisioned-by":{}}},"f:spec":{"f:accessModes":{},"f:capacity":{".":{},"f:storage":{}},"f:claimRef":{},"f:persistentVolumeReclaimPolicy":{},"f:rbd":{".":{},"f:fsType":{},"f:image":{},"f:keyring":{},"f:monitors":{},"f:pool":{},"f:secretRef":{},"f:user":{}},"f:storageClassName":{},"f:volumeMode":{}}} }]},Spec:PersistentVolumeSpec{Capacity:ResourceList{storage: {{1073741824 0} {<nil>} 1Gi BinarySI},},PersistentVolumeSource:PersistentVolumeSource{GCEPersistentDisk:nil,AWSElasticBlockStore:nil,HostPath:nil,Glusterfs:nil,NFS:nil,RBD:nil,ISCSI:nil,Cinder:nil,CephFS:nil,FC:nil,Flocker:nil,FlexVolume:nil,AzureFile:nil,VsphereVolume:nil,Quobyte:nil,AzureDisk:nil,PhotonPersistentDisk:nil,PortworxVolume:nil,ScaleIO:nil,Local:nil,StorageOS:nil,CSI:&CSIPersistentVolumeSource{Driver:rbd.csi.ceph.com,VolumeHandle:mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239,ReadOnly:false,FSType:xfs,VolumeAttributes:map[string]string{clusterID: 8b203a321c465f2b57b3c11c38e4644c,imageFeatures: layering,imageFormat: ,imageName: kubernetes-dynamic-pvc-5b55e739-056b-49b0-85eb-077a3ed47e1e,journalPool: ,migration: true,pool: tu029,staticVolume: true,tryOtherMounters: true,},ControllerPublishSecretRef:nil,NodeStageSecretRef:&SecretReference{Name:ceph-secret-user,Namespace:kube-system,},NodePublishSecretRef:nil,ControllerExpandSecretRef:&SecretReference{Name:ceph-secret-user,Namespace:kube-system,},},},AccessModes:[ReadWriteOnce],ClaimRef:&ObjectReference{Kind:PersistentVolumeClaim,Namespace:default,Name:www-web-intree-0,UID:db77597c-4f07-4b51-b794-ee5e31fedb05,APIVersion:v1,ResourceVersion:4240112,FieldPath:,},PersistentVolumeReclaimPolicy:Delete,StorageClassName:intree-rbd,MountOptions:[],VolumeMode:*Filesystem,NodeAffinity:nil,},Status:PersistentVolumeStatus{Phase:Bound,Message:,Reason:,},} false false true})
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.048554   13357 csi_attacher.go:265] attacher.GetDeviceMountPath succeeded, deviceMountPath: /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.049332   13357 csi_attacher.go:574] kubernetes.io/csi: attacher.UnmountDevice(/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount)
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.049350   13357 csi_util.go:80] kubernetes.io/csi: loading volume data file [/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/vol_data.json]
Feb 09 04:00:31 node-10-200-112-220 kubelet[13357]: I0209 04:00:31.050383   13357 csi_client.go:458] kubernetes.io/csi: calling NodeUnstageVolume rpc [volid=mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239,staging_target_path=/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount]
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.114286   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.215382   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.316539   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.417465   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.517671   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.618891   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220 kubelet[13357]: I0209 04:00:40.719092   13357 reconciler.go:286] "Starting operationExecutor.UnmountDevice for volume \"pvc-db77597c-4f07-4b51-b794-ee5e31fedb05\" (UniqueName: \"kubernetes.io/csi/rbd.csi.ceph.com^mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239\") on node \"node-10-200-112-220\" "
Feb 09 04:00:40 node-10-200-112-220
......
......

The difference seems after NodeUnstageVolume.

Additional Information which could help @celiawa : Is this share or PVC part of another POD running on the same kubelet/node? or ONLY one pod has this share and mounted/staged only at ONE NODE and POD?

This PVC is not shared, used by only this pod .

I had a retest, the pod uid is changed.

Before I scale-dwon the pod, the pv mountpoint is as below.

# mount |grep pvc-db77
/dev/rbd6 on /var/lib/kubelet/pods/9d88f291-e6c9-4cee-9339-e9f1b8cd6ed3/volumes/kubernetes.io~rbd/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05 type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=64k,sunit=128,swidth=128,noquota)
/dev/rbd6 on /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/globalmount/mig_mons-8b203a321c465f2b57b3c11c38e4644c_image-5b55e739-056b-49b0-85eb-077a3ed47e1e_7475303239 type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=64k,sunit=128,swidth=128,noquota,_netdev)
/dev/rbd6 on /var/lib/kubelet/pods/9d88f291-e6c9-4cee-9339-e9f1b8cd6ed3/volumes/kubernetes.io~csi/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05/mount type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=64k,sunit=128,swidth=128,noquota,_netdev)

Then I delete the pod, the csi mountpoint is removed, the left is the rbd mountpoint.

# mount |grep pvc-db77
/dev/rbd6 on /var/lib/kubelet/pods/9d88f291-e6c9-4cee-9339-e9f1b8cd6ed3/volumes/kubernetes.io~rbd/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05 type xfs (rw,relatime,attr2,inode64,logbufs=8,logbsize=64k,sunit=128,swidth=128,noquota)

If I manually umount the mountpoint, then the pod is automatically deleted successfully.

# umount /var/lib/kubelet/pods/9d88f291-e6c9-4cee-9339-e9f1b8cd6ed3/volumes/kubernetes.io~rbd/pvc-db77597c-4f07-4b51-b794-ee5e31fedb05

What was the exact process followed to enable migration in the kubelet/cluster? did you drain the pods …etc before enabling the migration ? I am trying to understand, was there any scheduling happened while kubelet got upgraded…etc

The steps I did as below:

  1. Create an intree pvc/pv.
  2. Create a sts using this pvc.
  3. Enable migration in kube-controller-manager/kubelet.
    • –feature-gates=CSIMigration=true,csiMigrationRBD=true,InTreePluginRBDUnregister=true featureGates: CSIMigration: true csiMigrationRBD: true InTreePluginRBDUnregister: true systemctl restart kubelet
  4. Scale-down the pod.

I didn’t drain the pods before enabling the migration.

if I may ask, can we create a PVC before migration enabled and attach to a pod after enabling the migration and check ?

Yes, had tested that created a PVC before migration enabled and attached to a pod after enabling the migration, and this worked well.

@humblec, found that the difference from the demo was that the pod in my scenario was created before csiMigrationRBD was enabled. And just had a test if I create the statefulset after csiMigrationRBD the umount also successfully.

Thanks @humblec, Here is the sidecar images.

# k get po -n ceph-csi-rbd ceph-csi-rbd-provisioner-c96bf4c64-kg7g6 -oyaml|grep image:
    image: k8s.gcr.io/sig-storage/csi-provisioner:v3.1.0
    image: k8s.gcr.io/sig-storage/csi-resizer:v1.3.0
    image: k8s.gcr.io/sig-storage/csi-snapshotter:v4.2.0
    image: k8s.gcr.io/sig-storage/csi-attacher:v3.4.0
    image: quay.io/cephcsi/cephcsi:v3.5.1

Yes, I set csiMigrationRBD feature Gate enabled. Actually I raised this ticket 107488 😃

Will collect and upload the log soon~