Background
I recently ran into a strange issue in my home lab, running ESXi 7.0.2, build 17867351 where Veeam Backup & Replication v10 reported the following error:
Veeam Backup & Replication Log entries
16.05.2021 17:34:50 :: Failed to create VM snapshot. Error: CreateSnapshot failed, vmRef vm-4013, timeout 1800000, snName VEEAM BACKUP TEMPORARY SNAPSHOT, snDescription Please do not delete this snapshot. It is being used by Veeam Backup., memory False, quiesce False
The same error could also be seen in vCenter:
vCenter Log entries
16.05.2021 17:34:56 :: Error: An error occurred while saving the snapshot: msg.changetracker.MIRRORCOPYSTATUS.
Findings
The same issue arrises when manually creating a snapshot in vCenter, so it does not seem to be Veeam Backup & Replication specific.
A quick look into vmware.log for the affected VM:
Full vmware.log for the affected VM
2021-05-16T15:38:49.395Z| vmx| | I005: VigorTransportProcessClientPayload: opID=knxctxhk-242836-auto-57dh-h5:70044488-3a-9f-6432 seq=54938: Receiving Snapshot.Take request.
2021-05-16T15:38:49.397Z| vmx| | I005: SnapshotVMX_TakeSnapshot start: 'VM Snapshot 16%2f05%2f2021, 17:38:44', deviceState=0, lazy=0, quiesced=1, forceNative=0, tryNative=1, saveAllocMaps=0
2021-05-16T15:38:49.665Z| vmx| | I005: DISKLIB-LIB_CREATE : DiskLibCreateCreateParam: vmfsSparse grain size is set to 1 for '/vmfs/volumes/vsan:52b2da12ab7803d1-77d0a7d9896eb6ac/80f04160-c378-5f8b-871e-a4ae111c7980/idmc-01-000001.vmdk'
2021-05-16T15:38:49.852Z| vmx| | I005: DISKLIB-CBT :ChangeTrackerESX_CreateMirror: Created mirror node /vmfs/devices/svm/6d1716-25d0ef6-cbtmirror.
2021-05-16T15:38:49.953Z| vmx| | W003: DISKLIB-CBT : ChangeTrackerESX_GetMirrorCopyProgress: Failed to copy mirror: Lost previously held disk lock
2021-05-16T15:38:49.953Z| vmx| | I005: DISKLIB-LIB_BLOCKTRACK : DiskLibBlockTrackMirrorProgress: Failed to get mirror status of block track info file /vmfs/volumes/vsan:52b2da12ab7803d1-77d0a7d9896eb6ac/80f04160-c378-5f8b-871e-a4ae111c7980/idmc-01-ctk.vmdk.
2021-05-16T15:38:49.953Z| vmx| | I005: DISKLIB-CBT :ChangeTrackerESX_DestroyMirror: Destroyed mirror node 6d1716-25d0ef6-cbtmirror.
2021-05-16T15:38:49.976Z| vmx| | I005: SNAPSHOT: SnapshotPrepareTakeDoneCB: Failed to prepare block track.
2021-05-16T15:38:49.976Z| vmx| | I005: SNAPSHOT: SnapshotPrepareTakeDoneCB: Prepare phase complete (Could not get mirror copy status).
2021-05-16T15:38:49.976Z| vmx| | I005: SnapshotVMXPrepareTakeDoneCB: Prepare phase failed: Could not get mirror copy status (5).
2021-05-16T15:38:49.976Z| vmx| | I005: SnapshotVMXTakeSnapshotComplete: Done with snapshot 'VM Snapshot 16%2f05%2f2021, 17:38:44': 0
2021-05-16T15:38:49.977Z| vmx| | I005: SnapshotVMXTakeSnapshotComplete: Snapshot 0 failed: Could not get mirror copy status (5).
2021-05-16T15:38:49.977Z| vmx| | I005: VigorTransport_ServerSendResponse opID=knxctxhk-242836-auto-57dh-h5:70044488-3a-9f-6432 seq=54938: Completed Snapshot request with messages.
And there I found the locking issue:
"Failed to copy mirror: Lost previously held disk lock"
2021-05-16T15:38:49.953Z| vmx| | W003: DISKLIB-CBT : ChangeTrackerESX_GetMirrorCopyProgress: Failed to copy mirror: Lost previously held disk lock
Workaround
Since the lock is held locally by the ESXi host, I just did a vMotion of the VM (to another host in my cluster), to clear the lock and re-issue it by another host. After completing a vMotion of the affected VM, it now completed successfully (and backup is now working again). My lab is running vSAN, so this does not seem related to VMware KB 2107795: Troubleshooting issues resulting from locked virtual disks.
The root cause of the issue is still unknown, but a vMotion cleared the lock and backups have now been running successfully for a few days since the original issue appeared. Hopefully it stays that way!