11:36 a.m.
Hi,
yesterday we upgraded engine:
ovirt-engine-4.5.7-0.master.20240506114300.git0a1ba8203f.el8.noarch ->
ovirt-engine-4.5.7-0.master.20240527152413.gited023e5e0a.el8.noarch
Since then our backups (made by Storware backup and recovery, vprotect)
are failing.
It seems that engine tries to add backup twice, and db primary key
constraint obviously fails. Find below a snippet from engine.log.
The snapshot part of backup process is executed correctly (but snapshot
named "Auto-generated for Backup VM" remains after failure).
Also script
/usr/share/doc/python3-ovirt-engine-sdk4/examples/backup_vm.py fails to
finalize/terminate backup.
Has anyone seen this and filed a bug on github?
------------------------------------------------------
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
------------------------------------------------------
Thanks in advance,
Giulio