PVC cannot be attached to the pod.

[swlee4833]

I Have a Single K3S Cluster that i'd like to use with TrueNAS-SCALE-24.10.2.3 .

I was installed truenas-csp use by helm chart and i can provision pvc and pv through truenas-csp.

But this pvc cannot attached to the pod with error, Please take a look at the error below.

journalctl -f :

Aug 27 10:06:14 k3s k3s[1128]: E0827 10:06:14.219893    1128 csi_attacher.go:645] kubernetes.io/csi: attachment for test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6 failed: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6:2bb057cd-0a35-5755-a471-231c1cc3ac38
Aug 27 10:06:14 k3s k3s[1128]: E0827 10:06:14.220064    1128 nestedpendingoperations.go:348] Operation for "{volumeName:kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6 podName: nodeName:k3s}" failed. No retries permitted until 2025-08-27 10:06:14.720034899 +0000 UTC m=+188395.604237537 (durationBeforeRetry 500ms). Error: AttachVolume.Attach failed for volume "pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6" (UniqueName: "kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6") from node "k3s" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6:2bb057cd-0a35-5755-a471-231c1cc3ac38
Aug 27 10:06:14 k3s k3s[1128]: I0827 10:06:14.805492    1128 reconciler.go:360] "attacherDetacher.AttachVolume started" volumeName="kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6" nodeName="k3s" scheduledPods=["default/task-pv-pod"]

Below is my cluster information. :

[root@k3s ~]# kubectl get nodes -o wide
NAME   STATUS   ROLES                         AGE   VERSION        INTERNAL-IP    EXTERNAL-IP   OS-IMAGE                            KERNEL-VERSION             CONTAINER-RUNTIME
k3s    Ready    control-plane,master,worker   30d   v1.32.6+k3s1   10.12.40.251   <none>        Rocky Linux 8.10 (Green Obsidian)   4.18.0-553.el8_10.x86_64   containerd://2.0.5-k3s1.32
[root@k3s ~]#
[root@k3s ~]#
[root@k3s ~]# kubectl get all -A
NAMESPACE     NAME                                          READY   STATUS      RESTARTS       AGE
hpe-storage   pod/hpe-csi-controller-755b597ffb-jdq8s       9/9     Running     0              24h
hpe-storage   pod/hpe-csi-node-wxb6s                        2/2     Running     0              24h
hpe-storage   pod/truenas-csp-77845994f7-mhgxg              1/1     Running     0              24h
kube-system   pod/coredns-5688667fd4-hvpxc                  1/1     Running     1 (2d4h ago)   30d
kube-system   pod/helm-install-traefik-b2z2k                0/1     Completed   1              30d
kube-system   pod/helm-install-traefik-crd-w5rs5            0/1     Completed   0              30d
kube-system   pod/local-path-provisioner-774c6665dc-npzkv   1/1     Running     1 (2d4h ago)   30d
kube-system   pod/metrics-server-6f4c6675d5-rd2wb           1/1     Running     1 (2d4h ago)   30d
kube-system   pod/svclb-traefik-4f398a6f-d29zt              2/2     Running     2 (2d4h ago)   30d
kube-system   pod/traefik-c98fdf6fb-xhsrw                   1/1     Running     1 (2d4h ago)   30d

NAMESPACE     NAME                      TYPE           CLUSTER-IP      EXTERNAL-IP    PORT(S)                      AGE
default       service/kubernetes        ClusterIP      10.43.0.1       <none>         443/TCP                      30d
hpe-storage   service/truenas-csp-svc   ClusterIP      10.43.167.168   <none>         8080/TCP                     24h
kube-system   service/kube-dns          ClusterIP      10.43.0.10      <none>         53/UDP,53/TCP,9153/TCP       30d
kube-system   service/metrics-server    ClusterIP      10.43.85.150    <none>         443/TCP                      30d
kube-system   service/traefik           LoadBalancer   10.43.24.109    10.12.40.251   80:30916/TCP,443:31637/TCP   30d

NAMESPACE     NAME                                    DESIRED   CURRENT   READY   UP-TO-DATE   AVAILABLE   NODE SELECTOR   AGE
hpe-storage   daemonset.apps/hpe-csi-node             1         1         1       1            1           <none>          24h
kube-system   daemonset.apps/svclb-traefik-4f398a6f   1         1         1       1            1           <none>          30d

NAMESPACE     NAME                                     READY   UP-TO-DATE   AVAILABLE   AGE
hpe-storage   deployment.apps/hpe-csi-controller       1/1     1            1           24h
hpe-storage   deployment.apps/truenas-csp              1/1     1            1           24h
kube-system   deployment.apps/coredns                  1/1     1            1           30d
kube-system   deployment.apps/local-path-provisioner   1/1     1            1           30d
kube-system   deployment.apps/metrics-server           1/1     1            1           30d
kube-system   deployment.apps/traefik                  1/1     1            1           30d

NAMESPACE     NAME                                                DESIRED   CURRENT   READY   AGE
hpe-storage   replicaset.apps/hpe-csi-controller-755b597ffb       1         1         1       24h
hpe-storage   replicaset.apps/truenas-csp-77845994f7              1         1         1       24h
kube-system   replicaset.apps/coredns-5688667fd4                  1         1         1       30d
kube-system   replicaset.apps/local-path-provisioner-774c6665dc   1         1         1       30d
kube-system   replicaset.apps/metrics-server-6f4c6675d5           1         1         1       30d
kube-system   replicaset.apps/traefik-c98fdf6fb                   1         1         1       30d

NAMESPACE     NAME                                 STATUS     COMPLETIONS   DURATION   AGE
kube-system   job.batch/helm-install-traefik       Complete   1/1           21s        30d
kube-system   job.batch/helm-install-traefik-crd   Complete   1/1           19s        30d
[root@k3s ~]# kubectl get pvc
NAME          STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS       VOLUMEATTRIBUTESCLASS   AGE
rwx-truenas   Bound    pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6   1Gi        RWX            hpe-storageclass   <unset>                 74m

describe pod :

`Events:
  Type     Reason              Age               From                     Message
  ----     ------              ----              ----                     -------
  Normal   Scheduled           27s               default-scheduler        Successfully assigned default/task-pv-pod to k3s
  Warning  FailedAttachVolume  2s (x5 over 12s)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-9e2705b3-3d1f-452f-92a0-b84171d41da6:2bb057cd-0a35-5755-a471-231c1cc3ac38

[datamattsson]

Could you post the log for kubectl logs -n hpe-storage hpe-csi-node-wxb6s -c hpe-csi-driver?

[swlee4833]

The pod was restarted during the night and the pod was renamed.

[root@k3s ~]# kubectl get pods -n hpe-storage
NAME                                  READY   STATUS    RESTARTS      AGE
hpe-csi-controller-755b597ffb-p8rgn   9/9     Running   1 (13h ago)   13h
hpe-csi-node-tlqj2                    2/2     Running   0             13h
truenas-csp-77845994f7-mhgxg          1/1     Running   0             39h

[root@k3s ~]# kubectl logs -n hpe-storage   hpe-csi-node-tlqj2   -c hpe-csi-driver
time="2025-08-28T00:21:00Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T00:22:30Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T00:22:30Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T00:22:30Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T00:24:00Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T00:24:00Z" level=info msg=">>>>> Scrubber task invoked at 2025-08-28 00:24:00.780191268 +0000 UTC m=+46800.049768461" file="driver.go:736"
time="2025-08-28T00:24:00Z" level=info msg="No ephemeral inline volumes found" file="driver.go:805"
time="2025-08-28T00:24:00Z" level=info msg="<<<<< Scrubber task completed at 2025-08-28 00:24:00.785137548 +0000 UTC m=+46800.054714755" file="driver.go:741"
time="2025-08-28T00:24:00Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T00:24:00Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T00:25:30Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T00:25:30Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T00:25:30Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T00:27:00Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T00:27:00Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T00:27:00Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"

Also can not found target iscsi used iscsiadm commnad, and iscsid was nothing happend.

[root@k3s ~]# iscsiadm -m discovery --type st -p 172.16.100.2 

truenas target is not have iscsi group
I deleted the existing pvc and made a new pvc and conducted the test.

Authorized Networks items were manually deleted from the target created for the test to proceed.

[datamattsson]

I need to see the logs for when the attachment error is happening.

[swlee4833]

[root@k3s ~]# vim pods.yaml
apiVersion: v1
kind: Pod
metadata:
  name: task-pv-pod
spec:
  volumes:
    - name: task-pv-storage
      persistentVolumeClaim:
        claimName: rwx-truenas2
  containers:
    - name: task-pv-container
      image: nginx
      ports:
        - containerPort: 80
          name: "http-server"
      volumeDevices:
        - name: task-pv-storage
          devicePath: /dev/xvdb

[root@k3s ~]# kubectl get pvc
NAME           STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS        VOLUMEATTRIBUTESCLASS   AGE
rwx-truenas2   Bound    pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241   1Gi        RWX            hpe-storageclass2   <unset>                 92m
[root@k3s ~]# kubectl apply -f pods.yaml

[root@k3s ~]# tail -f /var/log/hpe-csi-controller.log
time="2025-08-28T01:53:56Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerUnpublishVolume" file="utils.go:69"
time="2025-08-28T01:53:56Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:54:01Z" level=info msg="Volume pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241 is already unpublished from node with ID 2bb057cd-0a35-5755-a471-231c1cc3ac38" file="controller_server.go:1033"
time="2025-08-28T01:54:01Z" level=info msg="GRPC response: {}" file="utils.go:75"
time="2025-08-28T01:56:17Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:56:17Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:56:22Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1013"
time="2025-08-28T01:56:22Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1019"
time="2025-08-28T01:56:22Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:999"
time="2025-08-28T01:56:22Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1005"
time="2025-08-28T01:56:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:56:32Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:56:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241:2bb057cd-0a35-5755-a471-231c1cc3ac38" file="utils.go:73"
time="2025-08-28T01:56:33Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:56:33Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:56:33Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241:2bb057cd-0a35-5755-a471-231c1cc3ac38" file="utils.go:73"
time="2025-08-28T01:56:37Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:56:37Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:56:37Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241:2bb057cd-0a35-5755-a471-231c1cc3ac38" file="utils.go:73"
time="2025-08-28T01:56:45Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:56:45Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:56:45Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241:2bb057cd-0a35-5755-a471-231c1cc3ac38" file="utils.go:73"
time="2025-08-28T01:56:54Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"172.16.100.2\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc0000008bb721287c1a2213cb5\",\"targetNames\":\"iqn.2005-10.org.freenas.ctl:pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"targetScope\":\"volume\"}}" file="utils.go:75"
time="2025-08-28T01:57:01Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:57:01Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:57:06Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1013"
time="2025-08-28T01:57:06Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1019"
time="2025-08-28T01:57:06Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:999"
time="2025-08-28T01:57:06Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1005"
time="2025-08-28T01:57:33Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"172.16.100.2\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc0000008bb721287c1a2213cb5\",\"targetNames\":\"iqn.2005-10.org.freenas.ctl:pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"targetScope\":\"volume\"}}" file="utils.go:75"
time="2025-08-28T01:57:48Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2025-08-28T01:57:48Z" level=info msg="GRPC request: {\"node_id\":\"2bb057cd-0a35-5755-a471-231c1cc3ac38\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Block\":{}},\"access_mode\":{\"mode\":5}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"allowOverrides\":\"sparse,compression,deduplication,volblocksize,sync,description\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\",\"csi.storage.k8s.io/pvc/name\":\"rwx-truenas2\",\"csi.storage.k8s.io/pvc/namespace\":\"default\",\"deduplication\":\"OFF\",\"hostEncryption\":\"false\",\"root\":\"test1/rpcloud\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1756293840379-4093-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\"},\"volume_id\":\"test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241\"}" file="utils.go:70"
time="2025-08-28T01:57:53Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1013"

[root@k3s ~]# kubectl logs -n hpe-storage pod/hpe-csi-controller-755b597ffb-p8rgn
I0828 01:54:00.427177       1 reflector.go:389] k8s.io/client-go/informers/factory.go:160: forcing resync
I0828 01:54:00.532824       1 reflector.go:389] sigs.k8s.io/sig-storage-lib-external-provisioner/v10/controller/controller.go:858: forcing resync
I0828 01:54:00.533267       1 controller.go:1171] "handleProtectionFinalizer" PV="&PersistentVolume{ObjectMeta:{pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241    95859ca2-f157-4fd2-8540-926a7d912c10 1496651 0 2025-08-28 00:41:40 +0000 UTC <nil> <nil> map[] map[pv.kubernetes.io/provisioned-by:csi.hpe.com volume.kubernetes.io/provisioner-deletion-secret-name:truenas-secret volume.kubernetes.io/provisioner-deletion-secret-namespace:hpe-storage] [] [external-provisioner.volume.kubernetes.io/finalizer kubernetes.io/pv-protection external-attacher/csi-hpe-com] [{csi-provisioner Update v1 2025-08-28 00:41:40 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:annotations\":{\".\":{},\"f:pv.kubernetes.io/provisioned-by\":{},\"f:volume.kubernetes.io/provisioner-deletion-secret-name\":{},\"f:volume.kubernetes.io/provisioner-deletion-secret-namespace\":{}},\"f:finalizers\":{\".\":{},\"v:\\\"external-provisioner.volume.kubernetes.io/finalizer\\\"\":{}}},\"f:spec\":{\"f:accessModes\":{},\"f:capacity\":{\".\":{},\"f:storage\":{}},\"f:claimRef\":{\".\":{},\"f:apiVersion\":{},\"f:kind\":{},\"f:name\":{},\"f:namespace\":{},\"f:resourceVersion\":{},\"f:uid\":{}},\"f:csi\":{\".\":{},\"f:controllerExpandSecretRef\":{},\"f:controllerPublishSecretRef\":{},\"f:driver\":{},\"f:nodePublishSecretRef\":{},\"f:nodeStageSecretRef\":{},\"f:volumeAttributes\":{\".\":{},\"f:accessProtocol\":{},\"f:allowOverrides\":{},\"f:compression\":{},\"f:csi.storage.k8s.io/pv/name\":{},\"f:csi.storage.k8s.io/pvc/name\":{},\"f:csi.storage.k8s.io/pvc/namespace\":{},\"f:deduplication\":{},\"f:hostEncryption\":{},\"f:root\":{},\"f:storage.kubernetes.io/csiProvisionerIdentity\":{},\"f:sync\":{},\"f:targetScope\":{},\"f:volblocksize\":{}},\"f:volumeHandle\":{}},\"f:persistentVolumeReclaimPolicy\":{},\"f:storageClassName\":{},\"f:volumeMode\":{}}} } {k3s Update v1 2025-08-28 00:41:40 +0000 UTC FieldsV1 {\"f:status\":{\"f:phase\":{}}} status} {csi-attacher Update v1 2025-08-28 01:33:59 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:finalizers\":{\"v:\\\"external-attacher/csi-hpe-com\\\"\":{}}}} }]},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:csi.hpe.com,VolumeHandle:test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241,ReadOnly:false,FSType:,VolumeAttributes:map[string]string{accessProtocol: iscsi,allowOverrides: sparse,compression,deduplication,volblocksize,sync,description,compression: LZ4,csi.storage.k8s.io/pv/name: pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241,csi.storage.k8s.io/pvc/name: rwx-truenas2,csi.storage.k8s.io/pvc/namespace: default,deduplication: OFF,hostEncryption: false,root: test1/rpcloud,storage.kubernetes.io/csiProvisionerIdentity: 1756293840379-4093-csi.hpe.com,sync: STANDARD,targetScope: volume,volblocksize: 8K,},ControllerPublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:hpe-storage,},NodeStageSecretRef:&SecretReference{Name:truenas-secret,Namespace:hpe-storage,},NodePublishSecretRef:&SecretReference{Name:truenas-secret,Namespace:hpe-storage,},ControllerExpandSecretRef:&SecretReference{Name:truenas-secret,Namespace:hpe-storage,},NodeExpandSecretRef:nil,},},AccessModes:[ReadWriteMany],ClaimRef:&ObjectReference{Kind:PersistentVolumeClaim,Namespace:default,Name:rwx-truenas2,UID:75b0aa08-7fcb-4d65-a515-3490bfad3241,APIVersion:v1,ResourceVersion:1493036,FieldPath:,},PersistentVolumeReclaimPolicy:Delete,StorageClassName:hpe-storageclass2,MountOptions:[],VolumeMode:*Block,NodeAffinity:nil,VolumeAttributesClassName:nil,},Status:PersistentVolumeStatus{Phase:Bound,Message:,Reason:,LastPhaseTransitionTime:2025-08-28 00:41:40 +0000 UTC,},}"
I0828 01:54:00.533311       1 controller.go:1258] "shouldDelete" PV="pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241"
I0828 01:54:00.533322       1 controller.go:1279] "shouldDelete is false: PersistentVolumePhase is not Released" PV="pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241"
I0828 01:55:44.634034       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.VolumeAttachment total 25 items received
I0828 01:55:50.625739       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.PersistentVolumeClaim total 9 items received
I0828 01:56:12.732990       1 reflector.go:871] sigs.k8s.io/sig-storage-lib-external-provisioner/v10/controller/controller.go:861: Watch close - *v1.StorageClass total 6 items received
I0828 01:57:04.638867       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.CSINode total 8 items received
I0828 01:57:33.635183       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.StorageClass total 7 items received
I0828 01:58:54.641478       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.Node total 10 items received
I0828 02:01:24.735189       1 reflector.go:871] sigs.k8s.io/sig-storage-lib-external-provisioner/v10/controller/controller.go:861: Watch close - *v1.StorageClass total 6 items received
I0828 02:01:53.741418       1 reflector.go:871] sigs.k8s.io/sig-storage-lib-external-provisioner/v10/controller/controller.go:858: Watch close - *v1.PersistentVolume total 10 items received
I0828 02:02:25.627832       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.PersistentVolumeClaim total 7 items received
I0828 02:02:44.641171       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.CSINode total 7 items received
I0828 02:04:25.636030       1 reflector.go:871] k8s.io/client-go/informers/factory.go:160: Watch close - *v1.VolumeAttachment total 24 items received

[root@k3s log]# kubectl logs -n hpe-storage   hpe-csi-node-tlqj2   -c hpe-csi-driver
time="2025-08-28T01:54:00Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T01:54:00Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T01:54:00Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T01:55:30Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T01:55:30Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T01:55:30Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T01:57:00Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T01:57:00Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T01:57:00Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"
time="2025-08-28T01:58:30Z" level=info msg="Node monitor started monitoring the node k3s" file="nodemonitor.go:101"
time="2025-08-28T01:58:30Z" level=info msg="Found 0 multipath devices []" file="multipath.go:423"
time="2025-08-28T01:58:30Z" level=info msg="No multipath devices found on this node k3s." file="utils.go:45"

[root@k3s ~]# kubectl describe pods task-pv-pod
Events:
  Type     Reason              Age                From                     Message
  ----     ------              ----               ----                     -------
  Normal   Scheduled           96s                default-scheduler        Successfully assigned default/task-pv-pod to k3s
  Warning  FailedAttachVolume  78s (x5 over 88s)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241" : volume attachment is being deleted

journalctl -f : 
Aug 28 01:57:52 k3s k3s[1128]: E0828 01:57:52.397125    1128 pod_workers.go:1301] "Error syncing pod, skipping" err="unmounted volumes=[task-pv-storage], unattached volumes=[task-pv-storage], failed to process volumes=[]: context deadline exceeded" pod="default/task-pv-pod" podUID="11a74fd1-dcc2-4f42-a7f6-37ed7d165988"
Aug 28 01:58:10 k3s k3s[1128]: I0828 01:58:10.377070    1128 reconciler.go:360] "attacherDetacher.AttachVolume started" volumeName="kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241" nodeName="k3s" scheduledPods=["default/task-pv-pod"]
Aug 28 01:58:10 k3s k3s[1128]: E0828 01:58:10.911553    1128 csi_attacher.go:645] kubernetes.io/csi: attachment for test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
Aug 28 01:58:10 k3s k3s[1128]: E0828 01:58:10.911714    1128 nestedpendingoperations.go:348] Operation for "{volumeName:kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241 podName: nodeName:k3s}" failed. No retries permitted until 2025-08-28 02:00:12.911681277 +0000 UTC m=+245633.795883943 (durationBeforeRetry 2m2s). Error: AttachVolume.Attach failed for volume "pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241" (UniqueName: "kubernetes.io/csi/csi.hpe.com^test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241") from node "k3s" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

[datamattsson]

What does the StorageClass look like?

[swlee4833]

[root@k3s ~]# kubectl edit sc hpe-storageclass2
# Please edit the object below. Lines beginning with a '#' will be ignored,
# and an empty file will abort the edit. If an error occurs while saving this file will be
# reopened with the relevant failures.
#
allowVolumeExpansion: true
apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  annotations:
    kubectl.kubernetes.io/last-applied-configuration: |
      {"allowVolumeExpansion":true,"apiVersion":"storage.k8s.io/v1","kind":"StorageClass","metadata":{"annotations":{"storageclass.kubernetes.io/is-default-class":"true"},"name":"hpe-storageclass2"},"parame
    storageclass.kubernetes.io/is-default-class: "true"
  creationTimestamp: "2025-08-27T10:23:33Z"
  name: hpe-storageclass2
  resourceVersion: "1437666"
  uid: 07cba69b-74f7-4586-85dc-c13364a8f028
parameters:
  accessProtocol: iscsi
  allowOverrides: sparse,compression,deduplication,volblocksize,sync,description
  csi.storage.k8s.io/controller-expand-secret-name: truenas-secret
  csi.storage.k8s.io/controller-expand-secret-namespace: hpe-storage
  csi.storage.k8s.io/controller-publish-secret-name: truenas-secret
  csi.storage.k8s.io/controller-publish-secret-namespace: hpe-storage
  csi.storage.k8s.io/fstype: xfs
  csi.storage.k8s.io/node-publish-secret-name: truenas-secret
  csi.storage.k8s.io/node-publish-secret-namespace: hpe-storage
  csi.storage.k8s.io/node-stage-secret-name: truenas-secret
  csi.storage.k8s.io/node-stage-secret-namespace: hpe-storage
  csi.storage.k8s.io/provisioner-secret-name: truenas-secret
  csi.storage.k8s.io/provisioner-secret-namespace: hpe-storage
  root: test1/rpcloud
provisioner: csi.hpe.com
reclaimPolicy: Delete
volumeBindingMode: Immediate

[datamattsson]

This is very strange. What host OS is the k3s node running?

[swlee4833]

It's the Rocky Linux release 8.10 (Green Obsidian) on fedora40 kvm.

[datamattsson]

Can the VM ping the data interfaces on the TrueNAS? What does the log from the CSP say? k logs -nhpe-storage deploy/truenas-csp

[swlee4833]

[root@k3s ~]# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether 52:54:00:3e:9a:7d brd ff:ff:ff:ff:ff:ff
    altname enp0s3
    altname ens3
    inet 10.12.40.251/16 brd 10.12.255.255 scope global noprefixroute eth0
       valid_lft forever preferred_lft forever
    inet6 fe80::5054:ff:fe3e:9a7d/64 scope link
       valid_lft forever preferred_lft forever
3: flannel.1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1450 qdisc noqueue state UNKNOWN group default
    link/ether 12:71:9d:9e:bc:de brd ff:ff:ff:ff:ff:ff
    inet 10.42.0.0/32 scope global flannel.1
       valid_lft forever preferred_lft forever
    inet6 fe80::1071:9dff:fe9e:bcde/64 scope link
       valid_lft forever preferred_lft forever
4: cni0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1450 qdisc noqueue state UP group default qlen 1000
    link/ether 16:54:51:0f:67:68 brd ff:ff:ff:ff:ff:ff
    inet 10.42.0.1/24 brd 10.42.0.255 scope global cni0
       valid_lft forever preferred_lft forever
    inet6 fe80::1454:51ff:fe0f:6768/64 scope link
       valid_lft forever preferred_lft forever

[root@k3s ~]# ping -I eth0 172.16.100.2
PING 172.16.100.2 (172.16.100.2) from 10.12.40.251 eth0: 56(84) bytes of data.
64 bytes from 172.16.100.2: icmp_seq=1 ttl=62 time=3.56 ms
64 bytes from 172.16.100.2: icmp_seq=2 ttl=62 time=3.70 ms
64 bytes from 172.16.100.2: icmp_seq=3 ttl=62 time=4.13 ms
64 bytes from 172.16.100.2: icmp_seq=4 ttl=62 time=3.85 ms
64 bytes from 172.16.100.2: icmp_seq=5 ttl=62 time=3.47 ms
64 bytes from 172.16.100.2: icmp_seq=6 ttl=62 time=4.47 ms
64 bytes from 172.16.100.2: icmp_seq=7 ttl=62 time=3.63 ms
64 bytes from 172.16.100.2: icmp_seq=8 ttl=62 time=3.52 ms
64 bytes from 172.16.100.2: icmp_seq=9 ttl=62 time=4.71 ms
64 bytes from 172.16.100.2: icmp_seq=10 ttl=62 time=3.89 ms

[root@k3s ~]# kubectl logs -nhpe-storage deploy/truenas-csp -f
Fri, 29 Aug 2025 00:47:51 +0000 backend 7 INFO Volume found: test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241
Fri, 29 Aug 2025 00:47:57 +0000 backend 7 INFO Initiator updated: 2bb057cd-0a35-5755-a471-231c1cc3ac38
Fri, 29 Aug 2025 00:47:57 +0000 backend 7 INFO Host initiator created: 2bb057cd-0a35-5755-a471-231c1cc3ac38
Fri, 29 Aug 2025 00:48:17 +0000 backend 7 INFO Volume published: test1_rpcloud_pvc-75b0aa08-7fcb-4d65-a515-3490bfad3241

The truenas-csp is nothing happend when ping to truenas from vm

[datamattsson]

If the TrueNAS is on a different subnet you need to specify that in the StorageClass: https://github.com/hpe-storage/truenas-csp/blob/master/INSTALL.md#custom-auth_networks-on-truenas-scale

In this case authNetworks: 10.12.40.0/16.

[swlee4833]

I did add authNetworks parameter in sc that my vm network id or 0.0.0.0/0.

But it's same before.

Events:
  Type     Reason              Age                    From                     Message
  ----     ------              ----                   ----                     -------
  Normal   Scheduled           4m14s                  default-scheduler        Successfully assigned default/task-pv-pod2 to k3s
  Warning  FailedAttachVolume  3m23s (x7 over 3m58s)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-965207e6-9d2b-4e13-902f-009a6b077382" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_hpe-csi_pvc-965207e6-9d2b-4e13-902f-009a6b077382:2bb057cd-0a35-5755-a471-231c1cc3ac38
  Warning  FailedAttachVolume  13s (x8 over 80s)      attachdetach-controller  AttachVolume.Attach failed for volume "pvc-965207e6-9d2b-4e13-902f-009a6b077382" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:test1_hpe-csi_pvc-965207e6-9d2b-4e13-902f-009a6b077382:2bb057cd-0a35-5755-a471-231c1cc3ac38

[datamattsson]

The PVC needs to be re-provisioned.

[datamattsson]

The node driver container will contain the correct error we need to understand but the logs posted above does not contain the publish and stage request.

[swlee4833]

Is there anything I should do to solve this problem?