search

dell / csm

Dell Container Storage Modules (CSM)
Apache License 2.0
71 stars 15 forks source link

[BUG]: CSI driver for Unity StagingTargetPath exceeds size limit for ISCSI PVC #304

Closed phbo-dec closed 2 years ago

phbo-dec commented 2 years ago

Bug Description

Pods can't mount the volume as the staging path is too long. PV creation works without a problem.

MountVolume.MountDevice failed for volume "csivol-0b9be6c2e6" : rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141

i also tested a custom built driver by porting the changes from https://github.com/dell/csi-powerscale/pull/78 but i could not get it to recognize/respect the env vars.

Logs

logs will follow

Screenshots

No response

Additional Environment Information

ISCSI and multipath are working as intended, tested manual mounts on the node itself

pod and pvc deployment:

kind: PersistentVolumeClaim
apiVersion: v1
metadata:
  name: pvol1
spec:
  accessModes:
    - ReadWriteOnce
  volumeMode: Filesystem
  resources:
    requests:
      storage: 12Gi
  storageClassName: unity01-iscsi
---
apiVersion: v1
kind: Pod
metadata:
  name: task-pv-pod
spec:
  volumes:
    - name: pvol1
      persistentVolumeClaim:
        claimName: pvol1
  containers:
    - name: pvol1
      image: ubuntu:latest
      command: [ "/bin/bash", "-c", "--" ]
      args: [ "while true; do sleep 30; done;" ]
      volumeMounts:
        - mountPath: "/mnt/lun"
          name: pvol1

events from the test pod:

Events:
  Type     Reason                  Age                From                     Message
  ----     ------                  ----               ----                     -------
  Warning  FailedScheduling        91s                default-scheduler        0/1 nodes are available: 1 pod has unbound immediate PersistentVolumeClaims.
  Warning  FailedScheduling        88s (x1 over 90s)  default-scheduler        0/1 nodes are available: 1 pod has unbound immediate PersistentVolumeClaims.
  Normal   Scheduled               83s                default-scheduler        Successfully assigned default/task-pv-pod to node1
  Normal   SuccessfulAttachVolume  80s                attachdetach-controller  AttachVolume.Attach succeeded for volume "csivol-c02cffe4d3"
  Warning  FailedMount             13s (x8 over 77s)  kubelet                  MountVolume.MountDevice failed for volume "csivol-c02cffe4d3" : rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141

pods in the unity namespace: 

Name:         unity-controller-56f889749b-ljsqs
Namespace:    unity
Priority:     0
Node:         node1/192.168.90.150
Start Time:   Mon, 16 May 2022 09:21:51 +0200
Labels:       app=unity-controller
              pod-template-hash=56f889749b
Annotations:  cni.projectcalico.org/containerID: 071b38e3d001f7814c7304f8234fde85658828f035ce09e32aac9abf7c18f1f4
              cni.projectcalico.org/podIP: 10.233.90.26/32
              cni.projectcalico.org/podIPs: 10.233.90.26/32
Status:       Running
IP:           10.233.90.26
IPs:
  IP:           10.233.90.26
Controlled By:  ReplicaSet/unity-controller-56f889749b
Containers:
  attacher:
    Container ID:  containerd://3a400033014a7ab2acf2f1626a6fbc64e1d47db060f6753dfa800905afa0f94b
    Image:         k8s.gcr.io/sig-storage/csi-attacher:v3.4.0
    Image ID:      k8s.gcr.io/sig-storage/csi-attacher@sha256:8b9c313c05f54fb04f8d430896f5f5904b6cb157df261501b29adc04d2b2dc7b
    Port:          <none>
    Host Port:     <none>
    Args:
      --csi-address=$(ADDRESS)
      --v=5
      --leader-election
    State:          Running
      Started:      Mon, 16 May 2022 09:21:52 +0200
    Ready:          True
    Restart Count:  0
    Environment:
      ADDRESS:  /var/run/csi/csi.sock
    Mounts:
      /var/run/csi from socket-dir (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-fwvpg (ro)
  provisioner:
    Container ID:  containerd://8ef0e661e214cbfff2de4a76d89b56c64a16b779e69b8f51b6dfbb73f8df5a28
    Image:         k8s.gcr.io/sig-storage/csi-provisioner:v3.1.0
    Image ID:      k8s.gcr.io/sig-storage/csi-provisioner@sha256:122bfb8c1edabb3c0edd63f06523e6940d958d19b3957dc7b1d6f81e9f1f6119
    Port:          <none>
    Host Port:     <none>
    Args:
      --csi-address=$(ADDRESS)
      --volume-name-prefix=csivol
      --volume-name-uuid-length=10
      --timeout=180s
      --worker-threads=6
      --v=5
      --feature-gates=Topology=true
      --strict-topology=true
      --leader-election
      --leader-election-namespace=unity
      --default-fstype=ext4
    State:          Running
      Started:      Mon, 16 May 2022 09:21:52 +0200
    Ready:          True
    Restart Count:  0
    Environment:
      ADDRESS:  /var/run/csi/csi.sock
    Mounts:
      /var/run/csi from socket-dir (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-fwvpg (ro)
  resizer:
    Container ID:  containerd://f92b48a21ae67540a6e23b374d73bee776e52652624a5489aa6ee0498bb1ad6f
    Image:         k8s.gcr.io/sig-storage/csi-resizer:v1.4.0
    Image ID:      k8s.gcr.io/sig-storage/csi-resizer@sha256:9ebbf9f023e7b41ccee3d52afe39a89e3ddacdbb69269d583abfc25847cfd9e4
    Port:          <none>
    Host Port:     <none>
    Args:
      --csi-address=$(ADDRESS)
      --v=5
      --leader-election
    State:          Running
      Started:      Mon, 16 May 2022 09:21:53 +0200
    Ready:          True
    Restart Count:  0
    Environment:
      ADDRESS:  /var/run/csi/csi.sock
    Mounts:
      /var/run/csi from socket-dir (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-fwvpg (ro)
  driver:
    Container ID:  containerd://8e9da12d4056c7de436e1c604b07a38aa8f607578725a86229dc99ea6c774310
    Image:         dellemc/csi-unity:v2.2.0
    Image ID:      docker.io/dellemc/csi-unity@sha256:9fddd37cf5a6af47e05c6c148a928524d278f505dc0de53109fab3682963b652
    Port:          <none>
    Host Port:     <none>
    Args:
      --driver-name=csi-unity.dellemc.com
      --driver-config=/unity-config/driver-config-params.yaml
      --driver-secret=/unity-secret/config
      --leader-election
    State:          Running
      Started:      Mon, 16 May 2022 09:21:55 +0200
    Ready:          True
    Restart Count:  0
    Environment:
      CSI_ENDPOINT:           /var/run/csi/csi.sock
      X_CSI_MODE:             controller
      X_CSI_UNITY_AUTOPROBE:  true
      SSL_CERT_DIR:           /certs
    Mounts:
      /certs from certs (ro)
      /unity-config from unity-config (rw)
      /unity-secret from unity-secret (rw)
      /var/run/csi from socket-dir (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-fwvpg (ro)
Conditions:
  Type              Status
  Initialized       True
  Ready             True
  ContainersReady   True
  PodScheduled      True
Volumes:
  certs:
    Type:                Projected (a volume that contains injected data from multiple sources)
    SecretName:          unity-certs-0
    SecretOptionalName:  <nil>
  socket-dir:
    Type:       EmptyDir (a temporary directory that shares a pod's lifetime)
    Medium:
    SizeLimit:  <unset>
  unity-config:
    Type:      ConfigMap (a volume populated by a ConfigMap)
    Name:      unity-config-params
    Optional:  false
  unity-secret:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  unity-creds
    Optional:    false
  kube-api-access-fwvpg:
    Type:                    Projected (a volume that contains injected data from multiple sources)
    TokenExpirationSeconds:  3607
    ConfigMapName:           kube-root-ca.crt
    ConfigMapOptional:       <nil>
    DownwardAPI:             true
QoS Class:                   BestEffort
Node-Selectors:              <none>
Tolerations:                 node.kubernetes.io/not-ready:NoExecute op=Exists for 300s
                             node.kubernetes.io/unreachable:NoExecute op=Exists for 300s
Events:
  Type     Reason            Age   From               Message
  ----     ------            ----  ----               -------
  Normal   Scheduled         27m   default-scheduler  Successfully assigned unity/unity-controller-56f889749b-ljsqs to node1
  Warning  FailedScheduling  27m   default-scheduler  0/1 nodes are available: 1 node(s) didn't match pod anti-affinity rules.
  Normal   Created           27m   kubelet            Created container resizer
  Normal   Pulled            27m   kubelet            Container image "k8s.gcr.io/sig-storage/csi-attacher:v3.4.0" already present on machine
  Normal   Created           27m   kubelet            Created container attacher
  Normal   Started           27m   kubelet            Started container attacher
  Normal   Pulled            27m   kubelet            Container image "k8s.gcr.io/sig-storage/csi-provisioner:v3.1.0" already present on machine
  Normal   Created           27m   kubelet            Created container provisioner
  Normal   Pulled            27m   kubelet            Container image "k8s.gcr.io/sig-storage/csi-resizer:v1.4.0" already present on machine
  Normal   Started           27m   kubelet            Started container provisioner
  Normal   Started           27m   kubelet            Started container resizer
  Normal   Pulling           27m   kubelet            Pulling image "dellemc/csi-unity:v2.2.0"
  Normal   Pulled            27m   kubelet            Successfully pulled image "dellemc/csi-unity:v2.2.0" in 1.775621499s
  Normal   Created           27m   kubelet            Created container driver
  Normal   Started           27m   kubelet            Started container driver

Name:         unity-node-mnd6b
Namespace:    unity
Priority:     0
Node:         node1/192.168.90.150
Start Time:   Mon, 16 May 2022 09:21:51 +0200
Labels:       app=unity-node
              controller-revision-hash=7c5c766f4
              pod-template-generation=7
Annotations:  <none>
Status:       Running
IP:           192.168.90.150
IPs:
  IP:           192.168.90.150
Controlled By:  DaemonSet/unity-node
Containers:
  driver:
    Container ID:  containerd://69ff98cfccb62434e727d151beea303abf326a0b55c6ba84c95b12e4fb972858
    Image:         dellemc/csi-unity:v2.2.0
    Image ID:      docker.io/dellemc/csi-unity@sha256:9fddd37cf5a6af47e05c6c148a928524d278f505dc0de53109fab3682963b652
    Port:          <none>
    Host Port:     <none>
    Args:
      --driver-name=csi-unity.dellemc.com
      --driver-config=/unity-config/driver-config-params.yaml
      --driver-secret=/unity-secret/config
    State:          Running
      Started:      Mon, 16 May 2022 09:21:53 +0200
    Ready:          True
    Restart Count:  0
    Environment:
      CSI_ENDPOINT:                        /var/lib/kubelet/plugins/unity.emc.dell.com/csi_sock
      X_CSI_MODE:                          node
      X_CSI_UNITY_AUTOPROBE:               true
      X_CSI_UNITY_ALLOW_MULTI_POD_ACCESS:  false
      X_CSI_PRIVATE_MOUNT_DIR:             /var/lib/kubelet/plugins/unity.emc.dell.com/disks
      X_CSI_EPHEMERAL_STAGING_PATH:        /var/lib/kubelet/plugins/kubernetes.io/csi/pv/
      X_CSI_ISCSI_CHROOT:                  /noderoot
      X_CSI_UNITY_NODENAME:                 (v1:spec.nodeName)
      X_CSI_UNITY_NODENAME_PREFIX:
      SSL_CERT_DIR:                        /certs
      X_CSI_UNITY_SYNC_NODEINFO_INTERVAL:  15
      X_CSI_HEALTH_MONITOR_ENABLED:        true
    Mounts:
      /certs from certs (ro)
      /dev from dev (rw)
      /noderoot from noderoot (rw)
      /unity-config from unity-config (rw)
      /unity-secret from unity-secret (rw)
      /var/lib/kubelet/plugins/kubernetes.io/csi from volumedevices-path (rw)
      /var/lib/kubelet/plugins/unity.emc.dell.com from driver-path (rw)
      /var/lib/kubelet/pods from pods-path (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-pkpdp (ro)
  registrar:
    Container ID:  containerd://2bcd2bb9fa7fae4a600fcc63e8007352908b784606938eb18e8964a6567065a4
    Image:         k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.5.0
    Image ID:      k8s.gcr.io/sig-storage/csi-node-driver-registrar@sha256:4fd21f36075b44d1a423dfb262ad79202ce54e95f5cbc4622a6c1c38ab287ad6
    Port:          <none>
    Host Port:     <none>
    Args:
      --v=5
      --csi-address=$(ADDRESS)
      --kubelet-registration-path=/var/lib/kubelet/plugins/unity.emc.dell.com/csi_sock
    State:          Running
      Started:      Mon, 16 May 2022 09:21:58 +0200
    Last State:     Terminated
      Reason:       Error
      Exit Code:    1
      Started:      Mon, 16 May 2022 09:21:54 +0200
      Finished:     Mon, 16 May 2022 09:21:57 +0200
    Ready:          True
    Restart Count:  1
    Environment:
      ADDRESS:         /csi/csi_sock
      KUBE_NODE_NAME:   (v1:spec.nodeName)
    Mounts:
      /csi from driver-path (rw)
      /registration from registration-dir (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-pkpdp (ro)
Conditions:
  Type              Status
  Initialized       True
  Ready             True
  ContainersReady   True
  PodScheduled      True
Volumes:
  registration-dir:
    Type:          HostPath (bare host directory volume)
    Path:          /var/lib/kubelet/plugins_registry/
    HostPathType:  DirectoryOrCreate
  driver-path:
    Type:          HostPath (bare host directory volume)
    Path:          /var/lib/kubelet/plugins/unity.emc.dell.com
    HostPathType:  DirectoryOrCreate
  volumedevices-path:
    Type:          HostPath (bare host directory volume)
    Path:          /var/lib/kubelet/plugins/kubernetes.io/csi
    HostPathType:  DirectoryOrCreate
  pods-path:
    Type:          HostPath (bare host directory volume)
    Path:          /var/lib/kubelet/pods
    HostPathType:  Directory
  dev:
    Type:          HostPath (bare host directory volume)
    Path:          /dev
    HostPathType:  Directory
  noderoot:
    Type:          HostPath (bare host directory volume)
    Path:          /
    HostPathType:  Directory
  certs:
    Type:                Projected (a volume that contains injected data from multiple sources)
    SecretName:          unity-certs-0
    SecretOptionalName:  <nil>
  unity-config:
    Type:      ConfigMap (a volume populated by a ConfigMap)
    Name:      unity-config-params
    Optional:  false
  unity-secret:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  unity-creds
    Optional:    false
  kube-api-access-pkpdp:
    Type:                    Projected (a volume that contains injected data from multiple sources)
    TokenExpirationSeconds:  3607
    ConfigMapName:           kube-root-ca.crt
    ConfigMapOptional:       <nil>
    DownwardAPI:             true
QoS Class:                   BestEffort
Node-Selectors:              <none>
Tolerations:                 node.kubernetes.io/disk-pressure:NoSchedule op=Exists
                             node.kubernetes.io/memory-pressure:NoSchedule op=Exists
                             node.kubernetes.io/network-unavailable:NoSchedule op=Exists
                             node.kubernetes.io/not-ready:NoExecute op=Exists
                             node.kubernetes.io/pid-pressure:NoSchedule op=Exists
                             node.kubernetes.io/unreachable:NoExecute op=Exists
                             node.kubernetes.io/unschedulable:NoSchedule op=Exists
Events:
  Type    Reason     Age                From               Message
  ----    ------     ----               ----               -------
  Normal  Scheduled  27m                default-scheduler  Successfully assigned unity/unity-node-mnd6b to node1
  Normal  Pulling    27m                kubelet            Pulling image "dellemc/csi-unity:v2.2.0"
  Normal  Pulled     27m                kubelet            Successfully pulled image "dellemc/csi-unity:v2.2.0" in 1.358120961s
  Normal  Created    27m                kubelet            Created container driver
  Normal  Started    27m                kubelet            Started container driver
  Normal  Pulled     27m (x2 over 27m)  kubelet            Container image "k8s.gcr.io/sig-storage/csi-node-driver-registrar:v2.5.0" already present on machine
  Normal  Created    27m (x2 over 27m)  kubelet            Created container registrar
  Normal  Started    27m (x2 over 27m)  kubelet            Started container registrar

Steps to Reproduce

clean install a single node k8s, use the dell-csi-helm-installer to install the driver, create pods/pvcs as described above.

Expected Behavior

Working mounts with either shorter staging paths or a higher size limit for path length.

CSM Driver(s)

CSI Driver for Unity XT v2.2.0

Installation Type

Helm

Container Storage Modules Enabled

No response

Container Orchestrator

Kubernetes v1.23.6

Operating System

ubuntu 20.04

phbo-dec commented 2 years ago

Logs: controller-attacher:

I0516 07:21:52.798313       1 main.go:92] Version: v3.4.0
I0516 07:21:52.802316       1 connection.go:154] Connecting to unix:///var/run/csi/csi.sock
W0516 07:22:02.802961       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
W0516 07:22:12.802455       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
I0516 07:22:14.888546       1 common.go:111] Probing CSI driver for readiness
I0516 07:22:14.888595       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0516 07:22:14.888609       1 connection.go:184] GRPC request: {}
I0516 07:22:16.498870       1 connection.go:186] GRPC response: {}
I0516 07:22:16.499006       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.499047       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I0516 07:22:16.499061       1 connection.go:184] GRPC request: {}
I0516 07:22:16.500181       1 connection.go:186] GRPC response: {"manifest":{"commit":"0188813dc1ca097b4b920b37784038482f5f1bd1","formed":"Tue, 22 Mar 2022 21:47:11 UTC","semver":"2.2.0","url":"http://github.com/dell/csi-unity"},"name":"csi-unity.dellemc.com","vendor_version":"2.2.0"}
I0516 07:22:16.500439       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.500465       1 main.go:148] CSI driver name: "csi-unity.dellemc.com"
I0516 07:22:16.500484       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0516 07:22:16.500496       1 connection.go:184] GRPC request: {}
I0516 07:22:16.501971       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"VolumeExpansion":{"type":2}}},{"Type":{"Service":{"type":2}}}]}
I0516 07:22:16.502318       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.502336       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0516 07:22:16.502348       1 connection.go:184] GRPC request: {}
I0516 07:22:16.503553       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":4}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":8}}},{"Type":{"Rpc":{"type":13}}}]}
I0516 07:22:16.503861       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.503987       1 main.go:223] CSI driver supports ControllerPublishUnpublish, using real CSI handler
I0516 07:22:16.505111       1 leaderelection.go:248] attempting to acquire leader lease unity/external-attacher-leader-csi-unity-dellemc-com...
I0516 07:22:16.525447       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:16.525493       1 leaderelection.go:253] failed to acquire lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:16.525536       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-x62m2
I0516 07:22:25.163913       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:25.163946       1 leaderelection.go:253] failed to acquire lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:35.820825       1 leaderelection.go:258] successfully acquired lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:35.820920       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-ljsqs
I0516 07:22:35.820982       1 leader_election.go:205] became leader, starting
I0516 07:22:35.821019       1 controller.go:128] Starting CSI attacher
I0516 07:22:35.821568       1 reflector.go:219] Starting reflector *v1.CSINode (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.821592       1 reflector.go:255] Listing and watching *v1.CSINode from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.821654       1 reflector.go:219] Starting reflector *v1.PersistentVolume (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.821698       1 reflector.go:255] Listing and watching *v1.PersistentVolume from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.821744       1 reflector.go:219] Starting reflector *v1.VolumeAttachment (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.821785       1 reflector.go:255] Listing and watching *v1.VolumeAttachment from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.829752       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:35.921907       1 shared_informer.go:270] caches populated
I0516 07:22:40.842788       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:41.353789       1 controller.go:208] Started VA processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.353856       1 csi_handler.go:221] CSIHandler: processing VA "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.353889       1 csi_handler.go:248] Attaching "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.353910       1 csi_handler.go:418] Starting attach operation for "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.354045       1 csi_handler.go:338] Adding finalizer to PV "csivol-0b9be6c2e6"
I0516 07:22:41.362039       1 csi_handler.go:347] PV finalizer added to "csivol-0b9be6c2e6"
I0516 07:22:41.362090       1 csi_handler.go:737] Found NodeID node1,node1 in CSINode node1
I0516 07:22:41.362165       1 csi_handler.go:309] VA finalizer added to "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.362190       1 csi_handler.go:323] NodeID annotation added to "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:41.367841       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0516 07:22:41.367874       1 connection.go:184] GRPC request: {"node_id":"node1,node1","volume_capability":{"AccessType":{"Mount":{"fs_type":"xfs"}},"access_mode":{"mode":7}},"volume_context":{"arrayId":"crk00212500758","protocol":"iSCSI","storage.kubernetes.io/csiProvisionerIdentity":"1652685735980-8081-csi-unity.dellemc.com","volumeId":"sv_50"},"volume_id":"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50"}
I0516 07:22:43.623360       1 connection.go:186] GRPC response: {"publish_context":{"arrayId":"crk00212500758","host":"node1,node1","lun":"sv_50","volumeContextId":"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50"}}
I0516 07:22:43.623573       1 connection.go:187] GRPC error: <nil>
I0516 07:22:43.623596       1 csi_handler.go:261] Attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.623614       1 util.go:38] Marking as attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.642986       1 util.go:52] Marked as attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643028       1 csi_handler.go:267] Fully attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643049       1 csi_handler.go:237] CSIHandler: finished processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643115       1 controller.go:208] Started VA processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643138       1 csi_handler.go:221] CSIHandler: processing VA "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643152       1 csi_handler.go:248] Attaching "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643165       1 csi_handler.go:418] Starting attach operation for "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643216       1 csi_handler.go:332] PV finalizer is already set on "csivol-0b9be6c2e6"
I0516 07:22:43.643256       1 csi_handler.go:737] Found NodeID node1,node1 in CSINode node1
I0516 07:22:43.643295       1 csi_handler.go:301] VA finalizer is already set on "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643314       1 csi_handler.go:315] NodeID annotation is already set on "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:43.643338       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerPublishVolume
I0516 07:22:43.643349       1 connection.go:184] GRPC request: {"node_id":"node1,node1","volume_capability":{"AccessType":{"Mount":{"fs_type":"xfs"}},"access_mode":{"mode":7}},"volume_context":{"arrayId":"crk00212500758","protocol":"iSCSI","storage.kubernetes.io/csiProvisionerIdentity":"1652685735980-8081-csi-unity.dellemc.com","volumeId":"sv_50"},"volume_id":"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50"}
I0516 07:22:44.229917       1 connection.go:186] GRPC response: {"publish_context":{"arrayId":"crk00212500758","host":"node1,node1","lun":"sv_50","volumeContextId":"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50"}}
I0516 07:22:44.230065       1 connection.go:187] GRPC error: <nil>
I0516 07:22:44.230087       1 csi_handler.go:261] Attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.230105       1 util.go:38] Marking as attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243674       1 util.go:52] Marked as attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243699       1 csi_handler.go:267] Fully attached "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243710       1 csi_handler.go:237] CSIHandler: finished processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243748       1 controller.go:208] Started VA processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243758       1 csi_handler.go:221] CSIHandler: processing VA "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:44.243767       1 csi_handler.go:243] "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9" is already attached
I0516 07:22:44.243775       1 csi_handler.go:237] CSIHandler: finished processing "csi-230a0cf497220780746dd9e423f4266e0dd5376759c87fb2faabee52afaa7ff9"
I0516 07:22:45.855064       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:50.867678       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:22:55.882425       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:00.896688       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:05.908980       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:10.924216       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:15.937998       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:20.952403       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:25.966086       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:30.976989       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:35.988002       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:41.002298       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:46.015869       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:51.030348       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:23:56.041289       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:01.055206       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:06.070868       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:11.085012       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:16.098848       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:21.109512       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:26.122573       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:31.136451       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:36.147459       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com
I0516 07:24:41.161245       1 leaderelection.go:278] successfully renewed lease unity/external-attacher-leader-csi-unity-dellemc-com

controller-driver:

Endpoint /var/run/csi/csi.sock
I0516 07:21:55.125583       1 leaderelection.go:243] attempting to acquire leader lease unity/driver-csi-unity-dellemc-com...
I0516 07:22:14.506217       1 leaderelection.go:253] successfully acquired lease unity/driver-csi-unity-dellemc-com
csi-unity logger initiated. This should be called only once.
time="2022-05-16T07:22:14Z" level=info  runid=start msg="Driver Mode:controller" func="github.com/dell/csi-unity/service.(*service).BeforeServe()" file="/go/src/csi-unity/service/service.go:174"
time="2022-05-16T07:22:14Z" level=info  runid=config-0 msg="*************Synchronizing driver secret**************" func="github.com/dell/csi-unity/service.(*service).syncDriverSecret()" file="/go/src/csi-unity/service/service.go:459"
gounity logger initiated. This should be called only once.
time="2022-05-16T07:22:14Z" level=info msg="configured csi-unity.dellemc.com" ArrayId=crk00212500758 Endpoint="https://192.168.150.241/" IsDefault=true SkipCertificateValidation=false password="*******" username=csi.k8s.*******.io
time="2022-05-16T07:22:14Z" level=info  runid=config-0 msg="configured csi-unity.dellemc.com" func="github.com/dell/csi-unity/service.(*service).BeforeServe.func1()" file="/go/src/csi-unity/service/service.go:169"
time="2022-05-16T07:22:14Z" level=info msg="identity service registered"
time="2022-05-16T07:22:14Z" level=info msg="controller service registered"
time="2022-05-16T07:22:14Z" level=info  runid=RegisterAdditionalServers msg="Registering additional GRPC servers" func="github.com/dell/csi-unity/service.(*service).RegisterAdditionalServers()" file="/go/src/csi-unity/service/service.go:286"
time="2022-05-16T07:22:14Z" level=info  runid=config-1 msg="Dynamic config load goroutine invoked" func="github.com/dell/csi-unity/service.(*service).loadDynamicConfig()" file="/go/src/csi-unity/service/service.go:374"
time="2022-05-16T07:22:14Z" level=info msg=serving endpoint="unix:///var/run/csi/csi.sock"
time="2022-05-16T07:22:14Z" level=info  runid=config-1 msg="*************Synchronizing driver config**************" func="github.com/dell/csi-unity/service.(*service).syncDriverConfig()" file="/go/src/csi-unity/service/service.go:560"
time="2022-05-16T07:22:14Z" level=warning  runid=config-1 msg="Log level changed to: debug" func="github.com/dell/csi-unity/service.(*service).syncDriverConfig()" file="/go/src/csi-unity/service/service.go:578"
time="2022-05-16T07:22:14Z" level=debug  runid=config-1 msg="Secret folder:/unity-secret" func="github.com/dell/csi-unity/service.(*service).loadDynamicConfig()" file="/go/src/csi-unity/service/service.go:398"
time="2022-05-16T07:22:14Z" level=info msg="/csi.v1.Identity/Probe: REQ 0001: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:14Z" level=info  runid=1 msg="Executing Probe with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:16"
time="2022-05-16T07:22:14Z" level=debug  runid=1 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:14Z" level=debug  runid=1 msg="Probing all arrays" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:799"
time="2022-05-16T07:22:14Z" level=debug msg="Executing Authenticate REST client" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:51"
time="2022-05-16T07:22:14Z" level=info msg="/csi.v1.Identity/Probe: REQ 0002: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:14Z" level=info  runid=2 msg="Executing Probe with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:16"
time="2022-05-16T07:22:14Z" level=debug  runid=2 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:14Z" level=debug  runid=2 msg="Probing all arrays" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:799"
time="2022-05-16T07:22:14Z" level=debug msg="Executing Authenticate REST client" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:51"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/Probe: REQ 0003: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info  runid=3 msg="Executing Probe with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:16"
time="2022-05-16T07:22:15Z" level=debug  runid=3 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:15Z" level=debug  runid=3 msg="Probing all arrays" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:799"
time="2022-05-16T07:22:15Z" level=debug msg="Executing Authenticate REST client" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:51"
time="2022-05-16T07:22:15Z" level=debug msg="Response code:200 for url: /api/types/loginSessionInfo" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:15Z" level=debug msg="Authentication response code: 200" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:65"
time="2022-05-16T07:22:15Z" level=debug msg="Authentication successful" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:75"
time="2022-05-16T07:22:15Z" level=debug arrayid=crk00212500758 runid=1 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.singleArrayProbe()" file="/go/src/csi-unity/service/service.go:785"
time="2022-05-16T07:22:15Z" level=info  runid=1 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:815"
time="2022-05-16T07:22:15Z" level=info  runid=1 msg="Identity probe success" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:29"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/Probe: REP 0001: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REQ 0004: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REP 0004: Name=csi-unity.dellemc.com, VendorVersion=2.2.0, Manifest=map[commit:0188813dc1ca097b4b920b37784038482f5f1bd1 formed:Tue, 22 Mar 2022 21:47:11 UTC semver:2.2.0 url:http://github.com/dell/csi-unity], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REQ 0005: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info  runid=5 msg="Executing GetPluginCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).GetPluginCapabilities()" file="/go/src/csi-unity/service/identity.go:50"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REP 0005: Capabilities=[service:<type:CONTROLLER_SERVICE >  volume_expansion:<type:ONLINE >  volume_expansion:<type:OFFLINE >  service:<type:VOLUME_ACCESSIBILITY_CONSTRAINTS > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REQ 0006: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:15Z" level=debug  runid=6 msg="Executing ControllerGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerGetCapabilities()" file="/go/src/csi-unity/service/controller.go:618"
time="2022-05-16T07:22:15Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REP 0006: Capabilities=[rpc:<type:CREATE_DELETE_VOLUME >  rpc:<type:PUBLISH_UNPUBLISH_VOLUME >  rpc:<type:GET_CAPACITY >  rpc:<type:CREATE_DELETE_SNAPSHOT >  rpc:<type:LIST_SNAPSHOTS >  rpc:<type:EXPAND_VOLUME >  rpc:<type:CLONE_VOLUME >  rpc:<type:PUBLISH_READONLY >  rpc:<type:SINGLE_NODE_MULTI_WRITER > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=debug msg="Response code:200 for url: /api/types/loginSessionInfo" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:16Z" level=debug msg="Authentication response code: 200" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:65"
time="2022-05-16T07:22:16Z" level=debug msg="Authentication successful" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:75"
time="2022-05-16T07:22:16Z" level=debug arrayid=crk00212500758 runid=2 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.singleArrayProbe()" file="/go/src/csi-unity/service/service.go:785"
time="2022-05-16T07:22:16Z" level=info  runid=2 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:815"
time="2022-05-16T07:22:16Z" level=info  runid=2 msg="Identity probe success" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:29"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/Probe: REP 0002: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REQ 0007: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REP 0007: Name=csi-unity.dellemc.com, VendorVersion=2.2.0, Manifest=map[commit:0188813dc1ca097b4b920b37784038482f5f1bd1 formed:Tue, 22 Mar 2022 21:47:11 UTC semver:2.2.0 url:http://github.com/dell/csi-unity], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REQ 0008: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info  runid=8 msg="Executing GetPluginCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).GetPluginCapabilities()" file="/go/src/csi-unity/service/identity.go:50"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REP 0008: Capabilities=[service:<type:CONTROLLER_SERVICE >  volume_expansion:<type:ONLINE >  volume_expansion:<type:OFFLINE >  service:<type:VOLUME_ACCESSIBILITY_CONSTRAINTS > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REQ 0009: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=debug  runid=9 msg="Executing ControllerGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerGetCapabilities()" file="/go/src/csi-unity/service/controller.go:618"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REP 0009: Capabilities=[rpc:<type:CREATE_DELETE_VOLUME >  rpc:<type:PUBLISH_UNPUBLISH_VOLUME >  rpc:<type:GET_CAPACITY >  rpc:<type:CREATE_DELETE_SNAPSHOT >  rpc:<type:LIST_SNAPSHOTS >  rpc:<type:EXPAND_VOLUME >  rpc:<type:CLONE_VOLUME >  rpc:<type:PUBLISH_READONLY >  rpc:<type:SINGLE_NODE_MULTI_WRITER > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=debug msg="Response code:200 for url: /api/types/loginSessionInfo" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:16Z" level=debug msg="Authentication response code: 200" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:65"
time="2022-05-16T07:22:16Z" level=debug msg="Authentication successful" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:75"
time="2022-05-16T07:22:16Z" level=debug arrayid=crk00212500758 runid=3 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.singleArrayProbe()" file="/go/src/csi-unity/service/service.go:785"
time="2022-05-16T07:22:16Z" level=info  runid=3 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:815"
time="2022-05-16T07:22:16Z" level=info  runid=3 msg="Identity probe success" func="github.com/dell/csi-unity/service.(*service).Probe()" file="/go/src/csi-unity/service/identity.go:29"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/Probe: REP 0003: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REQ 0010: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REP 0010: Name=csi-unity.dellemc.com, VendorVersion=2.2.0, Manifest=map[commit:0188813dc1ca097b4b920b37784038482f5f1bd1 formed:Tue, 22 Mar 2022 21:47:11 UTC semver:2.2.0 url:http://github.com/dell/csi-unity], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REQ 0011: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info  runid=11 msg="Executing GetPluginCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).GetPluginCapabilities()" file="/go/src/csi-unity/service/identity.go:50"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Identity/GetPluginCapabilities: REP 0011: Capabilities=[service:<type:CONTROLLER_SERVICE >  volume_expansion:<type:ONLINE >  volume_expansion:<type:OFFLINE >  service:<type:VOLUME_ACCESSIBILITY_CONSTRAINTS > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REQ 0012: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=debug  runid=12 msg="Executing ControllerGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerGetCapabilities()" file="/go/src/csi-unity/service/controller.go:618"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REP 0012: Capabilities=[rpc:<type:CREATE_DELETE_VOLUME >  rpc:<type:PUBLISH_UNPUBLISH_VOLUME >  rpc:<type:GET_CAPACITY >  rpc:<type:CREATE_DELETE_SNAPSHOT >  rpc:<type:LIST_SNAPSHOTS >  rpc:<type:EXPAND_VOLUME >  rpc:<type:CLONE_VOLUME >  rpc:<type:PUBLISH_READONLY >  rpc:<type:SINGLE_NODE_MULTI_WRITER > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REQ 0013: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:16Z" level=debug  runid=13 msg="Executing ControllerGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerGetCapabilities()" file="/go/src/csi-unity/service/controller.go:618"
time="2022-05-16T07:22:16Z" level=info msg="/csi.v1.Controller/ControllerGetCapabilities: REP 0013: Capabilities=[rpc:<type:CREATE_DELETE_VOLUME >  rpc:<type:PUBLISH_UNPUBLISH_VOLUME >  rpc:<type:GET_CAPACITY >  rpc:<type:CREATE_DELETE_SNAPSHOT >  rpc:<type:LIST_SNAPSHOTS >  rpc:<type:EXPAND_VOLUME >  rpc:<type:CLONE_VOLUME >  rpc:<type:PUBLISH_READONLY >  rpc:<type:SINGLE_NODE_MULTI_WRITER > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:35Z" level=info msg="/csi.v1.Controller/CreateVolume: REQ 0014: Name=csivol-0b9be6c2e6, CapacityRange=required_bytes:12884901888 , VolumeCapabilities=[mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > ], Parameters=map[arrayId:CRK00212500758 protocol:iSCSI storagePool:pool_1 thinProvisioned:true], AccessibilityRequirements=requisite:<segments:<key:\"csi-unity.dellemc.com/crk00212500758-iscsi\" value:\"true\" > segments:<key:\"csi-unity.dellemc.com/crk00212500758-nfs\" value:\"true\" > > preferred:<segments:<key:\"csi-unity.dellemc.com/crk00212500758-iscsi\" value:\"true\" > segments:<key:\"csi-unity.dellemc.com/crk00212500758-nfs\" value:\"true\" > > , XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:35Z" level=debug  runid=14 msg="Executing CreateVolume with args: {Name:csivol-0b9be6c2e6 CapacityRange:required_bytes:12884901888  VolumeCapabilities:[mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > ] Parameters:map[arrayId:CRK00212500758 protocol:iSCSI storagePool:pool_1 thinProvisioned:true] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > > preferred:<segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).CreateVolume()" file="/go/src/csi-unity/service/controller.go:87"
time="2022-05-16T07:22:35Z" level=debug arrayid=crk00212500758 runid=14 msg="Probing controller service automatically" func="github.com/dell/csi-unity/service.(*service).requireProbe()" file="/go/src/csi-unity/service/service.go:757"
time="2022-05-16T07:22:35Z" level=debug arrayid=crk00212500758 runid=14 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:35Z" level=debug arrayid=crk00212500758 runid=14 msg="Parameter tieringPolicy is set to [0]" func="github.com/dell/csi-unity/service.ValidateCreateVolumeRequest()" file="/go/src/csi-unity/service/validator.go:240"
time="2022-05-16T07:22:35Z" level=debug arrayid=crk00212500758 runid=14 msg="Parameter isDataReductionEnabled is set to [false]" func="github.com/dell/csi-unity/service.ValidateCreateVolumeRequest()" file="/go/src/csi-unity/service/validator.go:260"
time="2022-05-16T07:22:35Z" level=debug arrayid=crk00212500758 runid=14 msg="Volume AccessibilityRequirements: requisite:<segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > > preferred:<segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > > " func="github.com/dell/csi-unity/service.ValidateCreateVolumeRequest()" file="/go/src/csi-unity/service/validator.go:267"
time="2022-05-16T07:22:35Z" level=info arrayid=crk00212500758 runid=14 msg="PREFERRED-->[segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > ]" func="github.com/dell/csi-unity/service.(*service).CreateVolume()" file="/go/src/csi-unity/service/controller.go:113"
time="2022-05-16T07:22:35Z" level=info arrayid=crk00212500758 runid=14 msg="Executing CreateVolume with following fields" func="github.com/dell/csi-unity/service.(*service).CreateVolume()" file="/go/src/csi-unity/service/controller.go:226"
time="2022-05-16T07:22:35Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:36Z" level=debug msg="Response code:404 for url: /api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:36Z" level=debug msg="Invalid Response received Body: %!s(<nil>) error: <nil>" func="github.com/dell/gounity/api.(*client).DoWithHeaders()" file="dell/gounity@v1.9.1/api/restclient.go:333"
time="2022-05-16T07:22:36Z" level=debug msg="Error in response. Method:GET URI:/api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health Error: [{The requested resource does not exist. (Error Code:0x7d13005)}] JSON Error: [{The requested resource does not exist. (Error Code:0x7d13005)}]" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:114"
time="2022-05-16T07:22:36Z" level=error msg="failed to invoke Unity REST API server" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:127" error="[{The requested resource does not exist. (Error Code:0x7d13005)}]"
time="2022-05-16T07:22:36Z" level=debug arrayid=crk00212500758 runid=14 msg="Volume does not exist, proceeding to create new volume" func="github.com/dell/csi-unity/service.(*service).CreateVolume()" file="/go/src/csi-unity/service/controller.go:252"
time="2022-05-16T07:22:36Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/pool/pool_1?fields=id,name,description,sizeFree,sizeTotal,sizeUsed,sizeSubscribed,hasDataReductionEnabledLuns,hasDataReductionEnabledFs,isFASTCacheEnabled,type,isAllFlash,poolFastVP" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:36Z" level=debug msg="Response code:200 for url: /api/instances/pool/pool_1?fields=id,name,description,sizeFree,sizeTotal,sizeUsed,sizeSubscribed,hasDataReductionEnabledLuns,hasDataReductionEnabledFs,isFASTCacheEnabled,type,isAllFlash,poolFastVP" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:36Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/pool/pool_1?fields=id,name,description,sizeFree,sizeTotal,sizeUsed,sizeSubscribed,hasDataReductionEnabledLuns,hasDataReductionEnabledFs,isFASTCacheEnabled,type,isAllFlash,poolFastVP" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:36Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/license/name:THIN_PROVISIONING?fields=isInstalled,isValid" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:36Z" level=debug msg="Response code:200 for url: /api/instances/license/name:THIN_PROVISIONING?fields=isInstalled,isValid" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:36Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/license/name:THIN_PROVISIONING?fields=isInstalled,isValid" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:36Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/license/name:DATA_REDUCTION?fields=isInstalled,isValid" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:36Z" level=debug msg="Response code:200 for url: /api/instances/license/name:DATA_REDUCTION?fields=isInstalled,isValid" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:36Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/license/name:DATA_REDUCTION?fields=isInstalled,isValid" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:36Z" level=debug msg="FastVP is not enabled" func="github.com/dell/gounity.(*Volume).CreateLun()" file="dell/gounity@v1.9.1/volume.go:135"
time="2022-05-16T07:22:36Z" level=debug msg="Invoking REST API server info Method: POST, URI: /api/types/storageResource/action/createLun" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:36Z" level=debug msg="Request Body: {name:csivol-0b9be6c2e6,lunParameters:{size:12884901888,isThinEnabled:true,pool:{id:pool_1},isDataReductionEnabled:false}}" func="github.com/dell/gounity/api.(*client).DoWithHeaders()" file="dell/gounity@v1.9.1/api/restclient.go:301"
time="2022-05-16T07:22:38Z" level=debug msg="Response code:200 for url: /api/types/storageResource/action/createLun" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:38Z" level=debug msg="Execution successful on Method: POST, URI: /api/types/storageResource/action/createLun" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:38Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:39Z" level=debug msg="Response code:200 for url: /api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:39Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/lun/name:csivol-0b9be6c2e6?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:39Z" level=debug arrayid=crk00212500758 runid=14 msg="CreateVolume successful for volid: [csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50]" func="github.com/dell/csi-unity/service.(*service).CreateVolume()" file="/go/src/csi-unity/service/controller.go:261"
time="2022-05-16T07:22:39Z" level=info msg="/csi.v1.Controller/CreateVolume: REP 0014: Volume=capacity_bytes:12884901888 volume_id:\"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50\" volume_context:<key:\"arrayId\" value:\"crk00212500758\" > volume_context:<key:\"protocol\" value:\"iSCSI\" > volume_context:<key:\"volumeId\" value:\"sv_50\" > accessible_topology:<segments:<key:\"csi-unity.dellemc.com/crk00212500758-iscsi\" value:\"true\" > segments:<key:\"csi-unity.dellemc.com/crk00212500758-nfs\" value:\"true\" > > , XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:41Z" level=info msg="/csi.v1.Controller/ControllerPublishVolume: REQ 0015: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, NodeId=node1,node1, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , Readonly=false, VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:41Z" level=debug  runid=15 msg="Executing ControllerPublishVolume with args: {VolumeId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50 NodeId:node1,node1 VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerPublishVolume()" file="/go/src/csi-unity/service/controller.go:322"
time="2022-05-16T07:22:41Z" level=debug arrayid=crk00212500758 runid=15 msg="Probing controller service automatically" func="github.com/dell/csi-unity/service.(*service).requireProbe()" file="/go/src/csi-unity/service/service.go:757"
time="2022-05-16T07:22:41Z" level=debug arrayid=crk00212500758 runid=15 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:41Z" level=info msg="URI/api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Host).FindHostByName()" file="dell/gounity@v1.9.1/host.go:46"
time="2022-05-16T07:22:41Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:41Z" level=debug msg="Response code:200 for url: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:41Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:41Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:41Z" level=debug msg="Response code:200 for url: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:41Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:41Z" level=debug arrayid=crk00212500758 runid=15 msg="Adding host access to Host_32 on volume sv_50" func="github.com/dell/csi-unity/service.(*service).exportVolume()" file="/go/src/csi-unity/service/controller.go:1579"
time="2022-05-16T07:22:41Z" level=debug arrayid=crk00212500758 runid=15 msg="List of all hosts to which the volume will have access: [Host_32]" func="github.com/dell/csi-unity/service.(*service).exportVolume()" file="/go/src/csi-unity/service/controller.go:1580"
time="2022-05-16T07:22:41Z" level=debug msg="Invoking REST API server info Method: POST, URI: /api/instances/storageResource/sv_50/action/modifyLun" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:41Z" level=debug msg="Request Body: {lunParameters:{hostAccess:[{host:{id:Host_32},accessMask:1}]}}" func="github.com/dell/gounity/api.(*client).DoWithHeaders()" file="dell/gounity@v1.9.1/api/restclient.go:301"
time="2022-05-16T07:22:43Z" level=debug msg="Response code:204 for url: /api/instances/storageResource/sv_50/action/modifyLun" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:43Z" level=debug msg="Execution successful on Method: POST, URI: /api/instances/storageResource/sv_50/action/modifyLun" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:43Z" level=debug arrayid=crk00212500758 runid=15 msg="ControllerPublishVolume successful for volid: [csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50]" func="github.com/dell/csi-unity/service.(*service).exportVolume()" file="/go/src/csi-unity/service/controller.go:1585"
time="2022-05-16T07:22:43Z" level=info msg="/csi.v1.Controller/ControllerPublishVolume: REP 0015: PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:43Z" level=info msg="/csi.v1.Controller/ControllerPublishVolume: REQ 0016: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, NodeId=node1,node1, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , Readonly=false, VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:43Z" level=debug  runid=16 msg="Executing ControllerPublishVolume with args: {VolumeId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50 NodeId:node1,node1 VolumeCapability:mount:<fs_type:"xfs" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).ControllerPublishVolume()" file="/go/src/csi-unity/service/controller.go:322"
time="2022-05-16T07:22:43Z" level=debug arrayid=crk00212500758 runid=16 msg="Probing controller service automatically" func="github.com/dell/csi-unity/service.(*service).requireProbe()" file="/go/src/csi-unity/service/service.go:757"
time="2022-05-16T07:22:43Z" level=debug arrayid=crk00212500758 runid=16 msg="Inside Controller Probe" func="github.com/dell/csi-unity/service.(*service).probe()" file="/go/src/csi-unity/service/service.go:793"
time="2022-05-16T07:22:43Z" level=info msg="URI/api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Host).FindHostByName()" file="dell/gounity@v1.9.1/host.go:46"
time="2022-05-16T07:22:43Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:43Z" level=debug msg="Response code:200 for url: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:43Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:43Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:44Z" level=debug msg="Response code:200 for url: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:44Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/lun/sv_50?fields=id,name,description,type,wwn,sizeTotal,sizeUsed,sizeAllocated,hostAccess,pool,tieringPolicy,ioLimitPolicy,isThinEnabled,isDataReductionEnabled,isThinClone,parentSnap,originalParentLun?fields,health" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:44Z" level=debug arrayid=crk00212500758 runid=16 msg="Volume has been published to the given host and exists in the required state." func="github.com/dell/csi-unity/service.(*service).exportVolume()" file="/go/src/csi-unity/service/controller.go:1567"
time="2022-05-16T07:22:44Z" level=info msg="/csi.v1.Controller/ControllerPublishVolume: REP 0016: PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"

controller-provisioner:

W0516 07:21:52.978761       1 feature_gate.go:237] Setting GA feature gate Topology=true. It will be removed in a future release.
I0516 07:21:52.978813       1 feature_gate.go:245] feature gates: &{map[Topology:true]}
I0516 07:21:52.978830       1 csi-provisioner.go:139] Version: v3.1.0
I0516 07:21:52.978835       1 csi-provisioner.go:162] Building kube configs for running in cluster...
I0516 07:21:52.979505       1 connection.go:154] Connecting to unix:///var/run/csi/csi.sock
W0516 07:22:02.980071       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
W0516 07:22:12.980273       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
I0516 07:22:14.530354       1 common.go:111] Probing CSI driver for readiness
I0516 07:22:14.530396       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0516 07:22:14.530410       1 connection.go:184] GRPC request: {}
I0516 07:22:15.974283       1 connection.go:186] GRPC response: {}
I0516 07:22:15.974473       1 connection.go:187] GRPC error: <nil>
I0516 07:22:15.974501       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I0516 07:22:15.974512       1 connection.go:184] GRPC request: {}
I0516 07:22:15.975771       1 connection.go:186] GRPC response: {"manifest":{"commit":"0188813dc1ca097b4b920b37784038482f5f1bd1","formed":"Tue, 22 Mar 2022 21:47:11 UTC","semver":"2.2.0","url":"http://github.com/dell/csi-unity"},"name":"csi-unity.dellemc.com","vendor_version":"2.2.0"}
I0516 07:22:15.976062       1 connection.go:187] GRPC error: <nil>
I0516 07:22:15.976105       1 csi-provisioner.go:206] Detected CSI driver csi-unity.dellemc.com
I0516 07:22:15.976137       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0516 07:22:15.976150       1 connection.go:184] GRPC request: {}
I0516 07:22:15.978199       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"VolumeExpansion":{"type":2}}},{"Type":{"Service":{"type":2}}}]}
I0516 07:22:15.978582       1 connection.go:187] GRPC error: <nil>
I0516 07:22:15.978609       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0516 07:22:15.978621       1 connection.go:184] GRPC request: {}
I0516 07:22:15.980404       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":4}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":8}}},{"Type":{"Rpc":{"type":13}}}]}
I0516 07:22:15.980778       1 connection.go:187] GRPC error: <nil>
I0516 07:22:15.980941       1 csi-provisioner.go:275] CSI driver supports PUBLISH_UNPUBLISH_VOLUME, watching VolumeAttachments
I0516 07:22:15.981986       1 controller.go:732] Using saving PVs to API server in background
I0516 07:22:15.982839       1 leaderelection.go:248] attempting to acquire leader lease unity/csi-unity-dellemc-com...
I0516 07:22:16.003148       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:16.003198       1 leaderelection.go:253] failed to acquire lease unity/csi-unity-dellemc-com
I0516 07:22:16.003237       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-x62m2
I0516 07:22:26.659838       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:26.659865       1 leaderelection.go:253] failed to acquire lease unity/csi-unity-dellemc-com
I0516 07:22:35.658924       1 leaderelection.go:258] successfully acquired lease unity/csi-unity-dellemc-com
I0516 07:22:35.658979       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-ljsqs
I0516 07:22:35.659025       1 leader_election.go:205] became leader, starting
I0516 07:22:35.660066       1 reflector.go:219] Starting reflector *v1.CSINode (1h0m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660098       1 reflector.go:255] Listing and watching *v1.CSINode from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660095       1 reflector.go:219] Starting reflector *v1.VolumeAttachment (1h0m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660141       1 reflector.go:255] Listing and watching *v1.VolumeAttachment from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660142       1 reflector.go:219] Starting reflector *v1.StorageClass (1h0m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660175       1 reflector.go:255] Listing and watching *v1.StorageClass from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660179       1 reflector.go:219] Starting reflector *v1.PersistentVolumeClaim (15m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660242       1 reflector.go:219] Starting reflector *v1.Node (1h0m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660272       1 reflector.go:255] Listing and watching *v1.PersistentVolumeClaim from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.660286       1 reflector.go:255] Listing and watching *v1.Node from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.671138       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:22:35.760304       1 shared_informer.go:270] caches populated
I0516 07:22:35.760350       1 shared_informer.go:270] caches populated
I0516 07:22:35.760369       1 shared_informer.go:270] caches populated
I0516 07:22:35.760384       1 shared_informer.go:270] caches populated
I0516 07:22:35.760398       1 shared_informer.go:270] caches populated
I0516 07:22:35.760420       1 controller.go:811] Starting provisioner controller csi-unity.dellemc.com_unity-controller-56f889749b-ljsqs_5b63fd6d-aac4-41d1-aba5-313dff453028!
I0516 07:22:35.760473       1 clone_controller.go:66] Starting CloningProtection controller
I0516 07:22:35.760491       1 volume_store.go:97] Starting save volume queue
I0516 07:22:35.760587       1 clone_controller.go:82] Started CloningProtection controller
I0516 07:22:35.760765       1 reflector.go:219] Starting reflector *v1.PersistentVolume (15m0s) from sigs.k8s.io/sig-storage-lib-external-provisioner/v8/controller/controller.go:845
I0516 07:22:35.760792       1 reflector.go:255] Listing and watching *v1.PersistentVolume from sigs.k8s.io/sig-storage-lib-external-provisioner/v8/controller/controller.go:845
I0516 07:22:35.760862       1 reflector.go:219] Starting reflector *v1.StorageClass (15m0s) from sigs.k8s.io/sig-storage-lib-external-provisioner/v8/controller/controller.go:848
I0516 07:22:35.760920       1 reflector.go:255] Listing and watching *v1.StorageClass from sigs.k8s.io/sig-storage-lib-external-provisioner/v8/controller/controller.go:848
I0516 07:22:35.861453       1 shared_informer.go:270] caches populated
I0516 07:22:35.861517       1 controller.go:860] Started provisioner controller csi-unity.dellemc.com_unity-controller-56f889749b-ljsqs_5b63fd6d-aac4-41d1-aba5-313dff453028!
I0516 07:22:35.861611       1 controller.go:1337] provision "default/pvol1" class "unity01-iscsi": started
I0516 07:22:35.861849       1 connection.go:183] GRPC call: /csi.v1.Controller/CreateVolume
I0516 07:22:35.861856       1 event.go:285] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"pvol1", UID:"0b9be6c2-e6f2-43e4-bbc5-5ba1e31be6f5", APIVersion:"v1", ResourceVersion:"661299", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/pvol1"
I0516 07:22:35.861871       1 connection.go:184] GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"csi-unity.dellemc.com/crk00212500758-iscsi":"true","csi-unity.dellemc.com/crk00212500758-nfs":"true"}}],"requisite":[{"segments":{"csi-unity.dellemc.com/crk00212500758-iscsi":"true","csi-unity.dellemc.com/crk00212500758-nfs":"true"}}]},"capacity_range":{"required_bytes":12884901888},"name":"csivol-0b9be6c2e6","parameters":{"arrayId":"CRK00212500758","protocol":"iSCSI","storagePool":"pool_1","thinProvisioned":"true"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"xfs"}},"access_mode":{"mode":7}}]}
I0516 07:22:39.150133       1 connection.go:186] GRPC response: {"volume":{"accessible_topology":[{"segments":{"csi-unity.dellemc.com/crk00212500758-iscsi":"true","csi-unity.dellemc.com/crk00212500758-nfs":"true"}}],"capacity_bytes":12884901888,"volume_context":{"arrayId":"crk00212500758","protocol":"iSCSI","volumeId":"sv_50"},"volume_id":"csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50"}}
I0516 07:22:39.150459       1 connection.go:187] GRPC error: <nil>
I0516 07:22:39.150486       1 controller.go:774] create volume rep: {CapacityBytes:12884901888 VolumeId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50 VolumeContext:map[arrayId:crk00212500758 protocol:iSCSI volumeId:sv_50] ContentSource:<nil> AccessibleTopology:[segments:<key:"csi-unity.dellemc.com/crk00212500758-iscsi" value:"true" > segments:<key:"csi-unity.dellemc.com/crk00212500758-nfs" value:"true" > ] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0516 07:22:39.150608       1 controller.go:858] successfully created PV csivol-0b9be6c2e6 for PVC pvol1 and csi volume name csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50
I0516 07:22:39.150640       1 controller.go:874] successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:nil HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:&CSIPersistentVolumeSource{Driver:csi-unity.dellemc.com,VolumeHandle:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50,ReadOnly:false,FSType:xfs,VolumeAttributes:map[string]string{arrayId: crk00212500758,protocol: iSCSI,storage.kubernetes.io/csiProvisionerIdentity: 1652685735980-8081-csi-unity.dellemc.com,volumeId: sv_50,},ControllerPublishSecretRef:nil,NodeStageSecretRef:nil,NodePublishSecretRef:nil,ControllerExpandSecretRef:nil,}}
I0516 07:22:39.150903       1 controller.go:1442] provision "default/pvol1" class "unity01-iscsi": volume "csivol-0b9be6c2e6" provisioned
I0516 07:22:39.150928       1 controller.go:1455] provision "default/pvol1" class "unity01-iscsi": succeeded
I0516 07:22:39.150942       1 volume_store.go:154] Saving volume csivol-0b9be6c2e6
I0516 07:22:39.172399       1 volume_store.go:157] Volume csivol-0b9be6c2e6 saved
I0516 07:22:39.172533       1 controller.go:1069] Claim processing succeeded, removing PVC 0b9be6c2-e6f2-43e4-bbc5-5ba1e31be6f5 from claims in progress
I0516 07:22:39.172632       1 event.go:285] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"pvol1", UID:"0b9be6c2-e6f2-43e4-bbc5-5ba1e31be6f5", APIVersion:"v1", ResourceVersion:"661299", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume csivol-0b9be6c2e6
I0516 07:22:40.688448       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:22:45.699628       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:22:50.716298       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:22:55.727854       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:00.746091       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:05.755701       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:10.774453       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:15.795401       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:20.814577       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:25.833741       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:30.852413       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:35.870680       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:40.888153       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:45.906481       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:50.922395       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:23:55.939093       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:00.955879       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:05.972692       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:10.988784       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:16.007534       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:21.025182       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:26.044356       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:31.061264       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:36.080652       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:41.096906       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:46.113567       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:51.129930       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com
I0516 07:24:56.147485       1 leaderelection.go:278] successfully renewed lease unity/csi-unity-dellemc-com

controller-resizer:

I0516 07:21:53.102316       1 main.go:93] Version : v1.4.0
I0516 07:21:53.102369       1 feature_gate.go:245] feature gates: &{map[]}
I0516 07:21:53.104231       1 connection.go:154] Connecting to unix:///var/run/csi/csi.sock
W0516 07:22:03.104858       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
W0516 07:22:13.104987       1 connection.go:173] Still connecting to unix:///var/run/csi/csi.sock
I0516 07:22:15.044670       1 common.go:111] Probing CSI driver for readiness
I0516 07:22:15.044712       1 connection.go:183] GRPC call: /csi.v1.Identity/Probe
I0516 07:22:15.044725       1 connection.go:184] GRPC request: {}
I0516 07:22:16.658903       1 connection.go:186] GRPC response: {}
I0516 07:22:16.659056       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.659085       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I0516 07:22:16.659095       1 connection.go:184] GRPC request: {}
I0516 07:22:16.660232       1 connection.go:186] GRPC response: {"manifest":{"commit":"0188813dc1ca097b4b920b37784038482f5f1bd1","formed":"Tue, 22 Mar 2022 21:47:11 UTC","semver":"2.2.0","url":"http://github.com/dell/csi-unity"},"name":"csi-unity.dellemc.com","vendor_version":"2.2.0"}
I0516 07:22:16.662294       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.662755       1 main.go:141] CSI driver name: "csi-unity.dellemc.com"
I0516 07:22:16.662796       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginCapabilities
I0516 07:22:16.662817       1 connection.go:184] GRPC request: {}
I0516 07:22:16.664429       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Service":{"type":1}}},{"Type":{"VolumeExpansion":{"type":1}}},{"Type":{"VolumeExpansion":{"type":2}}},{"Type":{"Service":{"type":2}}}]}
I0516 07:22:16.664760       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.664782       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0516 07:22:16.664793       1 connection.go:184] GRPC request: {}
I0516 07:22:16.666209       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":4}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":8}}},{"Type":{"Rpc":{"type":13}}}]}
I0516 07:22:16.666498       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.666524       1 connection.go:183] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I0516 07:22:16.666534       1 connection.go:184] GRPC request: {}
I0516 07:22:16.667575       1 connection.go:186] GRPC response: {"capabilities":[{"Type":{"Rpc":{"type":1}}},{"Type":{"Rpc":{"type":2}}},{"Type":{"Rpc":{"type":4}}},{"Type":{"Rpc":{"type":5}}},{"Type":{"Rpc":{"type":6}}},{"Type":{"Rpc":{"type":9}}},{"Type":{"Rpc":{"type":7}}},{"Type":{"Rpc":{"type":8}}},{"Type":{"Rpc":{"type":13}}}]}
I0516 07:22:16.667797       1 connection.go:187] GRPC error: <nil>
I0516 07:22:16.668089       1 controller.go:120] Register Pod informer for resizer csi-unity.dellemc.com
I0516 07:22:16.668943       1 leaderelection.go:248] attempting to acquire leader lease unity/external-resizer-csi-unity-dellemc-com...
I0516 07:22:16.685399       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:16.685450       1 leaderelection.go:253] failed to acquire lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:16.685493       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-x62m2
I0516 07:22:25.320446       1 leaderelection.go:352] lock is held by unity-controller-56f889749b-x62m2 and has not yet expired
I0516 07:22:25.320477       1 leaderelection.go:253] failed to acquire lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:35.975181       1 leaderelection.go:258] successfully acquired lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:35.975264       1 leader_election.go:212] new leader detected, current leader: unity-controller-56f889749b-ljsqs
I0516 07:22:35.975406       1 leader_election.go:205] became leader, starting
I0516 07:22:35.975505       1 controller.go:255] Starting external resizer csi-unity.dellemc.com
I0516 07:22:35.976177       1 reflector.go:219] Starting reflector *v1.PersistentVolumeClaim (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.976248       1 reflector.go:255] Listing and watching *v1.PersistentVolumeClaim from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.976285       1 reflector.go:219] Starting reflector *v1.Pod (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.976320       1 reflector.go:255] Listing and watching *v1.Pod from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.976372       1 reflector.go:219] Starting reflector *v1.PersistentVolume (10m0s) from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.976406       1 reflector.go:255] Listing and watching *v1.PersistentVolume from k8s.io/client-go/informers/factory.go:134
I0516 07:22:35.986793       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:36.076081       1 shared_informer.go:270] caches populated
I0516 07:22:36.076200       1 controller.go:295] Started PVC processing "default/pvol1"
I0516 07:22:36.076257       1 controller.go:318] PV bound to PVC "default/pvol1" is not created yet
I0516 07:22:39.190958       1 controller.go:295] Started PVC processing "default/pvol1"
I0516 07:22:39.191014       1 controller.go:343] No need to resize PVC "default/pvol1"
I0516 07:22:40.999278       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:46.013529       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:51.027178       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:22:56.041938       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:01.055257       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:06.070097       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:11.084104       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:16.098794       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:21.113140       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:26.127579       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:31.140908       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:36.153990       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:41.168053       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:46.180429       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:51.194053       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:23:56.208622       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:01.222756       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:06.235836       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:11.253379       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:16.267230       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:21.281893       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:26.295117       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:31.309881       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:36.321970       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:41.336998       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:46.351915       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:51.367045       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:24:56.381660       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:25:01.396759       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:25:06.410982       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com
I0516 07:25:11.425896       1 leaderelection.go:278] successfully renewed lease unity/external-resizer-csi-unity-dellemc-com

node-driver:

Endpoint /var/lib/kubelet/plugins/unity.emc.dell.com/csi_sock
csi-unity logger initiated. This should be called only once.
time="2022-05-16T07:21:53Z" level=info  runid=start msg="Driver Mode:node" func="github.com/dell/csi-unity/service.(*service).BeforeServe()" file="/go/src/csi-unity/service/service.go:174"
time="2022-05-16T07:21:53Z" level=info  runid=start msg="X_CSI_UNITY_NODENAME: node1" func="github.com/dell/csi-unity/service.(*service).BeforeServe()" file="/go/src/csi-unity/service/service.go:182"
time="2022-05-16T07:21:53Z" level=info  runid=config-0 msg="*************Synchronizing driver secret**************" func="github.com/dell/csi-unity/service.(*service).syncDriverSecret()" file="/go/src/csi-unity/service/service.go:459"
gounity logger initiated. This should be called only once.
time="2022-05-16T07:21:53Z" level=info msg="configured csi-unity.dellemc.com" ArrayId=crk00212500758 Endpoint="https://192.168.150.241/" IsDefault=true SkipCertificateValidation=false password="*******" username=csi.k8s.*******.io
time="2022-05-16T07:21:53Z" level=info  runid=node-0 msg="Starting goroutine to add Node information to storage array" func="github.com/dell/csi-unity/service.(*service).syncNodeInfoRoutine()" file="/go/src/csi-unity/service/node.go:1835"
time="2022-05-16T07:21:53Z" level=info  runid=config-0 msg="configured csi-unity.dellemc.com" func="github.com/dell/csi-unity/service.(*service).BeforeServe.func1()" file="/go/src/csi-unity/service/service.go:169"
time="2022-05-16T07:21:53Z" level=info  runid=config-1 msg="Dynamic config load goroutine invoked" func="github.com/dell/csi-unity/service.(*service).loadDynamicConfig()" file="/go/src/csi-unity/service/service.go:374"
time="2022-05-16T07:21:53Z" level=info msg="identity service registered"
time="2022-05-16T07:21:53Z" level=info msg="node service registered"
time="2022-05-16T07:21:53Z" level=info  runid=RegisterAdditionalServers msg="Registering additional GRPC servers" func="github.com/dell/csi-unity/service.(*service).RegisterAdditionalServers()" file="/go/src/csi-unity/service/service.go:286"
time="2022-05-16T07:21:53Z" level=info msg=serving endpoint="unix:///var/lib/kubelet/plugins/unity.emc.dell.com/csi_sock"
time="2022-05-16T07:21:53Z" level=info arrayid=crk00212500758 runid=node-2 msg="*************Synchronizing driver config**************" func="github.com/dell/csi-unity/service.(*service).syncDriverConfig()" file="/go/src/csi-unity/service/service.go:560"
time="2022-05-16T07:21:53Z" level=warning arrayid=crk00212500758 runid=node-2 msg="Log level changed to: debug" func="github.com/dell/csi-unity/service.(*service).syncDriverConfig()" file="/go/src/csi-unity/service/service.go:578"
time="2022-05-16T07:21:53Z" level=debug  runid=config-1 msg="Secret folder:/unity-secret" func="github.com/dell/csi-unity/service.(*service).loadDynamicConfig()" file="/go/src/csi-unity/service/service.go:398"
time="2022-05-16T07:21:53Z" level=debug msg="Executing Authenticate REST client" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:51"
time="2022-05-16T07:21:54Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REQ 0001: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:21:54Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REP 0001: Name=csi-unity.dellemc.com, VendorVersion=2.2.0, Manifest=map[commit:0188813dc1ca097b4b920b37784038482f5f1bd1 formed:Tue, 22 Mar 2022 21:47:11 UTC semver:2.2.0 url:http://github.com/dell/csi-unity], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:21:54Z" level=info msg="/csi.v1.Node/NodeGetInfo: REQ 0002: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:21:54Z" level=debug  runid=2 msg="Executing NodeGetInfo with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetInfo()" file="/go/src/csi-unity/service/node.go:795"
time="2022-05-16T07:21:55Z" level=debug msg="Response code:200 for url: /api/types/loginSessionInfo" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:55Z" level=debug msg="Authentication response code: 200" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:65"
time="2022-05-16T07:21:55Z" level=debug msg="Authentication successful" func="github.com/dell/gounity.(*Client).Authenticate()" file="dell/gounity@v1.9.1/unityclient.go:75"
time="2022-05-16T07:21:55Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Controller Probe Success" func="github.com/dell/csi-unity/service.singleArrayProbe()" file="/go/src/csi-unity/service/service.go:785"
time="2022-05-16T07:21:55Z" level=warning arrayid=crk00212500758 runid=node-2 msg="Cannot read directory: /sys/class/fc_host : open /sys/class/fc_host: no such file or directory" func="github.com/dell/csi-unity/service/utils.GetFCInitiators()" file="/go/src/csi-unity/service/utils/emcutils.go:95"
time="2022-05-16T07:21:55Z" level=warning arrayid=crk00212500758 runid=node-2 msg="'FC Initiators' cannot be retrieved." func="github.com/dell/csi-unity/service.(*service).addNodeInformationIntoArray()" file="/go/src/csi-unity/service/node.go:1590"
time="2022-05-16T07:21:55Z" level=info msg="URI/api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Host).FindHostByName()" file="dell/gounity@v1.9.1/host.go:46"
time="2022-05-16T07:21:55Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:55Z" level=debug msg="Response code:200 for url: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:55Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:55Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Host node1 exists on the array" func="github.com/dell/csi-unity/service.(*service).addNodeInformationIntoArray()" file="/go/src/csi-unity/service/node.go:1632"
time="2022-05-16T07:21:55Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:56Z" level=debug msg="Response code:200 for url: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:56Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:56Z" level=info arrayid=crk00212500758 runid=node-2 msg="Node initiators are synchronized with the Host Wwns on the array" func="github.com/dell/csi-unity/service.(*service).checkHostIdempotency()" file="/go/src/csi-unity/service/node.go:1743"
time="2022-05-16T07:21:56Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Adding iSCSI Initiator: Host_32 to host: iqn.1993-08.org.debian:01:e0741deca62 " func="github.com/dell/csi-unity/service.(*service).addNodeInformationIntoArray()" file="/go/src/csi-unity/service/node.go:1668"
time="2022-05-16T07:21:56Z" level=debug msg="Finding Initiator: iqn.1993-08.org.debian:01:e0741deca62" func="github.com/dell/gounity.(*Host).CreateHostInitiator()" file="dell/gounity@v1.9.1/host.go:197"
time="2022-05-16T07:21:56Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/types/hostInitiator/instances?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:56Z" level=debug msg="Response code:200 for url: /api/types/hostInitiator/instances?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:56Z" level=debug msg="Execution successful on Method: GET, URI: /api/types/hostInitiator/instances?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:56Z" level=debug msg="FindHostInitiatorByName: &{{HostInitiator_11 {5 [ALRT_COMPONENT_OK] [The component is operating normally. No action is required.]} 2 iqn.1993-08.org.debian:01:e0741deca62 false {Host_32   [] [] [] } [{HostInitiator_11_03:00:00:06_2} {HostInitiator_11_03:00:01:06_1}]}} Error: <nil>" func="github.com/dell/gounity.(*Host).CreateHostInitiator()" file="dell/gounity@v1.9.1/host.go:199"
time="2022-05-16T07:21:56Z" level=debug msg="Initiator found and already added to existing host Initiator: iqn.1993-08.org.debian:01:e0741deca62 to host: Host_32 \n" func="github.com/dell/gounity.(*Host).CreateHostInitiator()" file="dell/gounity@v1.9.1/host.go:222"
time="2022-05-16T07:21:56Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_62?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:56Z" level=debug msg="Response code:200 for url: /api/instances/hostIPPort/HostNetworkAddress_62?fields=id,address" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:56Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_62?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:56Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_63?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:56Z" level=debug msg="Response code:200 for url: /api/instances/hostIPPort/HostNetworkAddress_63?fields=id,address" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:56Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_63?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:56Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_64?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:57Z" level=debug msg="Response code:200 for url: /api/instances/hostIPPort/HostNetworkAddress_64?fields=id,address" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:57Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_64?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:57Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_65?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:57Z" level=debug msg="Response code:200 for url: /api/instances/hostIPPort/HostNetworkAddress_65?fields=id,address" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:57Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostIPPort/HostNetworkAddress_65?fields=id,address" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="copied 617 bytes to /etc/multipath.conf" func="github.com/dell/csi-unity/service.(*service).copyMultipathConfigFile()" file="/go/src/csi-unity/service/node.go:1435"
time="2022-05-16T07:21:57Z" level=debug msg="URI: /api/types/ipInterface/instances?fields=id,ipAddress,type" func="github.com/dell/gounity.(*Ipinterface).ListIscsiIPInterfaces()" file="dell/gounity@v1.9.1/ipinterface.go:34"
time="2022-05-16T07:21:57Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/types/ipInterface/instances?fields=id,ipAddress,type" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:21:57Z" level=info msg="/csi.v1.Node/NodeGetInfo: REP 0002: rpc error: code = Unavailable desc =  runid=2 The node [node1] is not added to any of the arrays"
time="2022-05-16T07:21:57Z" level=debug msg="Response code:200 for url: /api/types/ipInterface/instances?fields=id,ipAddress,type" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:21:57Z" level=debug msg="Execution successful on Method: GET, URI: /api/types/ipInterface/instances?fields=id,ipAddress,type" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Tcp test on IP172.17.18.10" func="github.com/dell/csi-unity/service/utils.IPReachable()" file="/go/src/csi-unity/service/utils/emcutils.go:284"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Tcp test on IP172.17.17.10" func="github.com/dell/csi-unity/service/utils.IPReachable()" file="/go/src/csi-unity/service/utils/emcutils.go:284"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Valid IPs: [172.17.18.10 172.17.17.10]" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1332"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Begin discover and login to: 172.17.18.10" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1336"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Login successful to target iqn.1992-04.com.emc:cx.crk00212500758.b6" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1351"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Login successful to target iqn.1992-04.com.emc:cx.crk00212500758.a6" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1351"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Begin discover and login to: 172.17.17.10" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1336"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Login successful to target iqn.1992-04.com.emc:cx.crk00212500758.a6" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1351"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Login successful to target iqn.1992-04.com.emc:cx.crk00212500758.b6" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1351"
time="2022-05-16T07:21:57Z" level=debug arrayid=crk00212500758 runid=node-2 msg="Completed discovery and rescan of all IP Interfaces" func="github.com/dell/csi-unity/service.(*service).iScsiDiscoverAndLogin()" file="/go/src/csi-unity/service/node.go:1356"
time="2022-05-16T07:21:57Z" level=debug  runid=node-2 msg="Node [crk00212500758] Added successfully" func="github.com/dell/csi-unity/service.(*service).syncNodeInfo.func2.1()" file="/go/src/csi-unity/service/node.go:1884"
time="2022-05-16T07:21:58Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REQ 0003: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:21:58Z" level=info msg="/csi.v1.Identity/GetPluginInfo: REP 0003: Name=csi-unity.dellemc.com, VendorVersion=2.2.0, Manifest=map[commit:0188813dc1ca097b4b920b37784038482f5f1bd1 formed:Tue, 22 Mar 2022 21:47:11 UTC semver:2.2.0 url:http://github.com/dell/csi-unity], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:00Z" level=info msg="/csi.v1.Node/NodeGetInfo: REQ 0004: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:00Z" level=debug  runid=4 msg="Executing NodeGetInfo with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetInfo()" file="/go/src/csi-unity/service/node.go:795"
time="2022-05-16T07:22:03Z" level=warning  runid=4 msg="Cannot read directory: /sys/class/fc_host : open /sys/class/fc_host: no such file or directory" func="github.com/dell/csi-unity/service/utils.GetFCInitiators()" file="/go/src/csi-unity/service/utils/emcutils.go:95"
time="2022-05-16T07:22:03Z" level=info  runid=4 msg="iSCSI/FC package found in this node proceeding to further validations" func="github.com/dell/csi-unity/service.(*service).validateProtocols()" file="/go/src/csi-unity/service/node.go:1921"
time="2022-05-16T07:22:03Z" level=info msg="URI/api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Host).FindHostByName()" file="dell/gounity@v1.9.1/host.go:46"
time="2022-05-16T07:22:03Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:03Z" level=debug msg="Response code:200 for url: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:03Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/host/name:node1?fields=id,name,description,fcHostInitiators,iscsiHostInitiators,hostIPPorts?fields" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:03Z" level=info  runid=4 msg="Got iSCSI Initiators, Checking health of initiators:[{HostInitiator_11}]" func="github.com/dell/csi-unity/service.(*service).validateProtocols()" file="/go/src/csi-unity/service/node.go:1955"
time="2022-05-16T07:22:03Z" level=debug msg="Invoking REST API server info Method: GET, URI: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:106"
time="2022-05-16T07:22:03Z" level=debug msg="Response code:200 for url: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity/api.(*client).DoAndGetResponseBody()" file="dell/gounity@v1.9.1/api/restclient.go:292"
time="2022-05-16T07:22:03Z" level=debug msg="Execution successful on Method: GET, URI: /api/instances/hostInitiator/HostInitiator_11?fields=id,health,type,initiatorId,isIgnored,parentHost,paths" func="github.com/dell/gounity.(*Client).executeWithRetryAuthenticate()" file="dell/gounity@v1.9.1/unityclient.go:109"
time="2022-05-16T07:22:03Z" level=info  runid=4 msg="iSCSI health is good for array:crk00212500758, Health:ALRT_COMPONENT_OK" func="github.com/dell/csi-unity/service.(*service).validateProtocols()" file="/go/src/csi-unity/service/node.go:1965"
time="2022-05-16T07:22:03Z" level=debug  runid=4 msg="Topology Keys--->map[csi-unity.dellemc.com/crk00212500758-iscsi:true csi-unity.dellemc.com/crk00212500758-nfs:true]" func="github.com/dell/csi-unity/service.(*service).NodeGetInfo()" file="/go/src/csi-unity/service/node.go:812"
time="2022-05-16T07:22:03Z" level=debug arrayid=crk00212500758 runid=4 msg="Node labels: map[beta.kubernetes.io/arch:amd64 beta.kubernetes.io/os:linux csi-unity.dellemc.com/crk00212500758-iscsi:true csi-unity.dellemc.com/crk00212500758-nfs:true kubernetes.io/arch:amd64 kubernetes.io/hostname:node1 kubernetes.io/os:linux node-role.kubernetes.io/control-plane: node-role.kubernetes.io/master: node.kubernetes.io/exclude-from-external-load-balancers:]
" func="github.com/dell/csi-unity/service.(*service).GetNodeLabels()" file="/go/src/csi-unity/service/service.go:856"
time="2022-05-16T07:22:03Z" level=info  runid=4 msg="NodeGetInfo success" func="github.com/dell/csi-unity/service.(*service).NodeGetInfo()" file="/go/src/csi-unity/service/node.go:836"
time="2022-05-16T07:22:03Z" level=info msg="/csi.v1.Node/NodeGetInfo: REP 0004: NodeId=node1,node1, MaxVolumesPerNode=0, AccessibleTopology=segments:<key:\"csi-unity.dellemc.com/crk00212500758-iscsi\" value:\"true\" > segments:<key:\"csi-unity.dellemc.com/crk00212500758-nfs\" value:\"true\" > , XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0005: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info  runid=5 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0005: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0006: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info  runid=6 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0006: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0007: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info  runid=7 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0007: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0008: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:50Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0008: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0009: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info  runid=9 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0009: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0010: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info  runid=10 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0010: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0011: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info  runid=11 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0011: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0012: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:51Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0012: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0013: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info  runid=13 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0013: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0014: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info  runid=14 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0014: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0015: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info  runid=15 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0015: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0016: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:52Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0016: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0017: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info  runid=17 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0017: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0018: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info  runid=18 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0018: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0019: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info  runid=19 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0019: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0020: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:54Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0020: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0021: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info  runid=21 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0021: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0022: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info  runid=22 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0022: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0023: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info  runid=23 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0023: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0024: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:22:58Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0024: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0025: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info  runid=25 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0025: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0026: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info  runid=26 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0026: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0027: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info  runid=27 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0027: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0028: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:06Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0028: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0029: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info  runid=29 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0029: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0030: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info  runid=30 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0030: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REQ 0031: XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info  runid=31 msg="Executing NodeGetCapabilities with args: {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}" func="github.com/dell/csi-unity/service.(*service).NodeGetCapabilities()" file="/go/src/csi-unity/service/node.go:854"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeGetCapabilities: REP 0031: Capabilities=[rpc:<>  rpc:<type:STAGE_UNSTAGE_VOLUME >  rpc:<type:EXPAND_VOLUME >  rpc:<type:SINGLE_NODE_MULTI_WRITER >  rpc:<type:GET_VOLUME_STATS >  rpc:<type:VOLUME_CONDITION > ], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeStageVolume: REQ 0032: VolumeId=csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50, PublishContext=map[arrayId:crk00212500758 host:node1,node1 lun:sv_50 volumeContextId:csivol-0b9be6c2e6-iSCSI-crk00212500758-sv_50], StagingTargetPath=/var/lib/kubelet/plugins/kubernetes.io/csi/csi-unity.dellemc.com/4191be21bdeb9b28f514b3065367e78d0237d873af4291fa678edcb753546f82/globalmount, VolumeCapability=mount:<fs_type:\"xfs\" > access_mode:<mode:SINGLE_NODE_MULTI_WRITER > , VolumeContext=map[arrayId:crk00212500758 protocol:iSCSI storage.kubernetes.io/csiProvisionerIdentity:1652685735980-8081-csi-unity.dellemc.com volumeId:sv_50], XXX_NoUnkeyedLiteral={}, XXX_sizecache=0"
time="2022-05-16T07:23:22Z" level=info msg="/csi.v1.Node/NodeStageVolume: REP 0032: rpc error: code = InvalidArgument desc = exceeds size limit: StagingTargetPath: max=128, size=141"

node-registrar:

I0516 07:21:58.564739       1 main.go:166] Version: v2.5.0
I0516 07:21:58.564788       1 main.go:167] Running node-driver-registrar in mode=registration
I0516 07:21:58.566503       1 main.go:191] Attempting to open a gRPC connection with: "/csi/csi_sock"
I0516 07:21:58.566532       1 connection.go:154] Connecting to unix:///csi/csi_sock
I0516 07:21:58.567510       1 main.go:198] Calling CSI driver to discover driver name
I0516 07:21:58.567562       1 connection.go:183] GRPC call: /csi.v1.Identity/GetPluginInfo
I0516 07:21:58.567574       1 connection.go:184] GRPC request: {}
I0516 07:21:58.578998       1 connection.go:186] GRPC response: {"manifest":{"commit":"0188813dc1ca097b4b920b37784038482f5f1bd1","formed":"Tue, 22 Mar 2022 21:47:11 UTC","semver":"2.2.0","url":"http://github.com/dell/csi-unity"},"name":"csi-unity.dellemc.com","vendor_version":"2.2.0"}
I0516 07:21:58.579208       1 connection.go:187] GRPC error: <nil>
I0516 07:21:58.579250       1 main.go:208] CSI driver name: "csi-unity.dellemc.com"
I0516 07:21:58.579385       1 node_register.go:53] Starting Registration Server at: /registration/csi-unity.dellemc.com-reg.sock
I0516 07:21:58.579784       1 node_register.go:62] Registration Server started at: /registration/csi-unity.dellemc.com-reg.sock
I0516 07:21:58.579948       1 node_register.go:92] Skipping HTTP server because endpoint is set to: ""
I0516 07:22:00.285688       1 main.go:102] Received GetInfo call: &InfoRequest{}
I0516 07:22:00.286335       1 main.go:109] "Kubelet registration probe created" path="/var/lib/kubelet/plugins/unity.emc.dell.com/registration"
I0516 07:22:03.896542       1 main.go:120] Received NotifyRegistrationStatus call: &RegistrationStatus{PluginRegistered:true,Error:,}
phbo-dec commented 2 years ago

dell-csi-helm-installer values:

version: "v2.2.0"
logLevel: "debug"
certSecretCount: 1
imagePullPolicy: Always
kubeletConfigDir: /var/lib/kubelet

controller:
  controllerCount: 1
  volumeNamePrefix: csivol
  snapshot:
    enabled: false
    snapNamePrefix: csi-snap
  resizer:
    enabled: true

  nodeSelector:
  tolerations:

  healthMonitor:
    enabled: false
    interval: 60s

node:
  dnsPolicy: "ClusterFirstWithHostNet"
  healthMonitor:
    enabled: true

  nodeSelector:
  tolerations:

podmon:
  enabled: false
  image: dellemc/podmon:v1.1.0

syncNodeInfoInterval: 15
allowRWOMultiPodAccess: "false"
maxUnityVolumesPerNode: 0
tenantName: ""
images:
  driverRepository: dellemc
bandak2 commented 2 years ago

Hi @phbo-dec, We are looking into this. Could you please share the output of the kubectl version and kubectl get nodes -o wide command?

phbo-dec commented 2 years ago

Hi @bandak2, thanks for looking into this. Here are the details: 

dna@node1:~$ kubectl version
Client Version: version.Info{Major:"1", Minor:"23", GitVersion:"v1.23.6", GitCommit:"ad3338546da947756e8a88aa6822e9c11e7eac22", GitTreeState:"clean", BuildDate:"2022-04-14T08:49:13Z", GoVersion:"go1.17.9", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"23", GitVersion:"v1.23.6", GitCommit:"ad3338546da947756e8a88aa6822e9c11e7eac22", GitTreeState:"clean", BuildDate:"2022-04-14T08:43:11Z", GoVersion:"go1.17.9", Compiler:"gc", Platform:"linux/amd64"}

dna@node1:~$ kubectl get nodes -o wide
NAME    STATUS   ROLES                  AGE     VERSION   INTERNAL-IP      EXTERNAL-IP   OS-IMAGE             KERNEL-VERSION      CONTAINER-RUNTIME
node1   Ready    control-plane,master   3d23h   v1.24.0   192.168.90.150   <none>        Ubuntu 20.04.4 LTS   5.13.0-41-generic   containerd://1.6.4

to clarify, i used kubespray for the this setup (kubespray is also used for our production setup). I also tried a mikrok8s setup, this also failed with the same errors.

bandak2 commented 2 years ago

Hi @phbo-dec, Thanks for the requested info. From the output you shared above, the cluster version in the above output seems to be at v1.24.0. Could you please confirm if the apiserver, kubelet, and cluster version are at v1.23.x and less than v1.24.0? As of csi-unity v2.2.0 Kubernetes v1.24.0 is not in our support matrix.

Just for reference, there is an open issue that will be addressing the mounting issue observed on Kubernetes v1.24.0 clusters which are targeted towards csi-unity v2.3.0 release. https://github.com/dell/csm/issues/298

phbo-dec commented 2 years ago

hey @bandak2 i just reinstalled the everything from scratch again and verified that k8s is on version 1.23.6. StagingTargetPath are now shorter and everything is working fine.

Although i'm not sure how k8s v1.24.0 came to be, support is not a requirement for me right now. I will do some follow up tests, but from my point of view this issue can be resolved.

thanks alot and sorry for the confusion