CreateVolume times out and controller gets stuck in already exists loop

[damomurf]

Thanks for your work on this!

I think the provisioning of my LUN/Target is taking longer than some hard-coded 10 second timeout.

Once the timeout occurs, the controller continues trying to create the same objects on the Synology, but constantly just receives the already exists error.

I feel like there should be better handling of the timeout case and would it be possible to make the timeout interval configurable?

I1205 22:21:38.562909       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"prometheus-prometheus-operator-prometheus-db-prometheus-prometheus-operator-prometheus-0", UID:"f3621cf5-893e-4c33-a920-863d0713df96", APIVersion:"v1", ResourceVersion:"63903", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning volume for claim "default/prometheus-prometheus-operator-prometheus-db-prometheus-prometheus-operator-prometheus-0"
I1205 22:21:38.562324       1 controller.go:122] GRPC request: 
I1205 22:21:38.568163       1 controller.go:124] GRPC response: capabilities:<service:<type:CONTROLLER_SERVICE > > 
I1205 22:21:38.568361       1 controller.go:125] GRPC error: <nil>
I1205 22:21:38.568416       1 controller.go:121] GRPC call: /csi.v1.Controller/ControllerGetCapabilities
I1205 22:21:38.568433       1 controller.go:122] GRPC request: 
I1205 22:21:38.570195       1 controller.go:124] GRPC response: capabilities:<rpc:<type:LIST_VOLUMES > > capabilities:<rpc:<type:CREATE_DELETE_VOLUME > > capabilities:<rpc:<type:PUBLISH_UNPUBLISH_VOLUME > > 
I1205 22:21:38.570474       1 controller.go:125] GRPC error: <nil>
I1205 22:21:38.570988       1 controller.go:121] GRPC call: /csi.v1.Identity/GetPluginInfo
I1205 22:21:38.571049       1 controller.go:122] GRPC request: 
I1205 22:21:38.573108       1 controller.go:124] GRPC response: name:"csi.synology.com" vendor_version:"0.1.0" 
I1205 22:21:38.573209       1 controller.go:125] GRPC error: <nil>
I1205 22:21:38.573255       1 controller.go:447] CreateVolumeRequest {Name:pvc-f3621cf5-893e-4c33-a920-863d0713df96 CapacityRange:required_bytes:53687091200  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I1205 22:21:38.573742       1 controller.go:121] GRPC call: /csi.v1.Controller/CreateVolume
I1205 22:21:38.573773       1 controller.go:122] GRPC request: name:"pvc-f3621cf5-893e-4c33-a920-863d0713df96" capacity_range:<required_bytes:53687091200 > volume_capabilities:<mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > > 
I1205 22:21:48.573869       1 controller.go:124] GRPC response: 
I1205 22:21:48.574026       1 controller.go:125] GRPC error: rpc error: code = DeadlineExceeded desc = context deadline exceeded
W1205 22:21:48.574065       1 controller.go:490] CreateVolume timeout: 10s has expired, operation will be retried
I1205 22:21:53.574593       1 controller.go:121] GRPC call: /csi.v1.Controller/CreateVolume
I1205 22:21:53.574661       1 controller.go:122] GRPC request: name:"pvc-f3621cf5-893e-4c33-a920-863d0713df96" capacity_range:<required_bytes:53687091200 > volume_capabilities:<mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > > 
I1205 22:21:55.412035       1 controller.go:124] GRPC response: 
I1205 22:21:55.412223       1 controller.go:125] GRPC error: rpc error: code = AlreadyExists desc = Volume pvc-f3621cf5-893e-4c33-a920-863d0713df96 already exists, found LUN kube-csi-pvc-f3621cf5-893e-4c33-a920-863d0713df96
W1205 22:21:55.412489       1 controller.go:686] Retrying syncing claim "default/prometheus-prometheus-operator-prometheus-db-prometheus-prometheus-operator-prometheus-0" because failures 0 < threshold 15
E1205 22:21:55.412849       1 controller.go:701] error syncing claim "default/prometheus-prometheus-operator-prometheus-db-prometheus-prometheus-operator-prometheus-0": failed to provision volume with StorageClass "synology-iscsi-storage": rpc error: code = AlreadyExists desc = Volume pvc-f3621cf5-893e-4c33-a920-863d0713df96 already exists, found LUN kube-csi-pvc-f3621cf5-893e-4c33-a920-863d0713df96
I1205 22:21:55.414065       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"prometheus-prometheus-operator-prometheus-db-prometheus-prometheus-operator-prometheus-0", UID:"f3621cf5-893e-4c33-a920-863d0713df96", APIVersion:"v1", ResourceVersion:"63903", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' failed to provision volume with StorageClass "synology-iscsi-storage": rpc error: code = AlreadyExists desc = Volume pvc-f3621cf5-893e-4c33-a920-863d0713df96 already exists, found LUN kube-csi-pvc-f3621cf5-893e-4c33-a920-863d0713df96```

[damomurf]

Seems like it's probably related to this: kubernetes-csi/external-provisioner#131

[jparklab]

@damomurf thanks for reporting it, and details about the issue. It really helps to find what to update.
Error handling is definitely something needs to be improved.(that's one of the reasons why I don't recommend using this driver for any production use...)

It should be an easy fix. I'll post a comment when the driver is updated.

(also, sorry for late response, somewhat notification is not working.. I didn't get any email from github..)

[jparklab]

@damomurf I've updated the code & docker image. Please try with the new docker image, and let me know if it still does not work for you.