search

hpe-storage / truenas-csp

TrueNAS Container Storage Provider for HPE CSI Driver for Kubernetes
https://scod.hpedev.io
MIT License
67 stars 8 forks source link

Unable to attach iscsi volumes #66

Open santimar opened 3 days ago

santimar commented 3 days ago

I am using a single virtualized TrueNAS SCALE Dragonfish-24.04.2.2 to provide storage to various k3s clusters. Each cluster has it's own dataset and use truenas-csp version 2.5.1 to create volumes.

I followed install instruction and everything seems to work, since pvc can be provisioned and mounted.

However, after 7/8 nodes of different clusters start to connect to truenas, volumes struggle when they are mounted. I start to see the following event:

AttachVolume.Attach failed for volume "pvc-6cbede1c-c5e1-46dd-b6eb-8203c1e9badc" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:my-data_first.dataset_pvc-6cbede1c-c5e1-46dd-b6eb-8203c1e9badc:1d1d92c3-5fff-4b13-4f87-dba44e3067c6
AttachVolume.Attach failed for volume "pvc-6cbede1c-c5e1-46dd-b6eb-8203c1e9badc" : rpc error: code = DeadlineExceeded desc = context deadline exceeded

Sometimes, they are still successfully mounted after some time (that varies from 10 seconds to 1 hour) but other times they stay in this error state. Also, sometimes volumes are mounted without problems.

Volumes are always correctly provisioned, since i can see them listed in truenas web ui, thay just fail to be mounted. I don't seen any obvious error or timeout log on hpe-csi-controller nor hpe-csi-node nor truenas-csp, even after enabling debug log. It just seems that the mount request is pending indefinitely (and sometimes ends successfully).

TrueNAS doesn't seems to show any resource problem like high cpu usage, and I wasn't able to find any error log even there.

Any idea?

datamattsson commented 1 day ago

Thanks for reporting this. I'm out of pocket for the next couple of weeks. Can you describe more about the cluster sizes and PVC counts etc and I'll try to reproduce this.

Historically the CSI driver has struggled with Flannel as a CNI, especially on K3s, is that what you're using?

santimar commented 1 day ago

Yes, i am using k3s with flannel as CNI

k3s --version
k3s version v1.28.10+k3s1 (a4c5612e)
go version go1.21.9

and k3s is started using --flannel-backend=wireguard-native

Each cluster has 3 nodes running Ubuntu 20.04.2 LTS (GNU/Linux 5.4.0-131-generic x86_64) and 8 PVC (size between 2 and 40 GB) at the moment A total of 8 cluster are connected to the truenas instance, and on trueNAS there are ~70 targets

Each cluster has a different root parameter in the StorageClass, so that they can't share volumes by accident and hostEncryption is enabled Eg.

apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  annotations:
    storageclass.kubernetes.io/is-default-class: 'true'
  name: hpe-storageclass
parameters:
  allowOverrides: >-
    sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace
  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
  description: Volume for PVC {pvc}
  hostEncryption: 'true'
  hostEncryptionSecretName: storage-encryption-passphrase
  hostEncryptionSecretNamespace: hpe-storage
  root: my-data/first.dataset
provisioner: csi.hpe.com
reclaimPolicy: Delete
volumeBindingMode: Immediate
allowVolumeExpansion: true

I've eanbled trace log level in csi. This is the log of the hpe-csi-controller, container hpe-csi-driver I've added some comment in-between, but i'm not even sure if i'm looking on the correct place.

+ for arg in "$@"
+ '[' --endpoint=unix:///var/lib/csi/sockets/pluginproxy/csi.sock = --node-service ']'
+ '[' --endpoint=unix:///var/lib/csi/sockets/pluginproxy/csi.sock = --node-init ']'
+ for arg in "$@"
+ '[' --flavor=kubernetes = --node-service ']'
+ '[' --flavor=kubernetes = --node-init ']'
+ for arg in "$@"
+ '[' --pod-monitor = --node-service ']'
+ '[' --pod-monitor = --node-init ']'
+ for arg in "$@"
+ '[' --pod-monitor-interval=30 = --node-service ']'
+ '[' --pod-monitor-interval=30 = --node-init ']'
+ disableNodeConformance=
+ disableNodeConfiguration=
+ '[' '' = true ']'
+ '[' '' = true ']'
+ '[' '' = true ']'
+ echo 'Starting CSI plugin...'
+ exec /bin/csi-driver --endpoint=unix:///var/lib/csi/sockets/pluginproxy/csi.sock --flavor=kubernetes --pod-monitor --pod-monitor-interval=30
Starting CSI plugin...
time="2024-09-29T08:04:24Z" level=info msg="Initialized logging." alsoLogToStderr=true logFileLocation=/var/log/hpe-csi-controller.log logLevel=trace
time="2024-09-29T08:04:24Z" level=info msg="**********************************************" file="csi-driver.go:56"
time="2024-09-29T08:04:24Z" level=info msg="*************** HPE CSI DRIVER ***************" file="csi-driver.go:57"
time="2024-09-29T08:04:24Z" level=info msg="**********************************************" file="csi-driver.go:58"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> CMDLINE Exec, args: []" file="csi-driver.go:60"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> csiCliHandler" file="csi-driver.go:89"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> FileExists for path /var/lib/csi/sockets/pluginproxy" file="file.go:62"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< FileExists" file="file.go:72"
W0929 08:04:24.277753       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:04:24.277820       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: CREATE_DELETE_VOLUME" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: PUBLISH_UNPUBLISH_VOLUME" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: LIST_VOLUMES" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: CREATE_DELETE_SNAPSHOT" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: LIST_SNAPSHOTS" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: CLONE_VOLUME" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: PUBLISH_READONLY" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling controller service capability: EXPAND_VOLUME" file="driver.go:250"
time="2024-09-29T08:04:24Z" level=info msg="Enabling node service capability: STAGE_UNSTAGE_VOLUME" file="driver.go:267"
time="2024-09-29T08:04:24Z" level=info msg="Enabling node service capability: EXPAND_VOLUME" file="driver.go:267"
time="2024-09-29T08:04:24Z" level=info msg="Enabling node service capability: GET_VOLUME_STATS" file="driver.go:267"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume expansion type: ONLINE" file="driver.go:281"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume access mode: SINGLE_NODE_WRITER" file="driver.go:293"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume access mode: SINGLE_NODE_READER_ONLY" file="driver.go:293"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume access mode: MULTI_NODE_READER_ONLY" file="driver.go:293"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume access mode: MULTI_NODE_SINGLE_WRITER" file="driver.go:293"
time="2024-09-29T08:04:24Z" level=info msg="Enabling volume access mode: MULTI_NODE_MULTI_WRITER" file="driver.go:293"
time="2024-09-29T08:04:24Z" level=info msg="DB service disabled!!!" file="driver.go:145"
time="2024-09-29T08:04:24Z" level=info msg="About to start the CSI driver 'csi.hpe.com with KubeletRootDirectory /var/lib/kubelet/'" file="csi-driver.go:192"
time="2024-09-29T08:04:24Z" level=info msg="[1] reply  : [/bin/csi-driver --endpoint=unix:///var/lib/csi/sockets/pluginproxy/csi.sock --flavor=kubernetes --pod-monitor --pod-monitor-interval=30]" file="csi-driver.go:195"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> StartMonitor" file="monitor.go:48"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> monitorPod" file="monitor.go:96"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< monitorPod" file="monitor.go:115"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< StartMonitor" file="monitor.go:73"
time="2024-09-29T08:04:24Z" level=info msg="Listening for connections on address: &net.UnixAddr{Name:\"//var/lib/csi/sockets/pluginproxy/csi.sock\", Net:\"unix\"}" file="server.go:86"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/Probe" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> Probe" file="identity_server.go:39"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< Probe" file="identity_server.go:42"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginInfo" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> GetPluginInfo" file="identity_server.go:16"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< GetPluginInfo" file="identity_server.go:19"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"name\":\"csi.hpe.com\",\"vendor_version\":\"1.3\"}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginCapabilities" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> GetPluginCapabilities" file="identity_server.go:52"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< GetPluginCapabilities" file="identity_server.go:55"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Service\":{\"type\":1}}},{\"Type\":{\"Service\":{\"type\":2}}}]}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/Probe" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> Probe" file="identity_server.go:39"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< Probe" file="identity_server.go:42"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginInfo" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> GetPluginInfo" file="identity_server.go:16"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< GetPluginInfo" file="identity_server.go:19"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"name\":\"csi.hpe.com\",\"vendor_version\":\"1.3\"}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginCapabilities" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> GetPluginCapabilities" file="identity_server.go:52"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< GetPluginCapabilities" file="identity_server.go:55"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Service\":{\"type\":1}}},{\"Type\":{\"Service\":{\"type\":2}}}]}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginInfo" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> GetPluginInfo" file="identity_server.go:16"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< GetPluginInfo" file="identity_server.go:19"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"name\":\"csi.hpe.com\",\"vendor_version\":\"1.3\"}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Identity/Probe" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=info msg=">>>>> Probe" file="identity_server.go:39"
time="2024-09-29T08:04:24Z" level=info msg="<<<<< Probe" file="identity_server.go:42"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {}" file="utils.go:75"
time="2024-09-29T08:04:24Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:24Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:24Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:24Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:24Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Identity/Probe" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=info msg=">>>>> Probe" file="identity_server.go:39"
time="2024-09-29T08:04:25Z" level=info msg="<<<<< Probe" file="identity_server.go:42"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginInfo" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=info msg=">>>>> GetPluginInfo" file="identity_server.go:16"
time="2024-09-29T08:04:25Z" level=info msg="<<<<< GetPluginInfo" file="identity_server.go:19"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {\"name\":\"csi.hpe.com\",\"vendor_version\":\"1.3\"}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Identity/GetPluginCapabilities" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=info msg=">>>>> GetPluginCapabilities" file="identity_server.go:52"
time="2024-09-29T08:04:25Z" level=info msg="<<<<< GetPluginCapabilities" file="identity_server.go:55"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Service\":{\"type\":1}}},{\"Type\":{\"Service\":{\"type\":2}}}]}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:25Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:25Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
time="2024-09-29T08:04:25Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerGetCapabilities" file="utils.go:69"
time="2024-09-29T08:04:25Z" level=info msg="GRPC request: {}" file="utils.go:70"
time="2024-09-29T08:04:25Z" level=trace msg=">>>>> ControllerGetCapabilities" file="controller_server.go:1177"
time="2024-09-29T08:04:25Z" level=trace msg="<<<<< ControllerGetCapabilities" file="controller_server.go:1180"
time="2024-09-29T08:04:25Z" level=info msg="GRPC response: {\"capabilities\":[{\"Type\":{\"Rpc\":{\"type\":1}}},{\"Type\":{\"Rpc\":{\"type\":2}}},{\"Type\":{\"Rpc\":{\"type\":3}}},{\"Type\":{\"Rpc\":{\"type\":5}}},{\"Type\":{\"Rpc\":{\"type\":6}}},{\"Type\":{\"Rpc\":{\"type\":7}}},{\"Type\":{\"Rpc\":{\"type\":8}}},{\"Type\":{\"Rpc\":{\"type\":9}}}]}" file="utils.go:75"
W0929 08:04:25.282013       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:04:25.282411       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
W0929 08:04:27.764783       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:04:27.764858       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
W0929 08:04:33.987072       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:04:33.987141       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
W0929 08:04:44.838877       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:04:44.838919       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:04:54Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:04:54Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:04:54Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
W0929 08:05:08.304894       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:05:08.304955       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:05:12Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:05:12Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"

PUBLISH STARTS HERE

time="2024-09-29T08:05:12Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:05:12Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:12Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> AddRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8, value: true" file="driver.go:591"
time="2024-09-29T08:05:12Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:12Z" level=trace msg="Print RequestCache: map[ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8:true]" file="driver.go:599"
time="2024-09-29T08:05:12Z" level=trace msg="Successfully inserted an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 to the cache map" file="driver.go:600"
time="2024-09-29T08:05:12Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< AddRequest" file="driver.go:601"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:539"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> controllerPublishVolume with volumeID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1, nodeID: b1312db0-c69d-a568-6698-c1f50490d1f8, volumeCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > , readOnlyFlag: false, volumeContext: map[allowOverrides:sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace compression:LZ4 csi.storage.k8s.io/pv/name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 csi.storage.k8s.io/pvc/name:data-kafka-controller-2 csi.storage.k8s.io/pvc/namespace:mynamespace deduplication:OFF description:Volume for PVC {pvc} fsType:xfs hostEncryption:true hostEncryptionSecretName:storage-encryption-passphrase hostEncryptionSecretNamespace:hpe-storage root:my-data/first.dataset storage.kubernetes.io/csiProvisionerIdentity:1727529462858-4320-csi.hpe.com sync:STANDARD targetScope:volume volblocksize:8K volumeAccessMode:mount]" file="controller_server.go:754"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> IsValidVolumeCapability, volCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:86"
time="2024-09-29T08:05:12Z" level=trace msg="Found access_mode: SINGLE_NODE_WRITER" file="controller_server.go:95"
time="2024-09-29T08:05:12Z" level=trace msg="Found Mount access_type fs_type:\"xfs\" " file="controller_server.go:119"
time="2024-09-29T08:05:12Z" level=trace msg="Found Mount access_type, FileSystem: xfs" file="controller_server.go:122"
time="2024-09-29T08:05:12Z" level=trace msg="Total length of mount flags: 0" file="controller_server.go:136"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< IsValidVolumeCapability" file="controller_server.go:150"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> getVolumeAccessType, volCap: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:26"
time="2024-09-29T08:05:12Z" level=trace msg="Found mount access type fs_type:\"xfs\" " file="controller_server.go:39"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< getVolumeAccessType" file="controller_server.go:40"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> GetVolume, ID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="driver.go:431"
time="2024-09-29T08:05:12Z" level=trace msg="Secrets are provided. Checking with this particular storage provider." file="driver.go:438"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> AddStorageProvider" file="driver.go:331"
time="2024-09-29T08:05:12Z" level=info msg="Adding connection to CSP at IP truenas.internaldomain.com, port 8080, context path , with username ignored-when-using-api-key and serviceName truenas-csp-svc" file="driver.go:334"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> NewContainerStorageProvider" file="container_storage_provider.go:66"
time="2024-09-29T08:05:12Z" level=trace msg=">>>>> getCspClient (service) using URI http://truenas-csp-svc:8080 and username ignored-when-using-api-key with timeout set to 60 seconds" file="container_storage_provider.go:942"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< getCspClient" file="container_storage_provider.go:948"
time="2024-09-29T08:05:12Z" level=trace msg="Attempting initial login to CSP" file="container_storage_provider.go:81"
time="2024-09-29T08:05:12Z" level=info msg="About to attempt login to CSP for backend truenas.internaldomain.com" file="container_storage_provider.go:108"
time="2024-09-29T08:05:12Z" level=trace msg="Acquiring mutex lock for truenas.internaldomain.com" file="concurrent.go:44"
time="2024-09-29T08:05:12Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/tokens" file="client.go:173"
time="2024-09-29T08:05:12Z" level=trace msg="response: 200 OK, length=232" file="client.go:224"
time="2024-09-29T08:05:12Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0003ecf00 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:05:12Z" level=trace msg="Releasing mutex lock for truenas.internaldomain.com" file="concurrent.go:67"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< NewContainerStorageProvider" file="container_storage_provider.go:92"
time="2024-09-29T08:05:12Z" level=trace msg="Number of cached/known storage providers: 1" file="driver.go:345"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< AddStorageProvider" file="driver.go:346"
time="2024-09-29T08:05:12Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:389"
time="2024-09-29T08:05:12Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:12Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:12Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:12Z" level=trace msg="Request: action=GET path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="client.go:173"
time="2024-09-29T08:05:14Z" level=trace msg="response: 200 OK, length=405" file="client.go:224"
time="2024-09-29T08:05:14Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0004d9e40 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:05:14Z" level=trace msg="Found Volume &{ID:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Size:2147483648 Description:Volume for PVC data-kafka-controller-2 InUse:false Published:false BaseSnapID: ParentVolID: Clone:false Config:map[compression:LZ4 deduplication:OFF sync:STANDARD target_scope:volume volblocksize:8K] Metadata:[] SerialNumber: AccessProtocol: Iqn: Iqns:[] DiscoveryIP: DiscoveryIPs:[] MountPoint: Status:map[] Chap:<nil> Networks:[] ConnectionMode: LunID: TargetScope: IscsiSessions:[] FcSessions:[] VolumeGroupId: SecondaryArrayDetails: UsedBytes:0 FreeBytes:0 EncryptionKey:}" file="driver.go:469"
time="2024-09-29T08:05:14Z" level=trace msg="<<<<< GetVolume" file="driver.go:470"
time="2024-09-29T08:05:14Z" level=trace msg="volume config is map[compression:LZ4 deduplication:OFF sync:STANDARD targetScope:volume volblocksize:8K]" file="controller_server.go:823"
time="2024-09-29T08:05:14Z" level=trace msg=">>>>>> GetNodeInfo from node ID b1312db0-c69d-a568-6698-c1f50490d1f8" file="flavor.go:331"
time="2024-09-29T08:05:14Z" level=trace msg="Found the following HPE Node Info objects: &{{ } { 751184  <nil>} [{{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c3    5ba76957-0085-49f4-8761-04abc656873f 495465 1 2024-09-28 20:27:06 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:06 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {df97b3bc-a8d5-2492-cbdc-197130594330 [iqn.1993-08.org.debian:01:4efdaa484446] [192.168.150.117/24 10.42.2.0/32 10.42.2.1/24] []  }}]}" file="flavor.go:338"
time="2024-09-29T08:05:14Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:05:14Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:05:14Z" level=trace msg="<<<<<< GetNodeInfo" file="flavor.go:364"
time="2024-09-29T08:05:14Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1009"
time="2024-09-29T08:05:14Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1015"
time="2024-09-29T08:05:14Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:995"
time="2024-09-29T08:05:14Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1001"
time="2024-09-29T08:05:14Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:05:14Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:05:14Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:05:14Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:05:14Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:05:14Z" level=trace msg="Notifying CSP about Node with ID  and UUID b1312db0-c69d-a568-6698-c1f50490d1f8" file="controller_server.go:861"
time="2024-09-29T08:05:14Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:14Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:14Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:14Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/hosts" file="client.go:173"
time="2024-09-29T08:05:18Z" level=trace msg="response: 200 OK, length=278" file="client.go:224"
time="2024-09-29T08:05:18Z" level=debug msg="Received a null reader. That is not expected." file="client.go:245"
time="2024-09-29T08:05:18Z" level=trace msg="Defaulting to access protocol iscsi" file="controller_server.go:877"
time="2024-09-29T08:05:18Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:18Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:18Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:18Z" level=trace msg="Request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1/actions/publish" file="client.go:173"
time="2024-09-29T08:05:24Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:05:24Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:05:24Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
time="2024-09-29T08:05:27Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:05:27Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:05:27Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:05:27Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:05:27Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:05:27Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:27Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:27Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:05:27Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:532"
time="2024-09-29T08:05:27Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:722"
time="2024-09-29T08:05:27Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="utils.go:73"
time="2024-09-29T08:05:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:05:28Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:05:28Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:05:28Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:05:28Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:05:28Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:28Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:28Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:05:28Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:532"
time="2024-09-29T08:05:28Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:722"
time="2024-09-29T08:05:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="utils.go:73"
time="2024-09-29T08:05:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:05:32Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:05:32Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:05:32Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:05:32Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:05:32Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:32Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:532"
time="2024-09-29T08:05:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="utils.go:73"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:722"
time="2024-09-29T08:05:32Z" level=trace msg="response: 200 OK, length=260" file="client.go:224"
time="2024-09-29T08:05:32Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0003ec040 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:05:32Z" level=trace msg="PublishInfo response from CSP: &{SerialNumber:6589cfc000000a69472b2e921fd54e29 AccessInfo:{BlockDeviceAccessInfo:{AccessProtocol:iscsi TargetNames:[iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1] LunID:0 SecondaryBackendDetails:{PeerArrayDetails:[]} IscsiAccessInfo:{DiscoveryIPs:[192.168.150.241] ChapUser: ChapPassword:}} VirtualDeviceAccessInfo:{}}}" file="controller_server.go:887"
time="2024-09-29T08:05:32Z" level=trace msg="Adding filesystem details to the publish context" file="controller_server.go:930"
time="2024-09-29T08:05:32Z" level=trace msg="Volume pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 with ID my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 published with the following details: [serialNumber 6589cfc000000a69472b2e921fd54e29 accessProtocol iscsi targetScope volume fsType xfs fsMode  fsCreateOptions  targetNames iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 lunId 0 discoveryIps 192.168.150.241 readOnly false volumeAccessMode mount fsOwner ]" file="controller_server.go:942"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< controllerPublishVolume" file="controller_server.go:944"

VOLUME SHOULD BE PUBLISHED AFTER THIS POINT

time="2024-09-29T08:05:32Z" level=trace msg=">>>>> ClearRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:605"
time="2024-09-29T08:05:32Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:32Z" level=trace msg="Print RequestCache: map[]" file="driver.go:625"
time="2024-09-29T08:05:32Z" level=trace msg="Successfully removed an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 from the cache map" file="driver.go:626"
time="2024-09-29T08:05:32Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< ClearRequest" file="driver.go:627"
time="2024-09-29T08:05:32Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:740"
time="2024-09-29T08:05:32Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"192.168.150.241\",\"fsCreateOptions\":\"\",\"fsMode\":\"\",\"fsOwner\":\"\",\"fsType\":\"xfs\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000a69472b2e921fd54e29\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"
time="2024-09-29T08:05:40Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:05:40Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:05:40Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:40Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> AddRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8, value: true" file="driver.go:591"
time="2024-09-29T08:05:40Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:40Z" level=trace msg="Print RequestCache: map[ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8:true]" file="driver.go:599"
time="2024-09-29T08:05:40Z" level=trace msg="Successfully inserted an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 to the cache map" file="driver.go:600"
time="2024-09-29T08:05:40Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< AddRequest" file="driver.go:601"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:539"

A SECOND PUBLISH FOR THE SAME VOLUME STARTS HERE

time="2024-09-29T08:05:40Z" level=trace msg=">>>>> controllerPublishVolume with volumeID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1, nodeID: b1312db0-c69d-a568-6698-c1f50490d1f8, volumeCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > , readOnlyFlag: false, volumeContext: map[allowOverrides:sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace compression:LZ4 csi.storage.k8s.io/pv/name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 csi.storage.k8s.io/pvc/name:data-kafka-controller-2 csi.storage.k8s.io/pvc/namespace:mynamespace deduplication:OFF description:Volume for PVC {pvc} fsType:xfs hostEncryption:true hostEncryptionSecretName:storage-encryption-passphrase hostEncryptionSecretNamespace:hpe-storage root:my-data/first.dataset storage.kubernetes.io/csiProvisionerIdentity:1727529462858-4320-csi.hpe.com sync:STANDARD targetScope:volume volblocksize:8K volumeAccessMode:mount]" file="controller_server.go:754"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> IsValidVolumeCapability, volCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:86"
time="2024-09-29T08:05:40Z" level=trace msg="Found access_mode: SINGLE_NODE_WRITER" file="controller_server.go:95"
time="2024-09-29T08:05:40Z" level=trace msg="Found Mount access_type fs_type:\"xfs\" " file="controller_server.go:119"
time="2024-09-29T08:05:40Z" level=trace msg="Found Mount access_type, FileSystem: xfs" file="controller_server.go:122"
time="2024-09-29T08:05:40Z" level=trace msg="Total length of mount flags: 0" file="controller_server.go:136"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< IsValidVolumeCapability" file="controller_server.go:150"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> getVolumeAccessType, volCap: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:26"
time="2024-09-29T08:05:40Z" level=trace msg="Found mount access type fs_type:\"xfs\" " file="controller_server.go:39"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< getVolumeAccessType" file="controller_server.go:40"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> GetVolume, ID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="driver.go:431"
time="2024-09-29T08:05:40Z" level=trace msg="Secrets are provided. Checking with this particular storage provider." file="driver.go:438"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:05:40Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:05:40Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:05:40Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:05:40Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:40Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:40Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:40Z" level=trace msg="Request: action=GET path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="client.go:173"
time="2024-09-29T08:05:42Z" level=trace msg="response: 200 OK, length=404" file="client.go:224"
time="2024-09-29T08:05:42Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0000ae280 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:05:42Z" level=trace msg="Found Volume &{ID:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Size:2147483648 Description:Volume for PVC data-kafka-controller-2 InUse:false Published:true BaseSnapID: ParentVolID: Clone:false Config:map[compression:LZ4 deduplication:OFF sync:STANDARD target_scope:volume volblocksize:8K] Metadata:[] SerialNumber: AccessProtocol: Iqn: Iqns:[] DiscoveryIP: DiscoveryIPs:[] MountPoint: Status:map[] Chap:<nil> Networks:[] ConnectionMode: LunID: TargetScope: IscsiSessions:[] FcSessions:[] VolumeGroupId: SecondaryArrayDetails: UsedBytes:0 FreeBytes:0 EncryptionKey:}" file="driver.go:469"
time="2024-09-29T08:05:42Z" level=trace msg="<<<<< GetVolume" file="driver.go:470"
time="2024-09-29T08:05:42Z" level=trace msg="volume config is map[compression:LZ4 deduplication:OFF sync:STANDARD targetScope:volume volblocksize:8K]" file="controller_server.go:823"
time="2024-09-29T08:05:42Z" level=trace msg=">>>>>> GetNodeInfo from node ID b1312db0-c69d-a568-6698-c1f50490d1f8" file="flavor.go:331"
time="2024-09-29T08:05:42Z" level=trace msg="Found the following HPE Node Info objects: &{{ } { 751366  <nil>} [{{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c3    5ba76957-0085-49f4-8761-04abc656873f 495465 1 2024-09-28 20:27:06 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:06 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {df97b3bc-a8d5-2492-cbdc-197130594330 [iqn.1993-08.org.debian:01:4efdaa484446] [192.168.150.117/24 10.42.2.0/32 10.42.2.1/24] []  }}]}" file="flavor.go:338"
time="2024-09-29T08:05:42Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:05:42Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:05:42Z" level=trace msg="<<<<<< GetNodeInfo" file="flavor.go:364"
time="2024-09-29T08:05:42Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1009"
time="2024-09-29T08:05:42Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1015"
time="2024-09-29T08:05:42Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:995"
time="2024-09-29T08:05:42Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1001"
time="2024-09-29T08:05:42Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:05:42Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:05:42Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:05:42Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:05:42Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:05:42Z" level=trace msg="Notifying CSP about Node with ID  and UUID b1312db0-c69d-a568-6698-c1f50490d1f8" file="controller_server.go:861"
time="2024-09-29T08:05:42Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:42Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:42Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:42Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/hosts" file="client.go:173"
W0929 08:05:43.304023       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:05:43.304089       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:05:46Z" level=trace msg="response: 200 OK, length=278" file="client.go:224"
time="2024-09-29T08:05:46Z" level=debug msg="Received a null reader. That is not expected." file="client.go:245"
time="2024-09-29T08:05:46Z" level=trace msg="Defaulting to access protocol iscsi" file="controller_server.go:877"
time="2024-09-29T08:05:46Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:05:46Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:05:46Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:05:46Z" level=trace msg="Request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1/actions/publish" file="client.go:173"
time="2024-09-29T08:05:54Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:05:54Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:05:54Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
time="2024-09-29T08:05:57Z" level=trace msg="response: 200 OK, length=260" file="client.go:224"
time="2024-09-29T08:05:57Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0003ecb80 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:05:57Z" level=trace msg="PublishInfo response from CSP: &{SerialNumber:6589cfc000000a69472b2e921fd54e29 AccessInfo:{BlockDeviceAccessInfo:{AccessProtocol:iscsi TargetNames:[iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1] LunID:0 SecondaryBackendDetails:{PeerArrayDetails:[]} IscsiAccessInfo:{DiscoveryIPs:[192.168.150.241] ChapUser: ChapPassword:}} VirtualDeviceAccessInfo:{}}}" file="controller_server.go:887"
time="2024-09-29T08:05:57Z" level=trace msg="Adding filesystem details to the publish context" file="controller_server.go:930"
time="2024-09-29T08:05:57Z" level=trace msg="Volume pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 with ID my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 published with the following details: [volumeAccessMode mount fsType xfs fsOwner  accessProtocol iscsi targetScope volume lunId 0 discoveryIps 192.168.150.241 readOnly false fsMode  serialNumber 6589cfc000000a69472b2e921fd54e29 targetNames iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 fsCreateOptions ]" file="controller_server.go:942"
time="2024-09-29T08:05:57Z" level=trace msg="<<<<< controllerPublishVolume" file="controller_server.go:944"
time="2024-09-29T08:05:57Z" level=trace msg=">>>>> ClearRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:605"
time="2024-09-29T08:05:57Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:05:57Z" level=trace msg="Print RequestCache: map[]" file="driver.go:625"
time="2024-09-29T08:05:57Z" level=trace msg="Successfully removed an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 from the cache map" file="driver.go:626"
time="2024-09-29T08:05:57Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:05:57Z" level=trace msg="<<<<< ClearRequest" file="driver.go:627"
time="2024-09-29T08:05:57Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:740"
time="2024-09-29T08:05:57Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"192.168.150.241\",\"fsCreateOptions\":\"\",\"fsMode\":\"\",\"fsOwner\":\"\",\"fsType\":\"xfs\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000a69472b2e921fd54e29\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"
time="2024-09-29T08:06:11Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:06:11Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:06:11Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:06:11Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> AddRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8, value: true" file="driver.go:591"
time="2024-09-29T08:06:11Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:06:11Z" level=trace msg="Print RequestCache: map[ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8:true]" file="driver.go:599"
time="2024-09-29T08:06:11Z" level=trace msg="Successfully inserted an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 to the cache map" file="driver.go:600"
time="2024-09-29T08:06:11Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< AddRequest" file="driver.go:601"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:539"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> controllerPublishVolume with volumeID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1, nodeID: b1312db0-c69d-a568-6698-c1f50490d1f8, volumeCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > , readOnlyFlag: false, volumeContext: map[allowOverrides:sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace compression:LZ4 csi.storage.k8s.io/pv/name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 csi.storage.k8s.io/pvc/name:data-kafka-controller-2 csi.storage.k8s.io/pvc/namespace:mynamespace deduplication:OFF description:Volume for PVC {pvc} fsType:xfs hostEncryption:true hostEncryptionSecretName:storage-encryption-passphrase hostEncryptionSecretNamespace:hpe-storage root:my-data/first.dataset storage.kubernetes.io/csiProvisionerIdentity:1727529462858-4320-csi.hpe.com sync:STANDARD targetScope:volume volblocksize:8K volumeAccessMode:mount]" file="controller_server.go:754"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> IsValidVolumeCapability, volCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:86"
time="2024-09-29T08:06:11Z" level=trace msg="Found access_mode: SINGLE_NODE_WRITER" file="controller_server.go:95"
time="2024-09-29T08:06:11Z" level=trace msg="Found Mount access_type fs_type:\"xfs\" " file="controller_server.go:119"
time="2024-09-29T08:06:11Z" level=trace msg="Found Mount access_type, FileSystem: xfs" file="controller_server.go:122"
time="2024-09-29T08:06:11Z" level=trace msg="Total length of mount flags: 0" file="controller_server.go:136"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< IsValidVolumeCapability" file="controller_server.go:150"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> getVolumeAccessType, volCap: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:26"
time="2024-09-29T08:06:11Z" level=trace msg="Found mount access type fs_type:\"xfs\" " file="controller_server.go:39"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< getVolumeAccessType" file="controller_server.go:40"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> GetVolume, ID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="driver.go:431"
time="2024-09-29T08:06:11Z" level=trace msg="Secrets are provided. Checking with this particular storage provider." file="driver.go:438"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:06:11Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:06:11Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:06:11Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:06:11Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:06:11Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:06:11Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:06:11Z" level=trace msg="Request: action=GET path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="client.go:173"
time="2024-09-29T08:06:13Z" level=trace msg="response: 200 OK, length=404" file="client.go:224"
time="2024-09-29T08:06:13Z" level=debug msg="About to decode the error response &{0x4ff020 0xc000564a40 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:06:13Z" level=trace msg="Found Volume &{ID:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Size:2147483648 Description:Volume for PVC data-kafka-controller-2 InUse:false Published:true BaseSnapID: ParentVolID: Clone:false Config:map[compression:LZ4 deduplication:OFF sync:STANDARD target_scope:volume volblocksize:8K] Metadata:[] SerialNumber: AccessProtocol: Iqn: Iqns:[] DiscoveryIP: DiscoveryIPs:[] MountPoint: Status:map[] Chap:<nil> Networks:[] ConnectionMode: LunID: TargetScope: IscsiSessions:[] FcSessions:[] VolumeGroupId: SecondaryArrayDetails: UsedBytes:0 FreeBytes:0 EncryptionKey:}" file="driver.go:469"
time="2024-09-29T08:06:13Z" level=trace msg="<<<<< GetVolume" file="driver.go:470"
time="2024-09-29T08:06:13Z" level=trace msg="volume config is map[compression:LZ4 deduplication:OFF sync:STANDARD targetScope:volume volblocksize:8K]" file="controller_server.go:823"
time="2024-09-29T08:06:13Z" level=trace msg=">>>>>> GetNodeInfo from node ID b1312db0-c69d-a568-6698-c1f50490d1f8" file="flavor.go:331"
time="2024-09-29T08:06:13Z" level=trace msg="Found the following HPE Node Info objects: &{{ } { 751556  <nil>} [{{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c3    5ba76957-0085-49f4-8761-04abc656873f 495465 1 2024-09-28 20:27:06 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:06 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {df97b3bc-a8d5-2492-cbdc-197130594330 [iqn.1993-08.org.debian:01:4efdaa484446] [192.168.150.117/24 10.42.2.0/32 10.42.2.1/24] []  }}]}" file="flavor.go:338"
time="2024-09-29T08:06:13Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:06:13Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:06:13Z" level=trace msg="<<<<<< GetNodeInfo" file="flavor.go:364"
time="2024-09-29T08:06:13Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1009"
time="2024-09-29T08:06:13Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1015"
time="2024-09-29T08:06:13Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:995"
time="2024-09-29T08:06:13Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1001"
time="2024-09-29T08:06:13Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:06:13Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:06:13Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:06:13Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:06:13Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:06:13Z" level=trace msg="Notifying CSP about Node with ID  and UUID b1312db0-c69d-a568-6698-c1f50490d1f8" file="controller_server.go:861"
time="2024-09-29T08:06:13Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:06:13Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:06:13Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:06:13Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/hosts" file="client.go:173"
time="2024-09-29T08:06:17Z" level=trace msg="response: 200 OK, length=278" file="client.go:224"
time="2024-09-29T08:06:17Z" level=debug msg="Received a null reader. That is not expected." file="client.go:245"
time="2024-09-29T08:06:17Z" level=trace msg="Defaulting to access protocol iscsi" file="controller_server.go:877"
time="2024-09-29T08:06:17Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:06:17Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:06:17Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:06:17Z" level=trace msg="Request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1/actions/publish" file="client.go:173"
time="2024-09-29T08:06:24Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:06:24Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:06:24Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
W0929 08:06:24.469429       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:06:24.469464       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:06:28Z" level=trace msg="response: 200 OK, length=260" file="client.go:224"
time="2024-09-29T08:06:28Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0003ed440 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:06:28Z" level=trace msg="PublishInfo response from CSP: &{SerialNumber:6589cfc000000a69472b2e921fd54e29 AccessInfo:{BlockDeviceAccessInfo:{AccessProtocol:iscsi TargetNames:[iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1] LunID:0 SecondaryBackendDetails:{PeerArrayDetails:[]} IscsiAccessInfo:{DiscoveryIPs:[192.168.150.241] ChapUser: ChapPassword:}} VirtualDeviceAccessInfo:{}}}" file="controller_server.go:887"
time="2024-09-29T08:06:28Z" level=trace msg="Adding filesystem details to the publish context" file="controller_server.go:930"
time="2024-09-29T08:06:28Z" level=trace msg="Volume pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 with ID my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 published with the following details: [targetNames iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 readOnly false fsType xfs fsOwner  fsMode  volumeAccessMode mount fsCreateOptions  serialNumber 6589cfc000000a69472b2e921fd54e29 accessProtocol iscsi targetScope volume lunId 0 discoveryIps 192.168.150.241]" file="controller_server.go:942"
time="2024-09-29T08:06:28Z" level=trace msg="<<<<< controllerPublishVolume" file="controller_server.go:944"

SECOND PUBLISH ENDS WITHOUT ERROR AS WELL

time="2024-09-29T08:06:28Z" level=trace msg=">>>>> ClearRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:605"
time="2024-09-29T08:06:28Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:06:28Z" level=trace msg="Print RequestCache: map[]" file="driver.go:625"
time="2024-09-29T08:06:28Z" level=trace msg="Successfully removed an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 from the cache map" file="driver.go:626"
time="2024-09-29T08:06:28Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:06:28Z" level=trace msg="<<<<< ClearRequest" file="driver.go:627"
time="2024-09-29T08:06:28Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:740"
time="2024-09-29T08:06:28Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"192.168.150.241\",\"fsCreateOptions\":\"\",\"fsMode\":\"\",\"fsOwner\":\"\",\"fsType\":\"xfs\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000a69472b2e921fd54e29\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"
time="2024-09-29T08:06:54Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:06:54Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:06:54Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
time="2024-09-29T08:06:58Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:06:58Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:06:58Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:06:58Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> AddRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8, value: true" file="driver.go:591"
time="2024-09-29T08:06:58Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:06:58Z" level=trace msg="Print RequestCache: map[ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8:true]" file="driver.go:599"
time="2024-09-29T08:06:58Z" level=trace msg="Successfully inserted an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 to the cache map" file="driver.go:600"
time="2024-09-29T08:06:58Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< AddRequest" file="driver.go:601"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:539"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> controllerPublishVolume with volumeID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1, nodeID: b1312db0-c69d-a568-6698-c1f50490d1f8, volumeCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > , readOnlyFlag: false, volumeContext: map[allowOverrides:sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace compression:LZ4 csi.storage.k8s.io/pv/name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 csi.storage.k8s.io/pvc/name:data-kafka-controller-2 csi.storage.k8s.io/pvc/namespace:mynamespace deduplication:OFF description:Volume for PVC {pvc} fsType:xfs hostEncryption:true hostEncryptionSecretName:storage-encryption-passphrase hostEncryptionSecretNamespace:hpe-storage root:my-data/first.dataset storage.kubernetes.io/csiProvisionerIdentity:1727529462858-4320-csi.hpe.com sync:STANDARD targetScope:volume volblocksize:8K volumeAccessMode:mount]" file="controller_server.go:754"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> IsValidVolumeCapability, volCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:86"
time="2024-09-29T08:06:58Z" level=trace msg="Found access_mode: SINGLE_NODE_WRITER" file="controller_server.go:95"
time="2024-09-29T08:06:58Z" level=trace msg="Found Mount access_type fs_type:\"xfs\" " file="controller_server.go:119"
time="2024-09-29T08:06:58Z" level=trace msg="Found Mount access_type, FileSystem: xfs" file="controller_server.go:122"
time="2024-09-29T08:06:58Z" level=trace msg="Total length of mount flags: 0" file="controller_server.go:136"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< IsValidVolumeCapability" file="controller_server.go:150"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> getVolumeAccessType, volCap: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:26"
time="2024-09-29T08:06:58Z" level=trace msg="Found mount access type fs_type:\"xfs\" " file="controller_server.go:39"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< getVolumeAccessType" file="controller_server.go:40"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> GetVolume, ID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="driver.go:431"
time="2024-09-29T08:06:58Z" level=trace msg="Secrets are provided. Checking with this particular storage provider." file="driver.go:438"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:06:58Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:06:58Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:06:58Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:06:58Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:06:58Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:06:58Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:06:58Z" level=trace msg="Request: action=GET path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="client.go:173"
time="2024-09-29T08:07:00Z" level=trace msg="response: 200 OK, length=404" file="client.go:224"
time="2024-09-29T08:07:00Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0004d9a40 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:07:00Z" level=trace msg="Found Volume &{ID:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Size:2147483648 Description:Volume for PVC data-kafka-controller-2 InUse:false Published:true BaseSnapID: ParentVolID: Clone:false Config:map[compression:LZ4 deduplication:OFF sync:STANDARD target_scope:volume volblocksize:8K] Metadata:[] SerialNumber: AccessProtocol: Iqn: Iqns:[] DiscoveryIP: DiscoveryIPs:[] MountPoint: Status:map[] Chap:<nil> Networks:[] ConnectionMode: LunID: TargetScope: IscsiSessions:[] FcSessions:[] VolumeGroupId: SecondaryArrayDetails: UsedBytes:0 FreeBytes:0 EncryptionKey:}" file="driver.go:469"
time="2024-09-29T08:07:00Z" level=trace msg="<<<<< GetVolume" file="driver.go:470"
time="2024-09-29T08:07:00Z" level=trace msg="volume config is map[compression:LZ4 deduplication:OFF sync:STANDARD targetScope:volume volblocksize:8K]" file="controller_server.go:823"
time="2024-09-29T08:07:00Z" level=trace msg=">>>>>> GetNodeInfo from node ID b1312db0-c69d-a568-6698-c1f50490d1f8" file="flavor.go:331"
time="2024-09-29T08:07:00Z" level=trace msg="Found the following HPE Node Info objects: &{{ } { 751841  <nil>} [{{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c3    5ba76957-0085-49f4-8761-04abc656873f 495465 1 2024-09-28 20:27:06 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:06 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {df97b3bc-a8d5-2492-cbdc-197130594330 [iqn.1993-08.org.debian:01:4efdaa484446] [192.168.150.117/24 10.42.2.0/32 10.42.2.1/24] []  }}]}" file="flavor.go:338"
time="2024-09-29T08:07:00Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:07:00Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:07:00Z" level=trace msg="<<<<<< GetNodeInfo" file="flavor.go:364"
time="2024-09-29T08:07:00Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1009"
time="2024-09-29T08:07:00Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1015"
time="2024-09-29T08:07:00Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:995"
time="2024-09-29T08:07:00Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1001"
time="2024-09-29T08:07:00Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:07:00Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:07:00Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:07:00Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:07:00Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:07:00Z" level=trace msg="Notifying CSP about Node with ID  and UUID b1312db0-c69d-a568-6698-c1f50490d1f8" file="controller_server.go:861"
time="2024-09-29T08:07:00Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:07:00Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:07:00Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:07:00Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/hosts" file="client.go:173"
time="2024-09-29T08:07:04Z" level=trace msg="response: 200 OK, length=278" file="client.go:224"
time="2024-09-29T08:07:04Z" level=debug msg="Received a null reader. That is not expected." file="client.go:245"
time="2024-09-29T08:07:04Z" level=trace msg="Defaulting to access protocol iscsi" file="controller_server.go:877"
time="2024-09-29T08:07:04Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:07:04Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:07:04Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:07:04Z" level=trace msg="Request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1/actions/publish" file="client.go:173"
W0929 08:07:04.562554       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:07:04.562619       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:07:15Z" level=trace msg="response: 200 OK, length=260" file="client.go:224"
time="2024-09-29T08:07:15Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0002ee000 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:07:15Z" level=trace msg="PublishInfo response from CSP: &{SerialNumber:6589cfc000000a69472b2e921fd54e29 AccessInfo:{BlockDeviceAccessInfo:{AccessProtocol:iscsi TargetNames:[iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1] LunID:0 SecondaryBackendDetails:{PeerArrayDetails:[]} IscsiAccessInfo:{DiscoveryIPs:[192.168.150.241] ChapUser: ChapPassword:}} VirtualDeviceAccessInfo:{}}}" file="controller_server.go:887"
time="2024-09-29T08:07:15Z" level=trace msg="Adding filesystem details to the publish context" file="controller_server.go:930"
time="2024-09-29T08:07:15Z" level=trace msg="Volume pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 with ID my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 published with the following details: [fsOwner  serialNumber 6589cfc000000a69472b2e921fd54e29 targetScope volume lunId 0 discoveryIps 192.168.150.241 readOnly false fsType xfs accessProtocol iscsi targetNames iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 volumeAccessMode mount fsMode  fsCreateOptions ]" file="controller_server.go:942"
time="2024-09-29T08:07:15Z" level=trace msg="<<<<< controllerPublishVolume" file="controller_server.go:944"
time="2024-09-29T08:07:15Z" level=trace msg=">>>>> ClearRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:605"
time="2024-09-29T08:07:15Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:07:15Z" level=trace msg="Print RequestCache: map[]" file="driver.go:625"
time="2024-09-29T08:07:15Z" level=trace msg="Successfully removed an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 from the cache map" file="driver.go:626"
time="2024-09-29T08:07:15Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:07:15Z" level=trace msg="<<<<< ClearRequest" file="driver.go:627"
time="2024-09-29T08:07:15Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:740"
time="2024-09-29T08:07:15Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"192.168.150.241\",\"fsCreateOptions\":\"\",\"fsMode\":\"\",\"fsOwner\":\"\",\"fsType\":\"xfs\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000a69472b2e921fd54e29\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"
time="2024-09-29T08:07:24Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:07:24Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:07:24Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
W0929 08:07:37.449606       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:07:37.449669       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:07:54Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:07:54Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:07:54Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
W0929 08:08:13.921832       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:08:13.921872       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:08:17Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2024-09-29T08:08:17Z" level=info msg="GRPC request: {\"node_id\":\"b1312db0-c69d-a568-6698-c1f50490d1f8\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"xfs\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"allowOverrides\":\"sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace\",\"compression\":\"LZ4\",\"csi.storage.k8s.io/pv/name\":\"pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"csi.storage.k8s.io/pvc/name\":\"data-kafka-controller-2\",\"csi.storage.k8s.io/pvc/namespace\":\"mynamespace\",\"deduplication\":\"OFF\",\"description\":\"Volume for PVC {pvc}\",\"fsType\":\"xfs\",\"hostEncryption\":\"true\",\"hostEncryptionSecretName\":\"storage-encryption-passphrase\",\"hostEncryptionSecretNamespace\":\"hpe-storage\",\"root\":\"my-data/first.dataset\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1727529462858-4320-csi.hpe.com\",\"sync\":\"STANDARD\",\"targetScope\":\"volume\",\"volblocksize\":\"8K\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\"}" file="utils.go:70"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> ControllerPublishVolume" file="controller_server.go:704"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> HandleDuplicateRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:522"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> GetRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:579"
time="2024-09-29T08:08:17Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:08:17Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< GetRequest" file="driver.go:586"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> AddRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8, value: true" file="driver.go:591"
time="2024-09-29T08:08:17Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:08:17Z" level=trace msg="Print RequestCache: map[ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8:true]" file="driver.go:599"
time="2024-09-29T08:08:17Z" level=trace msg="Successfully inserted an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 to the cache map" file="driver.go:600"
time="2024-09-29T08:08:17Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< AddRequest" file="driver.go:601"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< HandleDuplicateRequest" file="driver.go:539"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> controllerPublishVolume with volumeID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1, nodeID: b1312db0-c69d-a568-6698-c1f50490d1f8, volumeCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > , readOnlyFlag: false, volumeContext: map[allowOverrides:sparse,compression,deduplication,sync,description,hostEncryption,hostEncryptionSecretName,hostEncryptionSecretNamespace compression:LZ4 csi.storage.k8s.io/pv/name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 csi.storage.k8s.io/pvc/name:data-kafka-controller-2 csi.storage.k8s.io/pvc/namespace:mynamespace deduplication:OFF description:Volume for PVC {pvc} fsType:xfs hostEncryption:true hostEncryptionSecretName:storage-encryption-passphrase hostEncryptionSecretNamespace:hpe-storage root:my-data/first.dataset storage.kubernetes.io/csiProvisionerIdentity:1727529462858-4320-csi.hpe.com sync:STANDARD targetScope:volume volblocksize:8K volumeAccessMode:mount]" file="controller_server.go:754"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> IsValidVolumeCapability, volCapability: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:86"
time="2024-09-29T08:08:17Z" level=trace msg="Found access_mode: SINGLE_NODE_WRITER" file="controller_server.go:95"
time="2024-09-29T08:08:17Z" level=trace msg="Found Mount access_type fs_type:\"xfs\" " file="controller_server.go:119"
time="2024-09-29T08:08:17Z" level=trace msg="Found Mount access_type, FileSystem: xfs" file="controller_server.go:122"
time="2024-09-29T08:08:17Z" level=trace msg="Total length of mount flags: 0" file="controller_server.go:136"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< IsValidVolumeCapability" file="controller_server.go:150"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> getVolumeAccessType, volCap: mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_WRITER > " file="controller_server.go:26"
time="2024-09-29T08:08:17Z" level=trace msg="Found mount access type fs_type:\"xfs\" " file="controller_server.go:39"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< getVolumeAccessType" file="controller_server.go:40"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> GetVolume, ID: my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="driver.go:431"
time="2024-09-29T08:08:17Z" level=trace msg="Secrets are provided. Checking with this particular storage provider." file="driver.go:438"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:08:17Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:08:17Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:08:17Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:08:17Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:08:17Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:08:17Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:08:17Z" level=trace msg="Request: action=GET path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1" file="client.go:173"
time="2024-09-29T08:08:19Z" level=trace msg="response: 200 OK, length=404" file="client.go:224"
time="2024-09-29T08:08:19Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0000af2c0 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:08:19Z" level=trace msg="Found Volume &{ID:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Name:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 Size:2147483648 Description:Volume for PVC data-kafka-controller-2 InUse:false Published:true BaseSnapID: ParentVolID: Clone:false Config:map[compression:LZ4 deduplication:OFF sync:STANDARD target_scope:volume volblocksize:8K] Metadata:[] SerialNumber: AccessProtocol: Iqn: Iqns:[] DiscoveryIP: DiscoveryIPs:[] MountPoint: Status:map[] Chap:<nil> Networks:[] ConnectionMode: LunID: TargetScope: IscsiSessions:[] FcSessions:[] VolumeGroupId: SecondaryArrayDetails: UsedBytes:0 FreeBytes:0 EncryptionKey:}" file="driver.go:469"
time="2024-09-29T08:08:19Z" level=trace msg="<<<<< GetVolume" file="driver.go:470"
time="2024-09-29T08:08:19Z" level=trace msg="volume config is map[compression:LZ4 deduplication:OFF sync:STANDARD targetScope:volume volblocksize:8K]" file="controller_server.go:823"
time="2024-09-29T08:08:19Z" level=trace msg=">>>>>> GetNodeInfo from node ID b1312db0-c69d-a568-6698-c1f50490d1f8" file="flavor.go:331"
time="2024-09-29T08:08:19Z" level=trace msg="Found the following HPE Node Info objects: &{{ } { 752323  <nil>} [{{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }} {{HPENodeInfo storage.hpe.com/v1} {c3    5ba76957-0085-49f4-8761-04abc656873f 495465 1 2024-09-28 20:27:06 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:06 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {df97b3bc-a8d5-2492-cbdc-197130594330 [iqn.1993-08.org.debian:01:4efdaa484446] [192.168.150.117/24 10.42.2.0/32 10.42.2.1/24] []  }}]}" file="flavor.go:338"
time="2024-09-29T08:08:19Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c1    7f95b111-3eb1-4115-bc54-59ac2442ea4c 495583 1 2024-09-28 20:27:12 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:12 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {1d1d92c3-5fff-4b13-4f87-dba44e3067c6 [iqn.1993-08.org.debian:01:4efdaa484444] [192.168.150.115/24 10.42.0.0/32 10.42.0.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:08:19Z" level=trace msg="Processing node info {{HPENodeInfo storage.hpe.com/v1} {c2    fac777c1-03fe-43d2-998f-8c45c2b04642 495394 1 2024-09-28 20:27:02 +0000 UTC <nil> <nil> map[] map[] [] [] [{csi-driver Update storage.hpe.com/v1 2024-09-28 20:27:02 +0000 UTC FieldsV1 {\"f:spec\":{\".\":{},\"f:iqns\":{},\"f:networks\":{},\"f:uuid\":{}}} }]} {b1312db0-c69d-a568-6698-c1f50490d1f8 [iqn.1993-08.org.debian:01:4efdaa484445] [192.168.150.116/24 10.42.1.0/32 10.42.1.1/24] []  }}" file="flavor.go:341"
time="2024-09-29T08:08:19Z" level=trace msg="<<<<<< GetNodeInfo" file="flavor.go:364"
time="2024-09-29T08:08:19Z" level=info msg=GetChapCredentialsFromVolumeContext file="flavor.go:1009"
time="2024-09-29T08:08:19Z" level=info msg="CHAP secret name and namespace are not provided in the storage class parameters." file="flavor.go:1015"
time="2024-09-29T08:08:19Z" level=info msg=GetChapCredentialsFromEnvironment file="flavor.go:995"
time="2024-09-29T08:08:19Z" level=info msg="CHAP secret name and namespace are not provided as environment variables." file="flavor.go:1001"
time="2024-09-29T08:08:19Z" level=trace msg=">>>>> GetStorageProvider" file="driver.go:360"
time="2024-09-29T08:08:19Z" level=trace msg=">>>>> CreateCredentials" file="storage_provider.go:65"
time="2024-09-29T08:08:19Z" level=trace msg="<<<<< CreateCredentials" file="storage_provider.go:125"
time="2024-09-29T08:08:19Z" level=trace msg="Storage provider already exists. Returning it." file="driver.go:380"
time="2024-09-29T08:08:19Z" level=trace msg="<<<<< GetStorageProvider" file="driver.go:381"
time="2024-09-29T08:08:19Z" level=trace msg="Notifying CSP about Node with ID  and UUID b1312db0-c69d-a568-6698-c1f50490d1f8" file="controller_server.go:861"
time="2024-09-29T08:08:19Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:08:19Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:08:19Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:08:19Z" level=trace msg="Request: action=POST path=http://truenas-csp-svc:8080/containers/v1/hosts" file="client.go:173"
time="2024-09-29T08:08:23Z" level=trace msg="response: 200 OK, length=278" file="client.go:224"
time="2024-09-29T08:08:23Z" level=debug msg="Received a null reader. That is not expected." file="client.go:245"
time="2024-09-29T08:08:23Z" level=trace msg="Defaulting to access protocol iscsi" file="controller_server.go:877"
time="2024-09-29T08:08:23Z" level=trace msg="About to invoke CSP request for backend truenas.internaldomain.com" file="container_storage_provider.go:153"
time="2024-09-29T08:08:23Z" level=trace msg="Header: {x-auth-token : *****}\n" file="client.go:166"
time="2024-09-29T08:08:23Z" level=trace msg="Header: {x-array-ip : truenas.internaldomain.com}\n" file="client.go:168"
time="2024-09-29T08:08:23Z" level=trace msg="Request: action=PUT path=http://truenas-csp-svc:8080/containers/v1/volumes/my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1/actions/publish" file="client.go:173"
time="2024-09-29T08:08:24Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:08:24Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:08:24Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
time="2024-09-29T08:08:35Z" level=trace msg="response: 200 OK, length=260" file="client.go:224"
time="2024-09-29T08:08:35Z" level=debug msg="About to decode the error response &{0x4ff020 0xc0003ec6c0 0x843500} into destination interface" file="client.go:231"
time="2024-09-29T08:08:35Z" level=trace msg="PublishInfo response from CSP: &{SerialNumber:6589cfc000000a69472b2e921fd54e29 AccessInfo:{BlockDeviceAccessInfo:{AccessProtocol:iscsi TargetNames:[iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1] LunID:0 SecondaryBackendDetails:{PeerArrayDetails:[]} IscsiAccessInfo:{DiscoveryIPs:[192.168.150.241] ChapUser: ChapPassword:}} VirtualDeviceAccessInfo:{}}}" file="controller_server.go:887"
time="2024-09-29T08:08:35Z" level=trace msg="Adding filesystem details to the publish context" file="controller_server.go:930"
time="2024-09-29T08:08:35Z" level=trace msg="Volume pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 with ID my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 published with the following details: [fsMode  serialNumber 6589cfc000000a69472b2e921fd54e29 targetNames iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 targetScope volume lunId 0 readOnly false volumeAccessMode mount fsOwner  accessProtocol iscsi discoveryIps 192.168.150.241 fsType xfs fsCreateOptions ]" file="controller_server.go:942"
time="2024-09-29T08:08:35Z" level=trace msg="<<<<< controllerPublishVolume" file="controller_server.go:944"
time="2024-09-29T08:08:35Z" level=trace msg=">>>>> ClearRequest, key: ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="driver.go:605"
time="2024-09-29T08:08:35Z" level=trace msg="Acquiring mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:44"
time="2024-09-29T08:08:35Z" level=trace msg="Print RequestCache: map[]" file="driver.go:625"
time="2024-09-29T08:08:35Z" level=trace msg="Successfully removed an entry with key ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8 from the cache map" file="driver.go:626"
time="2024-09-29T08:08:35Z" level=trace msg="Releasing mutex lock for ControllerPublishVolume:my-data_first.dataset_pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1:b1312db0-c69d-a568-6698-c1f50490d1f8" file="concurrent.go:67"
time="2024-09-29T08:08:35Z" level=trace msg="<<<<< ClearRequest" file="driver.go:627"
time="2024-09-29T08:08:35Z" level=trace msg="<<<<< ControllerPublishVolume" file="controller_server.go:740"
time="2024-09-29T08:08:35Z" level=info msg="GRPC response: {\"publish_context\":{\"accessProtocol\":\"iscsi\",\"discoveryIps\":\"192.168.150.241\",\"fsCreateOptions\":\"\",\"fsMode\":\"\",\"fsOwner\":\"\",\"fsType\":\"xfs\",\"lunId\":\"0\",\"readOnly\":\"false\",\"serialNumber\":\"6589cfc000000a69472b2e921fd54e29\",\"targetNames\":\"iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1\",\"targetScope\":\"volume\",\"volumeAccessMode\":\"mount\"}}" file="utils.go:75"
time="2024-09-29T08:08:54Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:08:54Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:08:54Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"
W0929 08:09:08.752555       1 reflector.go:424] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
E0929 08:09:08.752694       1 reflector.go:140] hpe-csi-driver/pkg/flavor/kubernetes/flavor.go:147: Failed to watch *v1.VolumeSnapshot: failed to list *v1.VolumeSnapshot: the server could not find the requested resource (get volumesnapshots.snapshot.storage.k8s.io)
time="2024-09-29T08:09:24Z" level=trace msg=">>>>> MonitorPod with label monitored-by=hpe-csi" file="flavor.go:838"
time="2024-09-29T08:09:24Z" level=trace msg="cannot find any nfs pod with label monitored-by=hpe-csi" file="flavor.go:852"
time="2024-09-29T08:09:24Z" level=trace msg="<<<<< MonitorPod" file="flavor.go:853"

Even if volumes should be published, if i run multipath -ll i don't see the volume mounted. Looking at timing, i see that the http response from the truenas-csp services takes a while, but i suppose this is due to the size of the response.

I also tried to manually mount the volume via ssh and it seems that in such a case there is no problem

iscsiadm -m discovery -t sendtargets -p truenas.internaldomain.com
iscsiadm -m node -T iqn.2011-08.org.truenas.ctl:pvc-916c05db-b7d8-4a7f-aa48-2d10cbb3c2b1 -l

after this, both lsblk and iscsiadm -m session confirm that the volume is mounted

datamattsson commented 13 hours ago

Thanks for providing the logs and manually verifying the data path. This is definitely a control plane issue.

I have a hard time following the logs on my phone and I'll have to get back to you later.