VM backup failure

[giuliocasella]

• oVirt Engine: ovirt-engine-4.5.7-0.master.20240527152413.gited023e5e0a.el8.noarch
• Host OS Variant: oVirt Node 4.5.5
• VDSM version: vdsm-4.50.5.1-1.el8
• Additional relevant package versions:

Describe the bug

After upgrading engine to current version (before was: ovirt-engine-4.5.7-0.master.20240506114300.git0a1ba8203f.el8.noarch), every backup (either full or incremental) fails. Our backup system is Storware vProtect (unchanged in version and configuration). The snapshot part of backup process is executed (snapshot named "Auto-generated for Backup VM" is created, but remains after failure); something is going wrong in the database side (it seems the engine tries to insert backup in vm_backups table twice, and obviously complains about duplicated primary key). Find some relevant log below.

To reproduce

• Upgrade to ovirt-engine-4.5.7-0.master.20240527152413.gited023e5e0a.el8.noarch
• Start a VM backup (full or incremental)

Expected behavior

Backup is performed

Additional context

Snippet from engine.log:

2024-06-13 10:36:47,481+02 INFO [org.ovirt.engine.core.bll.storage.backup.HybridBackupCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Lock Acquired to object 'EngineLock:{exclusiveLocks='[09db7fdc-c4d3-4fbd-a50e-1b04de2b1341=DISK, 32f9b481-8431-4cbc-ad3e-bb226374e693=DISK]', sharedLocks=''}'
2024-06-13 10:36:47,535+02 INFO [org.ovirt.engine.core.bll.storage.backup.HybridBackupCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Running command: HybridBackupCommand internal: false. Entities affected : ID: dc6d9b23-e2f7-4744-a633-d4e532ef190f Type: VMAction group BACKUP_DISK with role type ADMIN, ID: 09db7fdc-c4d3-4fbd-a50e-1b04de2b1341 Type: DiskAction group BACKUP_DISK with role type ADMIN, ID: 32f9b481-8431-4cbc-ad3e-bb226374e693 Type: DiskAction group BACKUP_DISK with role type ADMIN
2024-06-13 10:36:47,541+02 INFO [org.ovirt.engine.core.bll.storage.backup.HybridBackupCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Created VmBackup entity 'd5bed8c5-f172-47c7-9827-5dda51490ee8' for VM 'dc6d9b23-e2f7-4744-a633-d4e532ef190f'
2024-06-13 10:36:47,596+02 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Lock Acquired to object 'EngineLock:{exclusiveLocks='[dc6d9b23-e2f7-4744-a633-d4e532ef190f=VM]', sharedLocks=''}'
2024-06-13 10:36:47,640+02 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Running command: CreateSnapshotForVmCommand internal: true. Entities affected : ID: dc6d9b23-e2f7-4744-a633-d4e532ef190f Type: VMAction group MANIPULATE_VM_SNAPSHOTS with role type USER
2024-06-13 10:36:47,668+02 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Running command: CreateSnapshotDiskCommand internal: true. Entities affected : ID: dc6d9b23-e2f7-4744-a633-d4e532ef190f Type: VMAction group MANIPULATE_VM_SNAPSHOTS with role type USER
2024-06-13 10:36:47,731+02 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Running command: CreateSnapshotCommand internal: true. Entities affected : ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2024-06-13 10:36:47,767+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='42135536-980b-4ea9-ab66-b850ed8c1f2b', ignoreFailoverLimit='false', storageDomainId='459011cf-ebb6-46ff-831d-8ccfafd82c8a', imageGroupId='32f9b481-8431-4cbc-ad3e-bb226374e693', imageSizeInBytes='107374182400', volumeFormat='COW', newImageId='754b091f-eaa9-4fd8-afbf-1caa0e747eb6', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='06289dbc-fc0a-4d7b-bd13-92a2df199971', sourceImageGroupId='32f9b481-8431-4cbc-ad3e-bb226374e693', shouldAddBitmaps='false', legal='true', sequenceNumber='1', bitmap='bf62fab5-fb82-4c03-ac60-ddb9943c9f0d'}), log id: 128fa930
2024-06-13 10:36:47,883+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] FINISH, CreateVolumeVDSCommand, return: 754b091f-eaa9-4fd8-afbf-1caa0e747eb6, log id: 128fa930
2024-06-13 10:36:47,895+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '43b174d8-3b84-46a3-abe6-e825e9ce7c81'
2024-06-13 10:36:47,896+02 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] CommandMultiAsyncTasks::attachTask: Attaching task '86720608-b5bd-4a28-b7ee-b1a3507592aa' to command '43b174d8-3b84-46a3-abe6-e825e9ce7c81'.
2024-06-13 10:36:47,918+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Adding task '86720608-b5bd-4a28-b7ee-b1a3507592aa' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet..
2024-06-13 10:36:47,947+02 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Running command: CreateSnapshotCommand internal: true. Entities affected : ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2024-06-13 10:36:47,963+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='42135536-980b-4ea9-ab66-b850ed8c1f2b', ignoreFailoverLimit='false', storageDomainId='459011cf-ebb6-46ff-831d-8ccfafd82c8a', imageGroupId='09db7fdc-c4d3-4fbd-a50e-1b04de2b1341', imageSizeInBytes='53687091200', volumeFormat='COW', newImageId='1407954a-6d41-4f01-928b-98afa8ef215f', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='5d65f77d-25fa-4879-8144-6147a16f3ae3', sourceImageGroupId='09db7fdc-c4d3-4fbd-a50e-1b04de2b1341', shouldAddBitmaps='false', legal='true', sequenceNumber='2', bitmap='bf62fab5-fb82-4c03-ac60-ddb9943c9f0d'}), log id: 5ce87935
2024-06-13 10:36:48,055+02 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] FINISH, CreateVolumeVDSCommand, return: 1407954a-6d41-4f01-928b-98afa8ef215f, log id: 5ce87935
2024-06-13 10:36:48,058+02 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'a3f817d8-ca15-4fff-a411-ac0294e2ea70'
2024-06-13 10:36:48,058+02 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] CommandMultiAsyncTasks::attachTask: Attaching task '60e6899b-f59f-404d-af8f-d2ef73e0c908' to command 'a3f817d8-ca15-4fff-a411-ac0294e2ea70'.
2024-06-13 10:36:48,067+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Adding task '60e6899b-f59f-404d-af8f-d2ef73e0c908' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet..
2024-06-13 10:36:48,080+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] BaseAsyncTask::startPollingTask: Starting to poll task '86720608-b5bd-4a28-b7ee-b1a3507592aa'.
2024-06-13 10:36:48,081+02 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] BaseAsyncTask::startPollingTask: Starting to poll t
ask '60e6899b-f59f-404d-af8f-d2ef73e0c908'.
2024-06-13 10:36:48,147+02 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] EVENT_ID: USER_CREATE_SNAPS
HOT(45), Snapshot 'Auto-generated for Backup VM' creation for VM 'mercurio' was initiated by admin@internal.
2024-06-13 10:36:48,151+02 ERROR [org.ovirt.engine.core.bll.storage.backup.HybridBackupCommand] (default task-8) [38c00ae1-a837-4758-85a9-ee9943395753] Command 'org.ovirt.engine.core.bll.
storage.backup.HybridBackupCommand' failed: CallableStatementCallback; SQL [{call insertvmbackup(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: duplicate key value violates unique constraint
"vm_backups_pkey"
Detail: Key (backup_id)=(d5bed8c5-f172-47c7-9827-5dda51490ee8) already exists.
Where: SQL statement "INSERT INTO vm_backups (
backup_id,
from_checkpoint_id,
to_checkpoint_id,
vm_id,
host_id,
phase,
_create_date,
_update_date,
description,
backup_type,
snapshot_id
)
VALUES (
v_backup_id,
v_from_checkpoint_id,
v_to_checkpoint_id,
v_vm_id,
v_host_id,
v_phase,
v__create_date,
v__update_date,
v_description,
v_backup_type,
v_snapshot_id
)"
PL/pgSQL function insertvmbackup(uuid,uuid,uuid,uuid,uuid,text,timestamp with time zone,timestamp with time zone,character varying,character varying,uuid) line 3 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "vm_backups_pkey"
Detail: Key (backup_id)=(d5bed8c5-f172-47c7-9827-5dda51490ee8) already exists.
Where: SQL statement "INSERT INTO vm_backups (
backup_id,
from_checkpoint_id,
to_checkpoint_id,
vm_id,
host_id,
phase,
_create_date,
_update_date,
description,
backup_type,
snapshot_id
)
VALUES (
v_backup_id,
v_from_checkpoint_id,
v_to_checkpoint_id,
v_vm_id,
v_host_id,
v_phase,
v__create_date,
v__update_date,
v_description,
v_backup_type,
v_snapshot_id
)"
PL/pgSQL function insertvmbackup(uuid,uuid,uuid,uuid,uuid,text,timestamp with time zone,timestamp with time zone,character varying,character varying,uuid) line 3 at SQL statement

[BrooklynDewolf]

This issue was fixed in #948. Can you try a more recent oVirt engine build?
The most recent build is: 4.5.7-0.master.20240610091440.git1043c13207

[giuliocasella]

My setup is based on CentOS 8 stream, latest build available is 4.5.7-0.master.20240527152413.gited023e5e0a.
If there's a chance to have (quite quickly) a newer build for CentOS 8 stream, I prefer to wait. If not, I have to migrate to CentOS 9 stream.

[BrooklynDewolf]

Unfortunately, CentOS 8 stream support was dropped in #947, as it is end of life (https://blog.centos.org/2023/04/end-dates-are-coming-for-centos-stream-8-and-centos-linux-7/).

It is recommended to upgrade to CentOS Stream 9.