longhorn: [BUG] Failure to create a volume on a retry since v1.1.1

Describe the bug We started upgrading our production clusters from v1.1.0 to v1.1.1 and found several issues. The root issue is timeouts (causing even a detach to last for tens of minutes) on CSI operations while and after undergoing the engine upgrades. We can’t pin the cause of this yet, but the timeouts uncovered another easily traceable issue.

When creating a new volume and the first attempt fails due to a timeout, the second attempt (as an automatic retry) fails in the CSI provisioner with the following error:

E0524 17:29:20.796731       1 controller.go:939] error syncing claim "63b55846-8795-41f6-8cbf-986a7a402ccf": failed to provision volume with StorageClass "longhorn-db": rpc error: code = AlreadyExists desc = CreateVolume: cannot change volume size from 109051904 to 107374183

It leads to a volume never reporting a successful provisioning even though it was created in Longhorn.

We managed to trace the logic and it happens due to volume size rounding in the CreateVolume function that never gets persisted to the original volume spec. So when a retry happens it finds the created volume through the LH API, but fails validation as the requested size differs (not rounded).

This should be easy to fix by rounding the size before trying to find it in LH.

Validation check: https://github.com/longhorn/longhorn-manager/blob/ac065a8deb96193ffec142bcc7e7345615b57b8d/csi/controller_server.go#L115-L119

Volume size rounding: https://github.com/longhorn/longhorn-manager/blob/ac065a8deb96193ffec142bcc7e7345615b57b8d/csi/controller_server.go#L192-L193

To Reproduce Steps to reproduce the behavior:

1. Create a new PV© with requested size that’s not a multiple of 2*1024*1024 (e.g. 107374183)
2. Make a first LH volume creation request fail somehow (in our case timeouts)
3. See the reported error that never goes away

Expected behavior The CSI operations should be retried with idempotency.

Log

W0524 17:29:20.796712       1 controller.go:916] Retrying syncing claim "63b55846-8795-41f6-8cbf-986a7a402ccf", failure 7                                                                                                                                                                                                    │
│ E0524 17:29:20.796731       1 controller.go:939] error syncing claim "63b55846-8795-41f6-8cbf-986a7a402ccf": failed to provision volume with StorageClass "longhorn-db": rpc error: code = AlreadyExists desc = CreateVolume: cannot change volume size from 109051904 to 107374183                                          │
│ I0524 17:29:20.796751       1 event.go:281] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"test-lh", UID:"63b55846-8795-41f6-8cbf-986a7a402ccf", APIVersion:"v1", ResourceVersion:"303698001", FieldPath:""}): type: 'Warning' reason: 'ProvisioningFailed' failed to provision volume wi │
│ I0524 17:31:28.799565       1 controller.go:562] CreateVolumeRequest {Name:pvc-63b55846-8795-41f6-8cbf-986a7a402ccf CapacityRange:required_bytes:107374183  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[numberOfReplicas:3 recurringJobs:[{"cron":"10 */12 * * *","n │
│ I0524 17:31:28.799649       1 event.go:281] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"default", Name:"test-lh", UID:"63b55846-8795-41f6-8cbf-986a7a402ccf", APIVersion:"v1", ResourceVersion:"303698001", FieldPath:""}): type: 'Normal' reason: 'Provisioning' External provisioner is provisioning │
│ I0524 17:31:28.799632       1 connection.go:183] GRPC request: {"capacity_range":{"required_bytes":107374183},"name":"pvc-63b55846-8795-41f6-8cbf-986a7a402ccf","parameters":{"numberOfReplicas":"3","recurringJobs":"[{\"cron\":\"10 */12 * * *\",\"name\":\"backup\",\"retain\":2,\"task\":\"backup\"}]","staleReplicaTime │
│ I0524 17:31:28.808656       1 controller.go:1051] Final error received, removing PVC 63b55846-8795-41f6-8cbf-986a7a402ccf from claims in progress

Environment:

• Longhorn version: 1.1.1
• Installation method (e.g. Rancher Catalog App/Helm/Kubectl): Rancher App
• Kubernetes distro (e.g. RKE/K3s/EKS/OpenShift) and version: EKS 1.17
  • Number of management node in the cluster: unknown
  • Number of worker node in the cluster: 25
• Node config
  • OS type and version: EKS-optimized Amazon Linux 2
  • CPU per node: varies
  • Memory per node: varies
  • Disk type(e.g. SSD/NVMe): NVMe
  • Network bandwidth between the nodes: varies
• Underlying Infrastructure (e.g. on AWS/GCE, EKS/GKE, VMWare/KVM, Baremetal): AWS
• Number of Longhorn volumes in the cluster: 400+

Additional context Although it’s an issue in itself, this wouldn’t be triggered without the timeouts, which are causing us significant issues (successfully getting a new PVC attached can take an hour) while upgrading the engines on production. This seems to come out of the scale as we couldn’t reproduce it on a much smaller scale staging clusters. It doesn’t seem to be related to the available resources as no OOM, throttling, iowaiting happens. The issue seems to temporarily resolve after rolling the longhorn-manager DaemonSet in the cluster. It even persists after stopping the engine upgrade. After the upgrade is complete it seems to work fine.

We’ll try to reproduce this in an isolated environment and report findings in a separate issue/Slack before upgrading the rest of our clusters.