search

hpe-storage / csi-driver

A Container Storage Interface (CSI) driver from HPE
https://scod.hpedev.io
Apache License 2.0
60 stars 55 forks source link

extremely slow provision rate #209

Open KpiHang opened 4 years ago

KpiHang commented 4 years ago

Hi,

my csi-driver are deployed successfully

$ kubectl -n kube-system get pods -A | grep -e 'cs[ip]'
kube-system   primera3par-csp-6c65cbfcc-mt5p6             1/1     Running    0          4h45m
kube-system   hpe-csi-controller-64d868c595-sf7k4         5/5     Running    0          4h45m
kube-system   hpe-csi-node-bm4kp                          2/2     Running    0          4h45m

storageclass

$ kubectl get storageclass
NAME                   PROVISIONER             RECLAIMPOLICY   VOLUMEBINDINGMODE      ALLOWVOLUMEEXPANSION   AGE
3par-sc                csi.hpe.com             Delete          Immediate              false                  5d21h

When I create one pvc using this storageclass，then mount the pvc onto a pod，it works. But when I create two or more pvcs in the same way, mount them, it doesn't work.

pvc & pv bound successfully

here are some logs:

pod events :

Events:
  Type     Reason              Age                    From                     Message
  ----     ------              ----                   ----                     -------
  Warning  FailedMount         19m (x5 over 85m)      kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0], unattached volumes=[pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0 host-dev vm-images default-token-w8q9x]: timed out waiting for the condition
  Warning  FailedMount         15m (x8 over 97m)      kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0], unattached volumes=[host-dev vm-images default-token-w8q9x pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0]: timed out waiting for the condition
  Warning  FailedAttachVolume  9m30s (x52 over 101m)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-6950d4e3-0eaf-4b14-905e-2129f7266371" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6950d4e3-0eaf-4b14-905e-2129f7266371:288023a9-6ad0-6663-6d61-737465720000
  Warning  FailedMount         8m44s (x18 over 99m)   kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0], unattached volumes=[vm-images default-token-w8q9x pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0 host-dev]: timed out waiting for the condition
  Warning  FailedAttachVolume  5m26s (x54 over 101m)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-5781d798-06c2-4b91-baf6-bd10785f37d7" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5781d798-06c2-4b91-baf6-bd10785f37d7:288023a9-6ad0-6663-6d61-737465720000
  Warning  FailedMount         4m10s (x4 over 53m)    kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-multi-pv2-0-d0 pvc-3par-sc-multi-pv2-0-d1], unattached volumes=[pvc-3par-sc-multi-pv2-0-d0 host-dev vm-images default-token-w8q9x pvc-3par-sc-multi-pv2-0-d1]: timed out waiting for the condition
  Warning  FailedMount         112s (x9 over 94m)     kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0], unattached volumes=[default-token-w8q9x pvc-3par-sc-multi-pv2-0-d1 pvc-3par-sc-multi-pv2-0-d0 host-dev vm-images]: timed out waiting for the condition

hpe-csi-driver logs:

time="2020-09-03T06:46:41Z" level=error msg="Failed to publish volume pvc-5781d798-06c2-4b91-baf6-bd10785f37d7, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-5781d798-06c2-4b91-baf6-bd10785f37d7/actions/publish: http: ContentLength=79 with Body length 0" file="controller_server.go:850"
time="2020-09-03T06:46:41Z" level=error msg="Error controller publishing volume pvc-5781d798-06c2-4b91-baf6-bd10785f37d7, err: rpc error: code = Internal desc = Failed to add ACL to volume pvc-5781d798-06c2-4b91-baf6-bd10785f37d7 for node &{ fcmaster 288023a9-6ad0-6663-6d61-737465720000 [0xc0006cc360] [0xc000232d00 0xc000232d10 0xc000232d20 0xc000232d30 0xc000232d40] [0xc00082b640 0xc00082b650]  } via CSP, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-5781d798-06c2-4b91-baf6-bd10785f37d7/actions/publish: http: ContentLength=79 with Body length 0" file="controller_server.go:709"
time="2020-09-03T06:46:41Z" level=error msg="GRPC error: rpc error: code = Internal desc = Failed to add ACL to volume pvc-5781d798-06c2-4b91-baf6-bd10785f37d7 for node &{ fcmaster 288023a9-6ad0-6663-6d61-737465720000 [0xc0006cc360] [0xc000232d00 0xc000232d10 0xc000232d20 0xc000232d30 0xc000232d40] [0xc00082b640 0xc00082b650]  } via CSP, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-5781d798-06c2-4b91-baf6-bd10785f37d7/actions/publish: http: ContentLength=79 with Body length 0" file="utils.go:73"
time="2020-09-03T06:46:42Z" level=error msg="Failed to publish volume pvc-6950d4e3-0eaf-4b14-905e-2129f7266371, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-6950d4e3-0eaf-4b14-905e-2129f7266371/actions/publish: http: ContentLength=79 with Body length 0" file="controller_server.go:850"
time="2020-09-03T06:46:42Z" level=error msg="Error controller publishing volume pvc-6950d4e3-0eaf-4b14-905e-2129f7266371, err: rpc error: code = Internal desc = Failed to add ACL to volume pvc-6950d4e3-0eaf-4b14-905e-2129f7266371 for node &{ fcmaster 288023a9-6ad0-6663-6d61-737465720000 [0xc0008743b0] [0xc0003a7b80 0xc0003a7b90 0xc0003a7ba0 0xc0003a7bb0 0xc0003a7bc0] [0xc0004348a0 0xc0004348b0]  } via CSP, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-6950d4e3-0eaf-4b14-905e-2129f7266371/actions/publish: http: ContentLength=79 with Body length 0" file="controller_server.go:709"
time="2020-09-03T06:46:42Z" level=error msg="GRPC error: rpc error: code = Internal desc = Failed to add ACL to volume pvc-6950d4e3-0eaf-4b14-905e-2129f7266371 for node &{ fcmaster 288023a9-6ad0-6663-6d61-737465720000 [0xc0008743b0] [0xc0003a7b80 0xc0003a7b90 0xc0003a7ba0 0xc0003a7bb0 0xc0003a7bc0] [0xc0004348a0 0xc0004348b0]  } via CSP, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-6950d4e3-0eaf-4b14-905e-2129f7266371/actions/publish: http: ContentLength=79 with Body length 0" file="utils.go:73"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-a33c358b-fbc5-4297-9871-406dd8d9ba32\"}" file="utils.go:70"
time="2020-09-03T06:47:13Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5d24afc3-c284-415b-89fa-fed1bdfabfb7\"}" file="utils.go:70"
time="2020-09-03T06:47:13Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:13Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-c53ea3a2-2df4-41ff-97f5-f00ff27b2ebf\"}" file="utils.go:70"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5781d798-06c2-4b91-baf6-bd10785f37d7\"}" file="utils.go:70"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:13Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-a33c358b-fbc5-4297-9871-406dd8d9ba32\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-a33c358b-fbc5-4297-9871-406dd8d9ba32:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5d24afc3-c284-415b-89fa-fed1bdfabfb7\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5d24afc3-c284-415b-89fa-fed1bdfabfb7:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-c53ea3a2-2df4-41ff-97f5-f00ff27b2ebf\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-c53ea3a2-2df4-41ff-97f5-f00ff27b2ebf:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5781d798-06c2-4b91-baf6-bd10785f37d7\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5781d798-06c2-4b91-baf6-bd10785f37d7:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6950d4e3-0eaf-4b14-905e-2129f7266371\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6950d4e3-0eaf-4b14-905e-2129f7266371:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:28Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-0be8d11a-19a9-405f-99a7-80313ee38173\"}" file="utils.go:70"
time="2020-09-03T06:47:28Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-0be8d11a-19a9-405f-99a7-80313ee38173:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:29Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:29Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:29Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:29Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:29Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5781d798-06c2-4b91-baf6-bd10785f37d7\"}" file="utils.go:70"
time="2020-09-03T06:47:29Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5781d798-06c2-4b91-baf6-bd10785f37d7:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:29Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:29Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746\"}" file="utils.go:70"
time="2020-09-03T06:47:29Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:29Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:29Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183\"}" file="utils.go:70"
time="2020-09-03T06:47:29Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:29Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:29Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd\"}" file="utils.go:70"
time="2020-09-03T06:47:29Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:30Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:30Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6950d4e3-0eaf-4b14-905e-2129f7266371\"}" file="utils.go:70"
time="2020-09-03T06:47:30Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6950d4e3-0eaf-4b14-905e-2129f7266371:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:30Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:30Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-0be8d11a-19a9-405f-99a7-80313ee38173\"}" file="utils.go:70"
time="2020-09-03T06:47:30Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-0be8d11a-19a9-405f-99a7-80313ee38173:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:30Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:30Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:30Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:30Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:30Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5781d798-06c2-4b91-baf6-bd10785f37d7\"}" file="utils.go:70"
time="2020-09-03T06:47:30Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5781d798-06c2-4b91-baf6-bd10785f37d7:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:30Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:30Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746\"}" file="utils.go:70"
time="2020-09-03T06:47:30Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:31Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:31Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183\"}" file="utils.go:70"
time="2020-09-03T06:47:31Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:31Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:31Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd\"}" file="utils.go:70"
time="2020-09-03T06:47:31Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:31Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:31Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6950d4e3-0eaf-4b14-905e-2129f7266371\"}" file="utils.go:70"
time="2020-09-03T06:47:31Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6950d4e3-0eaf-4b14-905e-2129f7266371:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:31Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:31Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-0be8d11a-19a9-405f-99a7-80313ee38173\"}" file="utils.go:70"
time="2020-09-03T06:47:31Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-0be8d11a-19a9-405f-99a7-80313ee38173:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:31Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:31Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:31Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:32Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-5781d798-06c2-4b91-baf6-bd10785f37d7\"}" file="utils.go:70"
time="2020-09-03T06:47:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-5781d798-06c2-4b91-baf6-bd10785f37d7:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:32Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746\"}" file="utils.go:70"
time="2020-09-03T06:47:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-22c7cf40-4338-4fe9-aec1-9ebcf8d13746:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:32Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183\"}" file="utils.go:70"
time="2020-09-03T06:47:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6a1b99c7-e0c3-44a5-bbbe-f50959638183:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:32Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd\"}" file="utils.go:70"
time="2020-09-03T06:47:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:32Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:32Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-6950d4e3-0eaf-4b14-905e-2129f7266371\"}" file="utils.go:70"
time="2020-09-03T06:47:32Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-6950d4e3-0eaf-4b14-905e-2129f7266371:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:33Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:33Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-0be8d11a-19a9-405f-99a7-80313ee38173\"}" file="utils.go:70"
time="2020-09-03T06:47:33Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-0be8d11a-19a9-405f-99a7-80313ee38173:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:33Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:33Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d\"}" file="utils.go:70"
time="2020-09-03T06:47:33Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-e7f3cb9d-e1e7-482c-bf7b-0d6dd898f86d:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:34Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
time="2020-09-03T06:47:34Z" level=info msg="GRPC request: {\"node_id\":\"288023a9-6ad0-6663-6d61-737465720000\",\"secrets\":\"***stripped***\",\"volume_capability\":{\"AccessType\":{\"Mount\":{\"fs_type\":\"ext4\"}},\"access_mode\":{\"mode\":1}},\"volume_context\":{\"accessProtocol\":\"iscsi\",\"cpg\":\"CPG_Raid6\",\"fsType\":\"ext4\",\"provisioningType\":\"full\",\"provisioning_type\":\"full\",\"storage.kubernetes.io/csiProvisionerIdentity\":\"1599097633503-8081-csi.hpe.com\",\"volumeAccessMode\":\"mount\"},\"volume_id\":\"pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd\"}" file="utils.go:70"
time="2020-09-03T06:47:34Z" level=error msg="GRPC error: rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f02ca42f-1aac-4f0f-b33f-11d36e3f5bfd:288023a9-6ad0-6663-6d61-737465720000" file="utils.go:73"
time="2020-09-03T06:47:34Z" level=info msg="GRPC call: /csi.v1.Controller/ControllerPublishVolume" file="utils.go:69"
wdurairaj commented 4 years ago

@hangees , can you collect the CSP logs of this pod primera3par-csp-6c65cbfcc-mt5p6 and attach here ?

The logs (if it's a plain k8s setup), it will be written on the node where the above pod (part of csp deployment) in /var/log /hpe-3par-primera-csp.log

Alternatively, you could file a support case also for this problem you are observing.. Please mention the

  1. Environment details
  2. Collect the node plugin logs (/var/log/hpe-csi-node.log) on the node where the pod mount is attempted..

On the array, are you seeing the following things

  1. host entry for the worker node of k8s
  2. vluns for the volume involved in PV of the pod (volume length on 3par will be truncated to 31 chars -- please note)

Thanks.

KpiHang commented 4 years ago

@wdurairaj Thanks for helping me

Because of the old logs was so big，i reappeared this bug.

I create 5 pods with pv created by hpe-csi storageclass，these files are the logs related.

hpe-3par-primera-csp.log hpe-csi-controller.log hpe-csi-node.log

host entry info:

SS8200-01 cli% showhost
Id Name     Persona       ------------WWN/iSCSI_Name------------ Port
 1 fcmaster Generic-ALUA  iqn.2016-04.com.open-iscsi:dd779986294 1:2:2
                          iqn.2016-04.com.open-iscsi:dd779986294 1:2:1
                          10000000C9D03876                       ---
                          10000000C9ADC715                       ---
 0 IMSVR1   WindowsServer 10000000C9B95FF0                       ---
                          10000000C9B95FFE                       ---

vluns:

SS8200-01 cli% showvlun
Active VLUNs
Lun VVName                          HostName ---------Host_WWN/iSCSI_Name----------  Port        Type Status ID
  0 pvc-e2eb4557-78ca-47e2-9689-f94 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  1 pvc-9cf6112c-ea09-45e0-8a88-e2a fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  2 pvc-a04c3e99-b419-441b-8b3b-fa2 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  3 pvc-3899eb8a-bdbb-4579-8c7e-2dc fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  4 pvc-59a245f4-da58-446d-8d82-108 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  5 pvc-0f479cb9-3568-4a40-8b51-c60 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  6 pvc-93c7a553-0907-4ac9-9e77-3af fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  7 pvc-3c3fc6b9-6293-4f48-8c77-fcf fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:1 matched set active  1
  0 pvc-e2eb4557-78ca-47e2-9689-f94 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  1 pvc-9cf6112c-ea09-45e0-8a88-e2a fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  2 pvc-a04c3e99-b419-441b-8b3b-fa2 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  3 pvc-3899eb8a-bdbb-4579-8c7e-2dc fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  4 pvc-59a245f4-da58-446d-8d82-108 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  5 pvc-0f479cb9-3568-4a40-8b51-c60 fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  6 pvc-93c7a553-0907-4ac9-9e77-3af fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
  7 pvc-3c3fc6b9-6293-4f48-8c77-fcf fcmaster iqn.2016-04.com.open-iscsi:dd779986294 1:2:2 matched set active  1
---------------------------------------------------------------------------------------------------------------
 16 total

VLUN Templates
Lun VVName                          HostName -Host_WWN/iSCSI_Name-  Port        Type
  0 pvc-e2eb4557-78ca-47e2-9689-f94 fcmaster ----------------      1:2:1 matched set
  1 pvc-9cf6112c-ea09-45e0-8a88-e2a fcmaster ----------------      1:2:1 matched set
  2 pvc-a04c3e99-b419-441b-8b3b-fa2 fcmaster ----------------      1:2:1 matched set
  3 pvc-3899eb8a-bdbb-4579-8c7e-2dc fcmaster ----------------      1:2:1 matched set
  4 pvc-59a245f4-da58-446d-8d82-108 fcmaster ----------------      1:2:1 matched set
  5 pvc-0f479cb9-3568-4a40-8b51-c60 fcmaster ----------------      1:2:1 matched set
  6 pvc-93c7a553-0907-4ac9-9e77-3af fcmaster ----------------      1:2:1 matched set
  7 pvc-3c3fc6b9-6293-4f48-8c77-fcf fcmaster ----------------      1:2:1 matched set
  0 pvc-e2eb4557-78ca-47e2-9689-f94 fcmaster ----------------      1:2:2 matched set
  1 pvc-9cf6112c-ea09-45e0-8a88-e2a fcmaster ----------------      1:2:2 matched set
  2 pvc-a04c3e99-b419-441b-8b3b-fa2 fcmaster ----------------      1:2:2 matched set
  3 pvc-3899eb8a-bdbb-4579-8c7e-2dc fcmaster ----------------      1:2:2 matched set
  4 pvc-59a245f4-da58-446d-8d82-108 fcmaster ----------------      1:2:2 matched set
  5 pvc-0f479cb9-3568-4a40-8b51-c60 fcmaster ----------------      1:2:2 matched set
  6 pvc-93c7a553-0907-4ac9-9e77-3af fcmaster ----------------      1:2:2 matched set
  7 pvc-3c3fc6b9-6293-4f48-8c77-fcf fcmaster ----------------      1:2:2 matched set
------------------------------------------------------------------------------------
 16 total
wdurairaj commented 4 years ago

I see at multiple places in the CSP rest call to the array, "system is busy" message

ime="2020-09-03T09:24:16Z" level=trace msg="Header: {X-HP3PAR-WSAPI-SessionKey : *****}\n" file="utils.go:31"
time="2020-09-03T09:24:16Z" level=trace msg="Header: {Content-type : application/json}\n" file="utils.go:33"
time="2020-09-03T09:24:19Z" level=info msg="Request: action=POST path=https://172.29.1.10:8080/api/v1/vluns" file="http.go:106"
time="2020-09-03T09:24:19Z" level=info msg="HTTP Response: {\n    \"code\": 270,\n    \"desc\": \" System is too busy. Please try again later\"\n }" file="utils.go:47"
time="2020-09-03T09:24:19Z" level=info msg="Response status 503 Service Unavailable" file="rest_client.go:30"
time="2020-09-03T09:24:19Z" level=info msg="Response status and status code of POST on vluns is: 503 Service Unavailable 503" file="client.go:122"
time="2020-09-03T09:24:19Z" level=info msg="Create response status: 503 Service Unavailable" file="client.go:131"
time="2020-09-03T09:24:19Z" level=error msg="[ REQUEST-ID 102309 ] -- Error creating VLUN models.CreateVLUNRequest{VolName:\"pvc-93c7a553-0907-4ac9-9e77-3af\", LunID:0, HostName:\"fcmaster\", PortPos:models.PortPos{Node:1, Slot:2, CardPort:1}, NoVcn:false, OverrideLowerPriority:false, AutoLun:true, MaxAutoLun:0}, error is 503 Service Unavailable" file="publish_volume_cmd.go:295"
time="2020-09-03T09:24:19Z" level=error msg="[ REQUEST-ID 102309 ] -- Error while creating LUN associated with volume pvc-93c7a553-0907-4ac9-9e77-3af and error is 503 Service Unavailable" file="publish_volume_cmd.go:296"
time="2020-09-03T09:24:19Z" level=error msg="Error from backend  503 Service Unavailable" file="utils.go:52"
time="2020-09-03T09:24:19Z" level=error msg="Error response to be sent is models.ErrorsPayload{Errors:[]models.ErrorObject{models.ErrorObject{Code:\"Service Unavailable\", Message:\"HTTP error response from backend models.ErrorStruct{Code:270, Description:\\\" System is too busy. Please try again later\\\", Ref:\\\"\\\"}\"}}}" file="utils.go:62"
KpiHang commented 4 years ago

it is a 3par 8200. It is almost idle, nobody else is using it. How many volumes can such a system provision per minute?

wdurairaj commented 4 years ago

Log lines 

ime="2020-09-03T09:24:19Z" level=info msg="Request: action=POST path=https://172.29.1.10:8080/api/v1/vluns" file="http.go:106"
time="2020-09-03T09:24:19Z" level=info msg="HTTP Response: {\n    \"code\": 270,\n    \"desc\": \" System is too busy. Please try again later\"\n }" file="utils.go:47"
time="2020-09-03T09:24:19Z" level=info msg="Response status 503 Service Unavailable" file="rest_client.go:30"
tim

there was a failure in processing REST call from the CSP pod to array during that moment of time. Please raise 3PAR support case to understand why it happens (or) it could be a networking problem at your end.

KpiHang commented 4 years ago

Now we have the only problem is that we can't create multiple pv at the same time.

i create 5 pvs by pvc used storageclass：

apiVersion: storage.k8s.io/v1
kind: StorageClass
metadata:
  name: 3par-sc
provisioner: csi.hpe.com
parameters:
  csi.storage.k8s.io/fstype: ext4
  csi.storage.k8s.io/provisioner-secret-name: primera3par-secret
  csi.storage.k8s.io/provisioner-secret-namespace: kube-system
  csi.storage.k8s.io/controller-publish-secret-name: primera3par-secret
  csi.storage.k8s.io/controller-publish-secret-namespace: kube-system
  csi.storage.k8s.io/node-publish-secret-name: primera3par-secret
  csi.storage.k8s.io/node-publish-secret-namespace: kube-system
  csi.storage.k8s.io/node-stage-secret-name: primera3par-secret
  csi.storage.k8s.io/node-stage-secret-namespace: kube-system
  # Uncomment for k8s 1.15 for resize support
  csi.storage.k8s.io/controller-expand-secret-name: primera3par-secret
  csi.storage.k8s.io/controller-expand-secret-namespace: kube-system
  cpg: CPG_Raid6
  provisioning_type: tpvv
  accessProtocol: iscsi

image it seems that creating pvs is successfully, but

when i used the pvs, something went wrong:

$ kubectl describe pods -n test testn-0
......
Events:
  Type     Reason              Age                  From                     Message
  ----     ------              ----                 ----                     -------
  Warning  FailedScheduling    <unknown>            default-scheduler        running "VolumeBinding" filter plugin for pod "testn-0": pod has unbound immediate PersistentVolumeClaims
  Normal   Scheduled           <unknown>            default-scheduler        Successfully assigned test/testn-0 to fcmaster
  Warning  FailedScheduling    <unknown>            default-scheduler        running "VolumeBinding" filter plugin for pod "testn-0": pod has unbound immediate PersistentVolumeClaims
  Warning  FailedAttachVolume  23m                  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-f5b94c3f-8820-44ed-aa11-40d291765439" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
  Warning  FailedMount         10m                  kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-testn-0-d0], unattached volumes=[pvc-3par-sc-testn-0-d0 host-dev vm-images default-token-w8q9x]: timed out waiting for the condition
  Warning  FailedMount         3m49s (x4 over 19m)  kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-testn-0-d0], unattached volumes=[host-dev vm-images default-token-w8q9x pvc-3par-sc-testn-0-d0]: timed out waiting for the condition
  Warning  FailedMount         91s (x5 over 22m)    kubelet, fcmaster        Unable to attach or mount volumes: unmounted volumes=[pvc-3par-sc-testn-0-d0], unattached volumes=[vm-images default-token-w8q9x pvc-3par-sc-testn-0-d0 host-dev]: timed out waiting for the condition
  Warning  FailedAttachVolume  83s (x18 over 23m)   attachdetach-controller  AttachVolume.Attach failed for volume "pvc-f5b94c3f-8820-44ed-aa11-40d291765439" : rpc error: code = Aborted desc = There is already an operation pending for the specified id ControllerPublishVolume:pvc-f5b94c3f-8820-44ed-aa11-40d291765439:288023a9-6ad0-6663-6d61-737465720000

I think it is a extremely serious problem. The pv doesn't mount to a pod for several hours.

However, creating only one pv at the same time, the process takes only a few seconds.

storm1kk commented 3 years ago

Hello all,

We're having exactly the same issue. Provision time could reach 30 to 40 min. Any advice on it?

HPE driver version - 1.30

Logs example:

csi_attacher.go:624] kubernetes.io/csi: attachment for pvc-3d7494d2-5a94-46bb-ad61-f19631911adb failed: rpc error: code = Internal desc = Failed to add ACL to volume pvc-3d7494d2-5a94-46bb-ad61-f19631911adb for node &{ endurancew40 0242ba4d-8375-656e-6475-72616e636577 [0xc00109a330] [0xc0004e90c0 0xc0004e90d0 0xc0004e90e0 0xc0004e90f0] [0xc0006ab8a0 0xc0006ab8b0] } via CSP, err: Put http://primera3par-csp-svc:8080/containers/v1/volumes/pvc-3d7494d2-5a94-46bb-ad61-f19631911adb/actions/publish: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

wdurairaj commented 3 years ago

Some customer of ours faced this problem and it's related to the volume attacher's bug

https://github.com/kubernetes/kubernetes/pull/91307

Anil-YadavK8s commented 3 years ago

Hello All,

We are facing the same issue with HPE CSI 1.3.0 with HPE backed 3par /Primera.

Any solution to the issue?

Thanks, Anil

wdurairaj commented 3 years ago

actually there are 3 issues around k8s slow provisioning as documented here

https://github.com/kubernetes/kubernetes/issues/86281 https://github.com/kubernetes/kubernetes/issues/84169 https://github.com/kubernetes/kubernetes/pull/91307