3:37 a.m.
Hi all,
I use a custom python script for performing full and incremental backup on few hundreds
vms. I customized the example script in
https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/backup....
Everything was working fine, but starting from a few days ago, some vms starts to fail the
backup. I upgraded the engine (self-hosted) from 4.4.4 to 4.4.5 yesterday afternoon and
today most of the vms failed the incremental and full backup.
The error is triggered when trying to get the backp_service in the following function:
```
def backup_disk(disk, backups_service, from_checkpoint_id):
# We need to set an array because backups_service.add need it
disks = []
disks.append(disk)
add_error = False
try:
backup = backups_service.add(
types.Backup(
disks=disks,
from_checkpoint_id=from_checkpoint_id
)
)
except Exception as e:
exception = str(e)
logging.error("error on backups_service.add, set backup object to False.
Error: {} ".format(exception))
add_error = True
backup = False
if not add_error:
backup_service = backups_service.backup_service(backup.id)
logging.info("Backup phase: {}".format(backup.phase))
while backup.phase != types.BackupPhase.READY:
time.sleep(1)
try:
backup = backup_service.get()
except sdk.NotFoundError:
logging.error("backup_service NotFoundError, set backup object to
False")
backup = False
break
if backup and backup.to_checkpoint_id is not None:
logging.info("Created checkpoint
{}".format(backup.to_checkpoint_id))
return backup
```
Here's the error in the engine logs.
```
2021-04-21 11:31:21,750+02 INFO
[org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService]
(EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread
pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks.
2021-04-21 11:31:21,750+02 INFO
[org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService]
(EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread
pool 'engine' is using 0 threads out of 500, 50 threads waiting for tasks and 0
tasks in queue.
2021-04-21 11:31:21,750+02 INFO
[org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService]
(EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread
pool 'engineScheduledThreadPool' is using 2 threads out of 1, 98 threads waiting
for tasks.
2021-04-21 11:31:21,750+02 INFO
[org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService]
(EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread
pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads
waiting for tasks.
2021-04-21 11:31:21,750+02 INFO
[org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService]
(EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread
pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for
tasks.
2021-04-21 11:31:59,013+02 INFO [org.ovirt.engine.core.sso.service.AuthenticationService]
(default task-19) [] User admin@internal-authz with profile [internal] successfully logged
in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search
ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate
ovirt-ext=token:password-access
2021-04-21 11:31:59,124+02 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand]
(default task-19) [43d5f322] Running command: CreateUserSessionCommand internal: false.
2021-04-21 11:31:59,157+02 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-19)
[43d5f322] EVENT_ID: USER_VDC_LOGIN(30), User admin@internal-authz connecting from
'5.19.121.125' using session
'VN/aBJxvgcG1WBY9OQSjUnHL7HaSPhbLSX52inLiYFGG/gubMeZiv9Tu+3D4htqVwrb/kqlvMzBL3WAQXb+3Lg=='
logged in.
2021-04-21 11:31:59,534+02 WARN [org.ovirt.engine.api.restapi.util.LinkHelper] (default
task-19) [] Can't find relative path for class
"org.ovirt.engine.api.resource.StorageDomainVmDiskAttachmentsResource", will
return null
2021-04-21 11:31:59,535+02 WARN [org.ovirt.engine.api.restapi.util.LinkHelper] (default
task-19) [] Can't find relative path for class
"org.ovirt.engine.api.resource.StorageDomainVmDiskAttachmentsResource", will
return null
2021-04-21 11:32:00,670+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Lock Acquired to object
'EngineLock:{exclusiveLocks='[0ff73c3a-fb49-4148-a3b4-6ce790523a49=DISK]',
sharedLocks='[94ec9758-cfc1-41ba-ba71-e339d8df8cee=VM]'}'
2021-04-21 11:32:00,863+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: StartVmBackupCommand internal:
false. Entities affected : ID: 94ec9758-cfc1-41ba-ba71-e339d8df8cee Type: VMAction group
BACKUP_DISK with role type ADMIN, ID: 0ff73c3a-fb49-4148-a3b4-6ce790523a49 Type:
DiskAction group BACKUP_DISK with role type ADMIN
2021-04-21 11:32:00,863+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Creating VmBackup entity for VM
'94ec9758-cfc1-41ba-ba71-e339d8df8cee'
2021-04-21 11:32:00,956+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Created VmBackup entity
'ee02f949-ccb9-452f-a1bb-8e05d0684b0f'
2021-04-21 11:32:00,956+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Redefine previous VM checkpoints for VM
'94ec9758-cfc1-41ba-ba71-e339d8df8cee'
2021-04-21 11:32:01,316+02 INFO
[org.ovirt.engine.core.bll.storage.backup.RedefineVmCheckpointCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: RedefineVmCheckpointCommand
internal: true. Entities affected : ID: 94ec9758-cfc1-41ba-ba71-e339d8df8cee Type:
VMAction group BACKUP_DISK with role type ADMIN, ID: 0ff73c3a-fb49-4148-a3b4-6ce790523a49
Type: DiskAction group BACKUP_DISK with role type ADMIN
2021-04-21 11:32:01,318+02 INFO
[org.ovirt.engine.core.bll.storage.backup.RedefineVmCheckpointCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] No previous VM checkpoints found for VM
'94ec9758-cfc1-41ba-ba71-e339d8df8cee', skipping redefining VM checkpoints
2021-04-21 11:32:01,567+02 INFO
[org.ovirt.engine.core.bll.storage.backup.RedefineVmCheckpointCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Lock freed to object
'EngineLock:{exclusiveLocks='[0ff73c3a-fb49-4148-a3b4-6ce790523a49=DISK]',
sharedLocks='[94ec9758-cfc1-41ba-ba71-e339d8df8cee=VM]'}'
2021-04-21 11:32:01,567+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Successfully redefined previous VM checkpoints for
VM '94ec9758-cfc1-41ba-ba71-e339d8df8cee'
2021-04-21 11:32:01,567+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Creating VmCheckpoint entity for VM
'94ec9758-cfc1-41ba-ba71-e339d8df8cee'
2021-04-21 11:32:01,602+02 INFO
[org.ovirt.engine.core.bll.storage.backup.StartVmBackupCommand] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Created VmCheckpoint entity
'b67a0436-42fb-4715-a0a5-6bfd9cb09214'
2021-04-21 11:32:01,736+02 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-19)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] EVENT_ID: VM_BACKUP_STARTED(10,790), Backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f for VM vm1.cloudserver.tld started (User:
admin@internal-authz).
2021-04-21 11:32:03,789+02 INFO
[org.ovirt.engine.core.bll.storage.backup.CreateScratchDisksCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: CreateScratchDisksCommand
internal: true. Entities affected : ID: 94ec9758-cfc1-41ba-ba71-e339d8df8cee Type:
VMAction group BACKUP_DISK with role type ADMIN
2021-04-21 11:32:03,910+02 INFO
[org.ovirt.engine.core.bll.storage.backup.CreateScratchDiskCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: CreateScratchDiskCommand internal:
true. Entities affected : ID: 4f6d464e-531a-431a-bfcc-ca9dfd1d0c9a Type: StorageAction
group CREATE_DISK with role type USER
2021-04-21 11:32:03,910+02 INFO
[org.ovirt.engine.core.bll.storage.backup.CreateScratchDiskCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Creating scratch disk for disk ID
0ff73c3a-fb49-4148-a3b4-6ce790523a49
2021-04-21 11:32:03,977+02 INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: AddDiskCommand internal: true.
Entities affected : ID: 4f6d464e-531a-431a-bfcc-ca9dfd1d0c9a Type: StorageAction group
CREATE_DISK with role type USER
2021-04-21 11:32:04,038+02 INFO
[org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Running command: AddImageFromScratchCommand
internal: true. Entities affected : ID: 4f6d464e-531a-431a-bfcc-ca9dfd1d0c9a Type:
Storage
2021-04-21 11:32:04,109+02 WARN
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] EVENT_ID:
FAILED_TO_STORE_ENTIRE_DISK_FIELD_IN_DISK_DESCRIPTION_METADATA(1,026), Failed to store
field DiskDescription as a part of VM vm1.cloudserver.tld backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f scratch disk for vm1.cloudserver.tld-0's
description metadata due to storage space limitations. The field DiskDescription will be
truncated.
2021-04-21 11:32:04,111+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] START, CreateVolumeVDSCommand(
CreateVolumeVDSCommandParameters:{storagePoolId='0532fe8c-d841-49ae-9615-45a7b865f3e3',
ignoreFailoverLimit='false',
storageDomainId='4f6d464e-531a-431a-bfcc-ca9dfd1d0c9a',
imageGroupId='a419fb9b-486d-4a92-83d0-ef6c845ae5ba',
imageSizeInBytes='268435456000', volumeFormat='COW',
newImageId='0cbd890e-5bdc-4e8e-9e46-53bf5093cfd0', imageType='Sparse',
newImageDescription='{"DiskAlias":"VM vm1.cloudserver.tld backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f scratch disk for
vm1.cloudserver.tld-0","DiskDescription":"Backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f scratch di"}',
imageInitialSizeInBytes='0',
imageId='00000000-0000-0000-0000-000000000000',
sourceImageGroupId='00000000-0000-0000-0000-000000000000',
shouldAddBitmaps='false'}), log id: 34e22243
2021-04-21 11:32:04,137+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM
command CreateVolumeVDS failed: Invalid parameter: 'DiskType=SCRD'
2021-04-21 11:32:04,137+02 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Command 'CreateVolumeVDSCommand(
CreateVolumeVDSCommandParameters:{storagePoolId='0532fe8c-d841-49ae-9615-45a7b865f3e3',
ignoreFailoverLimit='false',
storageDomainId='4f6d464e-531a-431a-bfcc-ca9dfd1d0c9a',
imageGroupId='a419fb9b-486d-4a92-83d0-ef6c845ae5ba',
imageSizeInBytes='268435456000', volumeFormat='COW',
newImageId='0cbd890e-5bdc-4e8e-9e46-53bf5093cfd0', imageType='Sparse',
newImageDescription='{"DiskAlias":"VM vm1.cloudserver.tld backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f scratch disk for
vm1.cloudserver.tld-0","DiskDescription":"Backup
ee02f949-ccb9-452f-a1bb-8e05d0684b0f scratch di"}',
imageInitialSizeInBytes='0',
imageId='00000000-0000-0000-0000-000000000000',
sourceImageGroupId='00000000-0000-0000-0000-000000000000',
shouldAddBitmaps='false'})' execution failed: I
RSGenericException: IRSErrorException: Invalid parameter: 'DiskType=SCRD'
2021-04-21 11:32:04,137+02 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] FINISH, CreateVolumeVDSCommand, return:
00000000-0000-0000-0000-000000000000, log id: 34e22243
2021-04-21 11:32:04,137+02 ERROR
[org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Command
'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' failed:
EngineException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Invalid parameter: 'DiskType=SCRD' (Failed
with error InvalidParameterException and code 1000)
2021-04-21 11:32:04,170+02 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-94)
[21bb0fd3-06fe-49c8-95ec-94856edabc41] Removed task
'cb1f10fc-13e6-4ead-a33f-fad342a69ea2' from DataBase
```
Here's the SPM host vdsm logs:
```
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887, in
_run
return fn(*args, **kargs)
File "<decorator-gen-61>", line 2, in createVolume
File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 1510, in
createVolume
add_bitmaps=addBitmaps)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sd.py", line 1002, in
validateCreateVolumeParams
add_bitmaps=add_bitmaps)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sd.py", line 649, in
validateCreateVolumeParams
raise se.InvalidParameterException("DiskType", diskType)
vdsm.storage.exception.InvalidParameterException: Invalid parameter: 'DiskType=SCRD
```
It's a known bug in 4.4.4/4.4.5? Any suggestion?
If needed any other info lemme know, I'll provide you asap.
Thank you for your time
Francesco