PV stuck in unattached state

[heilerich]

/kind bug

What happened:

A PersistentVolume is permanently stuck in an unattached state. The vsphere-csi regularly tries to attach the volume to a node, but fails receiving The operation is not allowed in the current state from vCenter. This error also shows up in the vSphere UI as a failing a Task: Attach a virtual disk on the node's event view.

The error first occurred without human intervention, so I can only make assumptions about the cause, but I think the event that triggered this error was a scaling operation by the cluster autoscaler which removed some nodes from the cluster. The pods successfully moved to other nodes, just this one PV is stuck since then.

Controller Logs

vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.878480       1 controller.go:208] Started VA processing "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.878566       1 csi_handler.go:221] CSIHandler: processing VA "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.878628       1 csi_handler.go:248] Attaching "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.878647       1 csi_handler.go:427] Starting attach operation for "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.878965       1 csi_handler.go:341] PV finalizer is already set on "pvc-d9969e2d-2cb7-431b-92b9-638aada364c1"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.879022       1 csi_handler.go:746] Found NodeID master-cp-2 in CSINode master-cp-2
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.879184       1 csi_handler.go:301] VA finalizer is already set on "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:48.879354       1 csi_handler.go:315] NodeID annotation is already set on "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:49.383722       1 csi_handler.go:597] Saving attach error to "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:49.393852       1 csi_handler.go:608] Saved attach error to "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:49.393898       1 csi_handler.go:231] Error processing "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b": failed to attach: rpc error: code = Internal desc = failed to attach disk: "dcd49689-504d-44b4-bd31-f22fe61ed16e" with node: "master-cp-2" err failed to attach cns volume: "dcd49689-504d-44b4-bd31-f22fe61ed16e" to node vm: "VirtualMachine:vm-1273030 [VirtualCenterHost: ukl-vcenter, UUID: 422f5fda-42d7-9fb8-f293-043322658f59, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: ukl-vcenter]]". fault: "(*types.LocalizedMethodFault)(0xc00108ffa0)({\n DynamicData: (types.DynamicData) {\n },\n Fault: (*types.InvalidState)(0xc00108ffc0)({\n  VimFault: (types.VimFault) {\n   MethodFault: (types.MethodFault) {\n    FaultCause: (*types.LocalizedMethodFault)(<nil>),\n    FaultMessage: ([]types.LocalizableMessage) <nil>\n   }\n  }\n }),\n LocalizedMessage: (string) (len=50) \"The operation is not allowed in the current state.\"\n})\n". opId: "057fca83"
vmware-system-csi/vsphere-csi-controller-55cfb8d97c-5knhd[csi-attacher]: I0221 16:29:49.394759       1 controller.go:165] Ignoring VolumeAttachment "csi-26543a1fadc21d76c122905992fcaa933b5bf0d94b75392cd64a61787a3d7a3b" change

What you expected to happen:

Since the volume shows up in vSphere UI as ready and unattached, the volume attachment should be successful.

How to reproduce it (as minimally and precisely as possible):

Unfortunately, no idea.

Environment:

• csi-vsphere version: v2.4.1
• vsphere-cloud-controller-manager version: v1.21.0
• Kubernetes version: v1.21.9
• vSphere version: v7.0u2d
• OS (e.g. from /etc/os-release): Flatcar Linux 3033.2.2 (stable)
• Kernel (e.g. uname -a): Linux 5.10.96

Other than investigating the cause of this error I would also greatly appreciate any ideas on how to rescue the stuck volume. Thanks :)

[heilerich]

Further investigation suggests that the problem is some kind of race condition between the volume detachment process and the deletion of the node's Virtual Machine. This leaves the CNS Volumes in some broken state where the CSI driver cannot re-attach them.

Since the volumes show up in vSphere UI as unattached and ready, but vCenter still refuses to attach them to a VM, I think this might actually be a bug in vSphere CNS rather than the CSI driver.

I think the problem is related to this issue kubermatic/machine-controller#1189
The problem seems to be slightly different because the author of that issue is getting stale VolumeAttachment objects.

[tgelter]

Further investigation suggests that the problem is some kind of race condition between the volume detachment process and the deletion of the node's Virtual Machine. This leaves the CNS Volumes in some broken state where the CSI driver cannot re-attach them.

Since the volumes show up in vSphere UI as unattached and ready, but vCenter still refuses to attach them to a VM, I think this might actually be a bug in vSphere CNS rather than the CSI driver.

I think the problem is related to this issue kubermatic/machine-controller#1189 The problem seems to be slightly different because the author of that issue is getting stale VolumeAttachment objects.

This issue is likely a duplicate of #359.

[tgelter]

Other than investigating the cause of this error I would also greatly appreciate any ideas on how to rescue the stuck volume. Thanks :)

We've run into this issue before and have had luck with this process:

1. Determine which Node holds a VolumeAttachment but is no longer present in the cluster.

❯ for node in $(kubectl get volumeattachments --no-headers | awk '{print $4}'); do kubectl get no $node >/dev/null; done
Error from server (NotFound): nodes "<internal_node_name_redacted>" not found

2. Check to see if the VM object still exists (we use automation which compares Nodes known to Kubernetes to those known to vCenter and our internal CMDB to determine if any orphaned VMs exist).
3. If the VM object does not exist, it's safe to delete the VolumeAttachment matching the Node name, but existing internal automation now largely avoids this potentially dangerous operation.
4. If the VM object still exists, it should be brought back into Kubernetes. This is most easily accomplished by rebooting the Node.
5. At this point, the subsequent volume attachment attempt should succeed. If the user would like to speed up the process, they may consider deleting the Pod in question. This assumes the Pod in question is managed by some sort of workload resource.

[heilerich]

I agree that the linked issue seems quite similar. The event that triggers the issue is probably the same (i.e. node removal before the volume detachment process is 100% complete).

There are some slight differences though

• The CSI logs in the linked issue complain about a missing node. The logs in our case complain about vCenter refusing to attach the CNS Volume (i.e. The operation is not allowed in the current state)
• The problem in the linked issues seem to involve stale VolumeAttachment objects. In our case all the VolumeAttachment objects are successfully removed.

So in respect to your proposed rescue process this means

1. There are no old VolumeAttachment, just the new ones created for the (existing) nodes where the pods were moved.
2. The old VMs are gone from vCenter. The nodes referenced by the new (failing) VolumeAttachments are online and fully operational.
3. No VolumeAttachment :(
4. ...

I think the difference in the underlying issue might be the following:

The problem causing #359 seems to be that the VM is deleted before the CSI is done processing the VolumeAttachment. A stale VolumeAttachment is the result.

The problem in our case is probably more akin to: The CSI deletes the VolumeAttachment before vSphere CNS is done processing the detachment operation. Since all VolumeAttachments and Pods are gone, the Node object and the VM is (rightfully) deleted. The volume object in vSphere CNS stays in some undefined state where it cannot be re-attached.

[ThoSap]

Probably related to #1416 but in our case, we also did not delete any node from the k8s cluster.
This just happens randomly 😭

[heilerich]

We also started experiencing this issue without the deletion of any nodes. It is now also (sometimes) happening simply when a volume is re-mounted (i.e. when a pod is re-created). We are in contact with vmware support to further investigate the issue.

We are also seeing more evidence that this issue is not a bug in vsphere-csi but ESXi/vSphere/CNS. Specifically, we noticed that the disks belonging to the container volumes can also not be mounted manually in vSphere anymore. So for now it seems like vsphere-csi is simply accurately reporting the errors happening in the underlying infrastructure.

Although, the question, what the root cause of the "locking" of the virtual disks might be, remains unanswered.

[ThoSap]

See #1416 (comment)

[heilerich]

Thanks for the update. In the meantime we had also figured out, that this error was caused by the Changed Block Tracking feature. However, in our case, it was the other way around: CBT is disabled by default on our machines and was enabled by accident on one of the worker machines. That worker started 'tainting' every volume that was attached to it with the CBT feature flag. After that these 'tainted' volumes were lost for all other nodes in the cluster. So the solution was to remove the node with the activated CBT and replace the virtual disks.

[fabiorauber]

I had a similar issue @heilerich, but in my case the CBT feature was being activated by a backup solution for VMs, used by another team. Took me a good while to figure it out. Since I didn't find a way to disable it for a single volume, I enabled CBT for all worker VMs with a Powershell script, made sure all CNS volumes were attached to these VMs, and then disabled CBT for all worker VMs again, so that the volumes were set back to CBT disabled.

[heilerich]

@fabiorauber thanks for the tip! I will try this should I ever encounter this problem again.

Backup software seems to be the most likely culprit in this case. It was exactly the same situation for us: A backup solution backing up VMs it was not supposed to touch.