PVC stuck in Pending due to "An operation with the given Volume ID nas.example.com/kube#pvc-13d... already exists"

[barbu110]

What happened:

I have configured a StorageClass to provision persistent storage on my NAS (external to the Kubernetes cluster). There is already a Samba share there and proper credentials configured. When enabling the provisioner-secret-name and provisioner-secret-namespace annotations on the StorageClass, PVCs are stuck in pending.

Now, it's important to mention that, if the two annotations mentioned above are not included on the StorageClass, volumes are successfully provisioned and containers are able to write to them. However, files end up on the root of the Samba share which is not desirable.

Also, important to mention is that, when the two annotations are included, a directory in the Samba share is created with the ID of the PVC, e.g. pvc-13dbd013-e3d9-4f47-a54b-7339068161a0, however, again, the PVC is stuck in Pending.

Exact errors are from the controller logs are:

I0125 21:31:44.148998       1 event.go:389] "Event occurred" object="default/storage-test-pvc" fieldPath="" kind="PersistentVolumeClaim" apiVersion="v1" type="Normal" reason="Provisioning" message="External provisioner is provisioning volume for claim \"default/storage-test-pvc\""
I0125 21:31:44.149146       1 controller.go:873] "Started provisioner controller" component="smb.csi.k8s.io_box-01_208072ce-405e-4422-99d7-ae2abbdfa990"
I0125 21:31:54.160600       1 controller.go:1101] "Temporary error received, adding PVC to claims in progress" claimUID="13dbd013-e3d9-4f47-a54b-7339068161a0"
I0125 21:31:54.160733       1 controller.go:951] "Retrying syncing claim" key="13dbd013-e3d9-4f47-a54b-7339068161a0" failures=0
E0125 21:31:54.160831       1 controller.go:974] error syncing claim "13dbd013-e3d9-4f47-a54b-7339068161a0": failed to provision volume with StorageClass "samba-share-kube": rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0125 21:31:54.160990       1 event.go:389] "Event occurred" object="default/storage-test-pvc" fieldPath="" kind="PersistentVolumeClaim" apiVersion="v1" type="Warning" reason="ProvisioningFailed" message="failed to provision volume with StorageClass \"samba-share-kube\": rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0125 21:31:55.162024       1 event.go:389] "Event occurred" object="default/storage-test-pvc" fieldPath="" kind="PersistentVolumeClaim" apiVersion="v1" type="Normal" reason="Provisioning" message="External provisioner is provisioning volume for claim \"default/storage-test-pvc\""
I0125 21:31:55.167200       1 controller.go:1094] "Final error received, removing PVC from claims in progress" claimUID="13dbd013-e3d9-4f47-a54b-7339068161a0"
I0125 21:31:55.167242       1 controller.go:951] "Retrying syncing claim" key="13dbd013-e3d9-4f47-a54b-7339068161a0" failures=1
E0125 21:31:55.167297       1 controller.go:974] error syncing claim "13dbd013-e3d9-4f47-a54b-7339068161a0": failed to provision volume with StorageClass "samba-share-kube": rpc error: code = Internal desc = failed to mount smb server: rpc error: code = Aborted desc = An operation with the given Volume ID nas.example.com/kube#pvc-13dbd013-e3d9-4f47-a54b-7339068161a0## already exists
I0125 21:31:55.167368       1 event.go:389] "Event occurred" object="default/storage-test-pvc" fieldPath="" kind="PersistentVolumeClaim" apiVersion="v1" type="Warning" reason="ProvisioningFailed" message="failed to provision volume with StorageClass \"samba-share-kube\": rpc error: code = Internal desc = failed to mount smb server: rpc error: code = Aborted desc = An operation with the given Volume ID nas.example.com/kube#pvc-13dbd013-e3d9-4f47-a54b-7339068161a0## already exists"
I0125 21:31:57.168317       1 event.go:389] "Event occurred" object="default/storage-test-pvc" fieldPath="" kind="PersistentVolumeClaim" apiVersion="v1" type="Normal" reason="Provisioning" message="External provisioner is provisioning volume for claim \"default/storage-test-pvc\""
I0125 21:31:57.176255       1 controller.go:1094] "Final error received, removing PVC from claims in progress" claimUID="13dbd013-e3d9-4f47-a54b-7339068161a0"

What you expected to happen: have volumes successfully provisioned

How to reproduce it:

apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  name: samba-share-kube
provisioner: smb.csi.k8s.io
parameters:
  source: //nas.example.com/kube
  csi.storage.k8s.io/provisioner-secret-name: samba-share-kube
  csi.storage.k8s.io/provisioner-secret-namespace: samba
  csi.storage.k8s.io/node-stage-secret-name: samba-share-kube
  csi.storage.k8s.io/node-stage-secret-namespace: samba
volumeBindingMode: Immediate
allowVolumeExpansion: true
reclaimPolicy: Retain
mountOptions:
  - dir_mode=0777
  - file_mode=0777
  - noserverino
  - noperm
  - cache=strict
---
apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: storage-test-pvc
spec:
  storageClassName: samba-share-kube
  accessModes:
    - ReadWriteMany
  resources:
    requests:
      storage: 10Gi

Anything else we need to know?:

I have tried both versions 1.16 and 1.15. I could not install 1.17 as images are seemingly not available to download as of 2025-01-25.

Environment:

• CSI Driver version: tried on 1.15 and 1.16
• Kubernetes version (use kubectl version): v1.31.4+rke2r1
• OS (e.g. from /etc/os-release): Ubuntu 24.04.1 LTS
• Kernel (e.g. uname -a): 6.8.0-51-generic
• Install tools:
• Others:

[andyzhangx]

what's the csi driver controller logs?
https://github.com/kubernetes-csi/csi-driver-smb/blob/master/docs/csi-debug.md#case1-volume-createdelete-failed

[barbu110]

Hey, unfortunately not much...

➜  tmp.CE9HpZI6fe k -n kube-system logs csi-smb-node-pnrhc -c smb
I0125 21:31:22.052418       1 smb.go:129]
DRIVER INFORMATION:
-------------------
Build Date: "2024-07-18T12:17:31Z"
Compiler: gc
Driver Name: smb.csi.k8s.io
Driver Version: v1.15.0
Git Commit: ""
Go Version: go1.22.3
Platform: linux/amd64

Streaming logs below:
I0125 21:31:22.056294       1 mount_linux.go:282] Detected umount with safe 'not mounted' behavior
I0125 21:31:22.056397       1 driver.go:93] Enabling controller service capability: CREATE_DELETE_VOLUME
I0125 21:31:22.056410       1 driver.go:93] Enabling controller service capability: SINGLE_NODE_MULTI_WRITER
I0125 21:31:22.056418       1 driver.go:93] Enabling controller service capability: CLONE_VOLUME
I0125 21:31:22.056428       1 driver.go:112] Enabling volume access mode: SINGLE_NODE_WRITER
I0125 21:31:22.056437       1 driver.go:112] Enabling volume access mode: SINGLE_NODE_READER_ONLY
I0125 21:31:22.056444       1 driver.go:112] Enabling volume access mode: SINGLE_NODE_SINGLE_WRITER
I0125 21:31:22.056450       1 driver.go:112] Enabling volume access mode: SINGLE_NODE_MULTI_WRITER
I0125 21:31:22.056457       1 driver.go:112] Enabling volume access mode: MULTI_NODE_READER_ONLY
I0125 21:31:22.056464       1 driver.go:112] Enabling volume access mode: MULTI_NODE_SINGLE_WRITER
I0125 21:31:22.056471       1 driver.go:112] Enabling volume access mode: MULTI_NODE_MULTI_WRITER
I0125 21:31:22.056485       1 driver.go:103] Enabling node service capability: STAGE_UNSTAGE_VOLUME
I0125 21:31:22.056495       1 driver.go:103] Enabling node service capability: SINGLE_NODE_MULTI_WRITER
I0125 21:31:22.056503       1 driver.go:103] Enabling node service capability: VOLUME_MOUNT_GROUP
I0125 21:31:22.056510       1 driver.go:103] Enabling node service capability: GET_VOLUME_STATS
I0125 21:31:22.056897       1 server.go:118] Listening for connections on address: &net.UnixAddr{Name:"//csi/csi.sock", Net:"unix"}
I0125 21:31:22.386520       1 utils.go:76] GRPC call: /csi.v1.Identity/GetPluginInfo
I0125 21:31:22.386566       1 utils.go:77] GRPC request: {}
I0125 21:31:22.388919       1 utils.go:83] GRPC response: {"name":"smb.csi.k8s.io","vendor_version":"v1.15.0"}
I0125 21:31:22.914664       1 utils.go:76] GRPC call: /csi.v1.Identity/GetPluginInfo
I0125 21:31:22.914705       1 utils.go:77] GRPC request: {}
I0125 21:31:22.914795       1 utils.go:83] GRPC response: {"name":"smb.csi.k8s.io","vendor_version":"v1.15.0"}
I0125 21:31:23.126265       1 utils.go:76] GRPC call: /csi.v1.Node/NodeGetInfo
I0125 21:31:23.126307       1 utils.go:77] GRPC request: {}
I0125 21:31:23.126437       1 utils.go:83] GRPC response: {"node_id":"box-01"}

Note: I have a single-node cluster at the moment, so that the only pod.

[andyzhangx]

@barbu110 you need to get the csi controller logs

[barbu110]

I’m sorry if I’m misunderstanding, but I believe the logs you’re looking for are in the description of the issue On Sun, Jan 26, 2025 at 10:40, Andy Zhang - notifications at github.com ***@***.***> wrote: @barbu110 you need to get the csi controller logs — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.Message ID: ***@***.***>

[andyzhangx]

the issue is in CreateVolume in controller pod:

kubectl logs csi-smb-controller-xxx -c smb -n kube-system > csi-smb-controller.log

[barbu110]

Sorry for the delayed response.

Thanks to you explaining what logs I had to investigate, I'm pleased to say the issue has gone away completely and volumes can now be successfully bound. Hopefully, this will serve as good material for future readers.

Logs indicated that a route to the host could not be found. Then, I tried replacing the DNS name with an IP and was getting a logon failure:

Status code returned 0xc000006d STATUS_LOGON_FAILURE

Both issues have gone away after installing the cifs-utils package on the Kubernetes node. I have no explanation as to why that worked, but it did - a Unix StackExchange post indicated it would.

Then, a new one appeared that could be traced in the logs of the controller:

I0126 11:49:04.273259       1 utils.go:77] GRPC request: {"capacity_range":{"required_bytes":10737418240},"name":"pvc-13dbd013-e3d9-4f47-a54b-7339068161a0","parameters":{"csi.storage.k8s.io/pv/name":"pvc-13dbd013-e3d9-4f47-a54b-7339068161a0","csi.storage.k8s.io/pvc/name":"storage-test-pvc","csi.storage.k8s.io/pvc/namespace":"default","source":"//nas.example.com/kube"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"mount_flags":["dir_mode=0777","file_mode=0777","noserverino","noperm","cache=strict"]}},"access_mode":{"mode":5}}]}
I0126 11:49:04.273699       1 controllerserver.go:288] internally mounting //nas.example.com/kube at /tmp/pvc-13dbd013-e3d9-4f47-a54b-7339068161a0
I0126 11:49:04.273841       1 nodeserver.go:209] NodeStageVolume: targetPath(/tmp/pvc-13dbd013-e3d9-4f47-a54b-7339068161a0) volumeID(nas.example.com/kube#pvc-13dbd013-e3d9-4f47-a54b-7339068161a0##) context(map[source://nas.example.com/kube]) mountflags([dir_mode=0777 file_mode=0777 noserverino noperm cache=strict]) mountOptions([dir_mode=0777 file_mode=0777 noserverino noperm cache=strict])
I0126 11:49:04.274396       1 mount_linux.go:218] Mounting cmd (mount) with arguments (-t cifs -o dir_mode=0777,file_mode=0777,noserverino,noperm,cache=strict,<masked> //nas.example.com/kube /tmp/pvc-13dbd013-e3d9-4f47-a54b-7339068161a0)
E0126 11:49:24.346251       1 mount_linux.go:230] Mount failed: exit status 32
Mounting command: mount
Mounting arguments: -t cifs -o dir_mode=0777,file_mode=0777,noserverino,noperm,cache=strict,<masked> //nas.example.com/kube /tmp/pvc-13dbd013-e3d9-4f47-a54b-7339068161a0
Output: mount error(13): Permission denied
Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) and kernel log messages (dmesg)

E0126 11:49:24.346347       1 utils.go:81] GRPC error: rpc error: code = Internal desc = failed to mount smb server: rpc error: code = Internal desc = volume(nas.example.com/kube#pvc-13dbd013-e3d9-4f47-a54b-7339068161a0##) mount "//nas.example.com/kube" on "/tmp/pvc-13dbd013-e3d9-4f47-a54b-7339068161a0" failed with mount failed: exit status 32

Now, trying the mount command on the node, I had to run it with root permissions, because that's how mount usually works. I found another explanation online, Unix StackExchange post, that instructed adding the user mount option and this did the trick.

So, my StorageClass now looks like:

apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  name: samba-share-kube
provisioner: smb.csi.k8s.io
parameters:
  source: //nas.example.com/kube
  csi.storage.k8s.io/provisioner-secret-name: samba-share-kube
  csi.storage.k8s.io/provisioner-secret-namespace: samba
  csi.storage.k8s.io/node-stage-secret-name: samba-share-kube
  csi.storage.k8s.io/node-stage-secret-namespace: samba
volumeBindingMode: Immediate
allowVolumeExpansion: true
reclaimPolicy: Retain
mountOptions:
  - dir_mode=0777
  - file_mode=0777
  - noserverino
  - noperm
  - cache=strict
  - user  # note this flag being added afterwards

Before we close this, please let me know if the addition of the user flag is the desired way of mounting SMB shares through this CSI. Thanks!