[ovirt-users] Fail to attach/create disk from template when running via Ansible

Dear oVirt, Just recently, I have upgraded oVirt staging environment from 4.3.4 to 4.3.6 release. Since then I noticed the issue when creating VMs from template, using Ansible. When creating VM from template using UI, all works well. Tests were executed with same user, with SuperUser priviledges. pip freeze ansible==2.7.13 asn1crypto==1.0.0 bcrypt==3.1.7 cffi==1.12.3 cryptography==2.7 dnspython==1.16.0 ipaddress==1.0.22 Jinja2==2.10.1 lxml==4.4.1 MarkupSafe==1.1.1 netaddr==0.7.19 ovirt-engine-sdk-python==4.3.3 paramiko==2.6.0 pycparser==2.19 pycurl==7.43.0.3 PyNaCl==1.3.0 PyYAML==5.1.2 six==1.12.0 Logs from engine: 2019-10-08 09:57:42,294Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Lock Acquired to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:57:42,299Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43687) [390b4c75] FINISH, HSMClearTaskVDSCommand, return: , log id: be932a0 2019-10-08 09:57:42,299Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43687) [390b4c75] FINISH, SPMClearTaskVDSCommand, return: , log id: 3e25883 2019-10-08 09:57:42,303Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43687) [390b4c75] BaseAsyncTask::removeTaskFromDB: Removed task '7e1d68a2-bb49-4456-b228-db851fe6603c' from DataBase 2019-10-08 09:57:42,303Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43687) [390b4c75] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity '4f8a6897-66e8-453b-b706-246cb8505b3e' 2019-10-08 09:57:42,375Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Running command: AddVmCommand internal: false. Entities affected : ID: 2e428504-c339-11e9-87ef-00163e3ec101 Type: ClusterAction group CREATE_VM with role type USER, ID: 9ac6f4ad-58d0-4a7e-b424-91f2d76abcac Type: VmTemplateAction group CREATE_VM with role type USER, ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: StorageAction group CREATE_DISK with role type USER 2019-10-08 09:57:42,488Z INFO [org.ovirt.engine.core.bll.AddRngDeviceCommand] (default task-23) [332c57d4] Running command: AddRngDeviceCommand internal: true. Entities affected : ID: d5719cf0-2a64-4a28-bbf2-edc1bb05b777 Type: VMAction group EDIT_VM_PROPERTIES with role type USER 2019-10-08 09:57:42,498Z INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-23) [332c57d4] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{vmId='d5719cf0-2a64-4a28-bbf2-edc1bb05b777', status='ImageLocked', exitStatus='Normal'}), log id: 2fe004e2 2019-10-08 09:57:42,507Z INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-23) [332c57d4] FINISH, SetVmStatusVDSCommand, return: , log id: 2fe004e2 2019-10-08 09:57:42,528Z INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Running command: CreateSnapshotFromTemplateCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:57:42,554Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', imageSizeInBytes='8589934592', volumeFormat='COW', newImageId='9a96018c-ce7d-4c77-a91a-30fc16c7b2ba', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='f9e0c4d9-81dd-4e44-8a71-33e55d4399c6', sourceImageGroupId='a7e42574-be60-4c94-94a5-cc4b30fdb16f'}), log id: 37b29c7d 2019-10-08 09:57:42,639Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] FINISH, CreateVolumeVDSCommand, return: 9a96018c-ce7d-4c77-a91a-30fc16c7b2ba, log id: 37b29c7d 2019-10-08 09:57:42,645Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'f1665b66-2032-4a60-944e-c04beace088e' 2019-10-08 09:57:42,645Z INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] CommandMultiAsyncTasks::attachTask: Attaching task '99abc310-b44b-435c-8d43-922b782a69dc' to command 'f1665b66-2032-4a60-944e-c04beace088e'. 2019-10-08 09:57:42,660Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Adding task '99abc310-b44b-435c-8d43-922b782a69dc' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2019-10-08 09:57:42,934Z INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] EVENT_ID: USER_ADD_VM_STARTED(37), VM centos-testvm-024 creation was initiated by mteam@internal-authz. 2019-10-08 09:57:42,935Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-23) [067ec489-ae6c-4871-8ab6-8296016ca1ce] BaseAsyncTask::startPollingTask: Starting to poll task '99abc310-b44b-435c-8d43-922b782a69dc'. 2019-10-08 09:57:44,384Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-74) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Command 'AddVm' (id: '1b65f576-365d-4e8b-a920-621516cbdaed') waiting on child command id: 'f1665b66-2032-4a60-944e-c04beace088e' type:'CreateSnapshotFromTemplate' to complete 2019-10-08 09:57:48,393Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Command 'AddVm' (id: '1b65f576-365d-4e8b-a920-621516cbdaed') waiting on child command id: 'f1665b66-2032-4a60-944e-c04beace088e' type:'CreateSnapshotFromTemplate' to complete 2019-10-08 09:57:48,394Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'AddDisk' id: '937776b8-b94d-4178-b9c2-e39fe42cb06c' child commands '[63409b0b-749a-45d5-85a5-baf55d5fa2a4]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:48,394Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'AddDisk' id: '937776b8-b94d-4178-b9c2-e39fe42cb06c' Updating status to 'SUCCEEDED', The command end method logic will be executed by one of its parent commands. 2019-10-08 09:57:48,398Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'AddDisk' id: 'fdc5571e-a925-4400-a54a-a1ef1dcd23ae' child commands '[54d68cae-6585-4351-aaf7-fe687905acf4]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:48,398Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'AddDisk' id: 'fdc5571e-a925-4400-a54a-a1ef1dcd23ae' Updating status to 'SUCCEEDED', The command end method logic will be executed by one of its parent commands. 2019-10-08 09:57:48,401Z INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'ProcessOvfUpdateForStorageDomain' (id: 'bdcdae3a-00f6-4176-9d27-0bb0f04912a3') waiting on child command id: 'b4050edd-62a7-4b83-a4ab-a21c83bf3ade' type:'CreateOvfVolumeForStorageDomain' to complete 2019-10-08 09:57:48,402Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'CreateOvfVolumeForStorageDomain' id: 'b4050edd-62a7-4b83-a4ab-a21c83bf3ade' child commands '[937776b8-b94d-4178-b9c2-e39fe42cb06c]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:48,404Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-37) [5830ba58] Command 'CreateOvfVolumeForStorageDomain' id: '5fd47910-95b2-4387-8e26-ea2c80b078a0' child commands '[fdc5571e-a925-4400-a54a-a1ef1dcd23ae]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:49,416Z INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [390b4c75] Command 'ProcessOvfUpdateForStorageDomain' id: '849bd16c-00d2-48a2-8fde-631af0dfe1b5' child commands '[a80a3657-c813-42c1-a43d-27442b5dc238, 4f8a6897-66e8-453b-b706-246cb8505b3e]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:49,418Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.CreateOvfVolumeForStorageDomainCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.CreateOvfVolumeForStorageDomainCommand' successfully. 2019-10-08 09:57:49,420Z INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' successfully. 2019-10-08 09:57:49,426Z INFO [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' successfully. 2019-10-08 09:57:49,427Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] START, GetImageInfoVDSCommand( GetImageInfoVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='66984468-bbfa-4941-8c6b-df72a6d920f2', imageId='7db55211-041a-40c8-85a6-a2ff1bd182ce'}), log id: 6c02a73c 2019-10-08 09:57:49,429Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] START, GetVolumeInfoVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, GetVolumeInfoVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c', storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='66984468-bbfa-4941-8c6b-df72a6d920f2', imageId='7db55211-041a-40c8-85a6-a2ff1bd182ce'}), log id: 2e131d9d 2019-10-08 09:57:49,456Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@26992dd0, log id: 2e131d9d 2019-10-08 09:57:49,456Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@26992dd0, log id: 6c02a73c 2019-10-08 09:57:49,464Z WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [] VM is null - no unlocking 2019-10-08 09:57:49,481Z INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [] EVENT_ID: USER_ADD_DISK_FINISHED_SUCCESS(2,021), The disk 'OVF_STORE' was successfully added. 2019-10-08 09:57:49,490Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.CreateOvfVolumeForStorageDomainCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.CreateOvfVolumeForStorageDomainCommand' successfully. 2019-10-08 09:57:49,491Z INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' successfully. 2019-10-08 09:57:49,495Z INFO [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' successfully. 2019-10-08 09:57:49,497Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] START, GetImageInfoVDSCommand( GetImageInfoVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='ee208fd3-e05c-4ba8-aba9-fa521d69a870', imageId='484c1eed-b03a-4fa0-a12d-0087294dec86'}), log id: 7a3dad31 2019-10-08 09:57:49,498Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] START, GetVolumeInfoVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, GetVolumeInfoVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c', storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='ee208fd3-e05c-4ba8-aba9-fa521d69a870', imageId='484c1eed-b03a-4fa0-a12d-0087294dec86'}), log id: 5b85c4a5 2019-10-08 09:57:49,522Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@13555e4, log id: 5b85c4a5 2019-10-08 09:57:49,522Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [5830ba58] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@13555e4, log id: 7a3dad31 2019-10-08 09:57:49,529Z WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [] VM is null - no unlocking 2019-10-08 09:57:49,540Z INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-3) [] EVENT_ID: USER_ADD_DISK_FINISHED_SUCCESS(2,021), The disk 'OVF_STORE' was successfully added. 2019-10-08 09:57:50,552Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [390b4c75] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand' successfully. 2019-10-08 09:57:50,575Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='ee208fd3-e05c-4ba8-aba9-fa521d69a870', imageId='484c1eed-b03a-4fa0-a12d-0087294dec86'}), log id: 7e77a9a8 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGroupGUID=ee208fd3-e05c-4ba8-aba9-fa521d69a870 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=484c1eed-b03a-4fa0-a12d-0087294dec86 2019-10-08 09:57:50,576Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ description={"Updated":false,"Last Updated":null,"Storage Domains":[{"uuid":"935de3ac-a735-4fc8-9161-26bfd751ffc7"}],"Disk Description":"OVF_STORE"} 2019-10-08 09:57:50,606Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 7e77a9a8 2019-10-08 09:57:50,614Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Lock Acquired to object 'EngineLock:{exclusiveLocks='', sharedLocks='[bfc4c379-bd5f-45be-98a4-f0469dc3817c=VDS_EXECUTION]'}' 2019-10-08 09:57:50,623Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Running command: UploadStreamCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:57:50,624Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, UploadStreamVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, UploadStreamVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c'}), log id: 531a4a4a 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeVdsBrokerCommand, parameters: 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGUID=ee208fd3-e05c-4ba8-aba9-fa521d69a870 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=484c1eed-b03a-4fa0-a12d-0087294dec86 2019-10-08 09:57:50,625Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ size=30720 2019-10-08 09:57:51,331Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, UploadStreamVDSCommand, return: , log id: 531a4a4a 2019-10-08 09:57:51,342Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'c11f4d3c-f85b-43c5-986f-a517aed66d7e' 2019-10-08 09:57:51,342Z INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] CommandMultiAsyncTasks::attachTask: Attaching task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' to command 'c11f4d3c-f85b-43c5-986f-a517aed66d7e'. 2019-10-08 09:57:51,351Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Adding task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2019-10-08 09:57:51,355Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] BaseAsyncTask::startPollingTask: Starting to poll task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d'. 2019-10-08 09:57:51,358Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[bfc4c379-bd5f-45be-98a4-f0469dc3817c=VDS_EXECUTION]'}' 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='ee208fd3-e05c-4ba8-aba9-fa521d69a870', imageId='484c1eed-b03a-4fa0-a12d-0087294dec86'}), log id: 238169f6 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGroupGUID=ee208fd3-e05c-4ba8-aba9-fa521d69a870 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=484c1eed-b03a-4fa0-a12d-0087294dec86 2019-10-08 09:57:51,360Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ description={"Updated":true,"Size":30720,"Last Updated":"Tue Oct 08 09:57:50 UTC 2019","Storage Domains":[{"uuid":"935de3ac-a735-4fc8-9161-26bfd751ffc7"}],"Disk Description":"OVF_STORE"} 2019-10-08 09:57:51,389Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 238169f6 2019-10-08 09:57:51,596Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='66984468-bbfa-4941-8c6b-df72a6d920f2', imageId='7db55211-041a-40c8-85a6-a2ff1bd182ce'}), log id: 59bde70f 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGroupGUID=66984468-bbfa-4941-8c6b-df72a6d920f2 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=7db55211-041a-40c8-85a6-a2ff1bd182ce 2019-10-08 09:57:51,627Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ description={"Updated":false,"Last Updated":null,"Storage Domains":[{"uuid":"935de3ac-a735-4fc8-9161-26bfd751ffc7"}],"Disk Description":"OVF_STORE"} 2019-10-08 09:57:51,664Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 59bde70f 2019-10-08 09:57:51,672Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Lock Acquired to object 'EngineLock:{exclusiveLocks='', sharedLocks='[bfc4c379-bd5f-45be-98a4-f0469dc3817c=VDS_EXECUTION]'}' 2019-10-08 09:57:51,683Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Running command: UploadStreamCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, UploadStreamVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, UploadStreamVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c'}), log id: 1cb812b6 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeVdsBrokerCommand, parameters: 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGUID=66984468-bbfa-4941-8c6b-df72a6d920f2 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=7db55211-041a-40c8-85a6-a2ff1bd182ce 2019-10-08 09:57:51,684Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ size=30720 2019-10-08 09:57:51,933Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, UploadStreamVDSCommand, return: , log id: 1cb812b6 2019-10-08 09:57:51,943Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'd0c07988-0e43-4e6d-b86c-e736b28d4537' 2019-10-08 09:57:51,943Z INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] CommandMultiAsyncTasks::attachTask: Attaching task 'ba88edd0-8188-472e-8f59-aa3f90e63181' to command 'd0c07988-0e43-4e6d-b86c-e736b28d4537'. 2019-10-08 09:57:51,952Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Adding task 'ba88edd0-8188-472e-8f59-aa3f90e63181' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2019-10-08 09:57:51,958Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] BaseAsyncTask::startPollingTask: Starting to poll task 'ba88edd0-8188-472e-8f59-aa3f90e63181'. 2019-10-08 09:57:51,961Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[bfc4c379-bd5f-45be-98a4-f0469dc3817c=VDS_EXECUTION]'}' 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='66984468-bbfa-4941-8c6b-df72a6d920f2', imageId='7db55211-041a-40c8-85a6-a2ff1bd182ce'}), log id: 213b3075 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ spUUID=2e3b3484-c339-11e9-8d02-00163e3ec101 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ sdUUID=935de3ac-a735-4fc8-9161-26bfd751ffc7 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ imageGroupGUID=66984468-bbfa-4941-8c6b-df72a6d920f2 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ volUUID=7db55211-041a-40c8-85a6-a2ff1bd182ce 2019-10-08 09:57:51,962Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] ++ description={"Updated":true,"Size":30720,"Last Updated":"Tue Oct 08 09:57:50 UTC 2019","Storage Domains":[{"uuid":"935de3ac-a735-4fc8-9161-26bfd751ffc7"}],"Disk Description":"OVF_STORE"} 2019-10-08 09:57:52,028Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-1) [5830ba58] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 213b3075 2019-10-08 09:57:52,224Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] Polling and updating Async Tasks: 7 tasks, 3 tasks to poll now 2019-10-08 09:57:52,228Z ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-10-08 09:57:52,235Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM ovirt-staging-hv-01.avinity.tv command HSMGetAllTasksStatusesVDS failed: Invalid parameter: 'size=16777216' 2019-10-08 09:57:52,235Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] SPMAsyncTask::PollTask: Polling task '99abc310-b44b-435c-8d43-922b782a69dc' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2019-10-08 09:57:52,240Z ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] BaseAsyncTask::logEndTaskFailure: Task '99abc310-b44b-435c-8d43-922b782a69dc' (Parent Command 'CreateSnapshotFromTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'size=16777216', code = 100', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = Invalid parameter: 'size=16777216', code = 100' 2019-10-08 09:57:52,241Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'f1665b66-2032-4a60-944e-c04beace088e' has ended -> executing 'endAction' 2019-10-08 09:57:52,241Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'f1665b66-2032-4a60-944e-c04beace088e'): calling endAction '. 2019-10-08 09:57:52,241Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] SPMAsyncTask::PollTask: Polling task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2019-10-08 09:57:52,241Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] BaseAsyncTask::onTaskEndSuccess: Task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2019-10-08 09:57:52,241Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateSnapshotFromTemplate', 2019-10-08 09:57:52,242Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'c11f4d3c-f85b-43c5-986f-a517aed66d7e' has ended -> executing 'endAction' 2019-10-08 09:57:52,243Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'c11f4d3c-f85b-43c5-986f-a517aed66d7e'): calling endAction '. 2019-10-08 09:57:52,243Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] SPMAsyncTask::PollTask: Polling task 'ba88edd0-8188-472e-8f59-aa3f90e63181' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2019-10-08 09:57:52,243Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] BaseAsyncTask::onTaskEndSuccess: Task 'ba88edd0-8188-472e-8f59-aa3f90e63181' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2019-10-08 09:57:52,243Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'UploadStream', 2019-10-08 09:57:52,244Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'd0c07988-0e43-4e6d-b86c-e736b28d4537' has ended -> executing 'endAction' 2019-10-08 09:57:52,244Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-91) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'd0c07988-0e43-4e6d-b86c-e736b28d4537'): calling endAction '. 2019-10-08 09:57:52,245Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'UploadStream', 2019-10-08 09:57:52,245Z INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Command [id=f1665b66-2032-4a60-944e-c04beace088e]: Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshotFromTemplate' completed, handling the result. 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshotFromTemplate' succeeded, clearing tasks. 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '99abc310-b44b-435c-8d43-922b782a69dc' 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand' successfully. 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand' successfully. 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', taskId='99abc310-b44b-435c-8d43-922b782a69dc'}), log id: 66a4e67 2019-10-08 09:57:52,247Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] START, HSMClearTaskVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, HSMTaskGuidBaseVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c', taskId='99abc310-b44b-435c-8d43-922b782a69dc'}), log id: 7ec6d8b8 2019-10-08 09:57:52,249Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' completed, handling the result. 2019-10-08 09:57:52,249Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' succeeded, clearing tasks. 2019-10-08 09:57:52,249Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' 2019-10-08 09:57:52,249Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', taskId='e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d'}), log id: 356927d 2019-10-08 09:57:52,250Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' completed, handling the result. 2019-10-08 09:57:52,250Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' succeeded, clearing tasks. 2019-10-08 09:57:52,250Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'ba88edd0-8188-472e-8f59-aa3f90e63181' 2019-10-08 09:57:52,251Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', taskId='ba88edd0-8188-472e-8f59-aa3f90e63181'}), log id: 75844e34 2019-10-08 09:57:52,259Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] FINISH, HSMClearTaskVDSCommand, return: , log id: 7ec6d8b8 2019-10-08 09:57:52,259Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] FINISH, SPMClearTaskVDSCommand, return: , log id: 66a4e67 2019-10-08 09:57:52,260Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] START, HSMClearTaskVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, HSMTaskGuidBaseVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c', taskId='e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d'}), log id: 3b239769 2019-10-08 09:57:52,263Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] BaseAsyncTask::removeTaskFromDB: Removed task '99abc310-b44b-435c-8d43-922b782a69dc' from DataBase 2019-10-08 09:57:52,263Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43693) [067ec489-ae6c-4871-8ab6-8296016ca1ce] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'f1665b66-2032-4a60-944e-c04beace088e' 2019-10-08 09:57:52,297Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] FINISH, HSMClearTaskVDSCommand, return: , log id: 3b239769 2019-10-08 09:57:52,297Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] FINISH, SPMClearTaskVDSCommand, return: , log id: 356927d 2019-10-08 09:57:52,298Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] START, HSMClearTaskVDSCommand(HostName = ovirt-staging-hv-01.avinity.tv, HSMTaskGuidBaseVDSCommandParameters:{hostId='bfc4c379-bd5f-45be-98a4-f0469dc3817c', taskId='ba88edd0-8188-472e-8f59-aa3f90e63181'}), log id: 32d44e1 2019-10-08 09:57:52,301Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] BaseAsyncTask::removeTaskFromDB: Removed task 'e5d00ff5-eaa2-48e9-ab10-d6d06a01e89d' from DataBase 2019-10-08 09:57:52,301Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43694) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'c11f4d3c-f85b-43c5-986f-a517aed66d7e' 2019-10-08 09:57:52,314Z INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] FINISH, HSMClearTaskVDSCommand, return: , log id: 32d44e1 2019-10-08 09:57:52,314Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] FINISH, SPMClearTaskVDSCommand, return: , log id: 75844e34 2019-10-08 09:57:52,317Z INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] BaseAsyncTask::removeTaskFromDB: Removed task 'ba88edd0-8188-472e-8f59-aa3f90e63181' from DataBase 2019-10-08 09:57:52,317Z INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-43695) [5830ba58] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'd0c07988-0e43-4e6d-b86c-e736b28d4537' 2019-10-08 09:57:54,039Z INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-44) [5830ba58] Command 'ProcessOvfUpdateForStorageDomain' id: 'bdcdae3a-00f6-4176-9d27-0bb0f04912a3' child commands '[b4050edd-62a7-4b83-a4ab-a21c83bf3ade, 5fd47910-95b2-4387-8e26-ea2c80b078a0, c11f4d3c-f85b-43c5-986f-a517aed66d7e, d0c07988-0e43-4e6d-b86c-e736b28d4537]' executions were completed, status 'SUCCEEDED' 2019-10-08 09:57:55,046Z INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-40) [5830ba58] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand' successfully. 2019-10-08 09:57:58,077Z INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-76) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Command 'AddVm' id: '1b65f576-365d-4e8b-a920-621516cbdaed' child commands '[f1665b66-2032-4a60-944e-c04beace088e]' executions were completed, status 'FAILED' 2019-10-08 09:57:59,094Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:57:59,099Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:57:59,104Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:57:59,126Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 69861a78 2019-10-08 09:57:59,139Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:57:59,139Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:57:59,139Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] FINISH, DeleteImageGroupVDSCommand, return: , log id: 69861a78 2019-10-08 09:57:59,139Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:57:59,149Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [5794ed92] Removed task 'b4c4c723-4ba1-4d5a-86e6-24658a293a04' from DataBase 2019-10-08 09:57:59,220Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] transaction rolled back 2019-10-08 09:57:59,220Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:57:59,233Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:57:59,233Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries 2019-10-08 09:58:01,252Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:58:01,257Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:58:01,270Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:58:01,308Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 35fec55 2019-10-08 09:58:01,324Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:01,324Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:01,324Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] FINISH, DeleteImageGroupVDSCommand, return: , log id: 35fec55 2019-10-08 09:58:01,324Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:58:01,335Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [19251787] Removed task '6ed0a844-5363-4afd-bffc-a80b6ace69ea' from DataBase 2019-10-08 09:58:01,395Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] transaction rolled back 2019-10-08 09:58:01,395Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] Trying to release a shared lock for key: '9ac6f4ad-58d0-4a7e-b424-91f2d76abcacTEMPLATE' , but lock does not exist 2019-10-08 09:58:01,395Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] Trying to release a shared lock for key: 'a7e42574-be60-4c94-94a5-cc4b30fdb16fDISK' , but lock does not exist 2019-10-08 09:58:01,395Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] Trying to release exclusive lock which does not exist, lock key: 'centos-testvm-024VM_NAME' 2019-10-08 09:58:01,395Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:58:01,407Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:58:01,407Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-85) [] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries 2019-10-08 09:58:05,427Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:58:05,430Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:58:05,437Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:58:05,452Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 6ac726b6 2019-10-08 09:58:05,466Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:05,466Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:05,466Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] FINISH, DeleteImageGroupVDSCommand, return: , log id: 6ac726b6 2019-10-08 09:58:05,467Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:58:05,477Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [cf91364] Removed task '31bd7a11-203d-4459-ac54-3c398c85771d' from DataBase 2019-10-08 09:58:05,490Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] transaction rolled back 2019-10-08 09:58:05,490Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] Trying to release a shared lock for key: '9ac6f4ad-58d0-4a7e-b424-91f2d76abcacTEMPLATE' , but lock does not exist 2019-10-08 09:58:05,490Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] Trying to release a shared lock for key: 'a7e42574-be60-4c94-94a5-cc4b30fdb16fDISK' , but lock does not exist 2019-10-08 09:58:05,490Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] Trying to release exclusive lock which does not exist, lock key: 'centos-testvm-024VM_NAME' 2019-10-08 09:58:05,490Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:58:05,503Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:58:05,503Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries 2019-10-08 09:58:13,523Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:58:13,527Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:58:13,533Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:58:13,548Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 33164673 2019-10-08 09:58:13,560Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:13,560Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:13,560Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] FINISH, DeleteImageGroupVDSCommand, return: , log id: 33164673 2019-10-08 09:58:13,560Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:58:13,570Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [56103b5a] Removed task 'ce6882de-2d89-4298-bdcf-86d621a54084' from DataBase 2019-10-08 09:58:13,583Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] transaction rolled back 2019-10-08 09:58:13,583Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] Trying to release a shared lock for key: '9ac6f4ad-58d0-4a7e-b424-91f2d76abcacTEMPLATE' , but lock does not exist 2019-10-08 09:58:13,583Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] Trying to release a shared lock for key: 'a7e42574-be60-4c94-94a5-cc4b30fdb16fDISK' , but lock does not exist 2019-10-08 09:58:13,583Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] Trying to release exclusive lock which does not exist, lock key: 'centos-testvm-024VM_NAME' 2019-10-08 09:58:13,583Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:58:13,595Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:58:13,595Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-35) [] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries 2019-10-08 09:58:23,616Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:58:23,620Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:58:23,627Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:58:23,642Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 7346a5bd 2019-10-08 09:58:23,663Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:23,663Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:23,663Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] FINISH, DeleteImageGroupVDSCommand, return: , log id: 7346a5bd 2019-10-08 09:58:23,663Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:58:23,682Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [48f2f9bd] Removed task '8483357d-6d4f-418e-9751-70fcb69685cb' from DataBase 2019-10-08 09:58:23,695Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] transaction rolled back 2019-10-08 09:58:23,695Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Trying to release a shared lock for key: '9ac6f4ad-58d0-4a7e-b424-91f2d76abcacTEMPLATE' , but lock does not exist 2019-10-08 09:58:23,695Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Trying to release a shared lock for key: 'a7e42574-be60-4c94-94a5-cc4b30fdb16fDISK' , but lock does not exist 2019-10-08 09:58:23,695Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Trying to release exclusive lock which does not exist, lock key: 'centos-testvm-024VM_NAME' 2019-10-08 09:58:23,695Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:58:23,706Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:58:23,706Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-71) [] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries 2019-10-08 09:58:33,725Z ERROR [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.AddVmCommand' with failure. 2019-10-08 09:58:33,729Z ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotFromTemplateCommand' with failure. 2019-10-08 09:58:33,736Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] Running command: RemoveImageCommand internal: true. Entities affected : ID: 935de3ac-a735-4fc8-9161-26bfd751ffc7 Type: Storage 2019-10-08 09:58:33,752Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'}), log id: 6d120001 2019-10-08 09:58:33,767Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:33,767Z ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{storagePoolId='2e3b3484-c339-11e9-8d02-00163e3ec101', ignoreFailoverLimit='false', storageDomainId='935de3ac-a735-4fc8-9161-26bfd751ffc7', imageGroupId='d680a46a-7188-45f6-b6a7-3333f830c0b4', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: u'image=d680a46a-7188-45f6-b6a7-3333f830c0b4, domain=935de3ac-a735-4fc8-9161-26bfd751ffc7' 2019-10-08 09:58:33,767Z INFO [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] FINISH, DeleteImageGroupVDSCommand, return: , log id: 6d120001 2019-10-08 09:58:33,767Z INFO [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] Disk 'd680a46a-7188-45f6-b6a7-3333f830c0b4' doesn't exist on storage domain '935de3ac-a735-4fc8-9161-26bfd751ffc7', rolling forward 2019-10-08 09:58:33,778Z INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [3eea0406] Removed task 'bfb5e88a-0e62-4e03-b02b-a5a0b36f84db' from DataBase 2019-10-08 09:58:33,791Z INFO [org.ovirt.engine.core.utils.transaction.TransactionSupport] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] transaction rolled back 2019-10-08 09:58:33,791Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] Trying to release a shared lock for key: '9ac6f4ad-58d0-4a7e-b424-91f2d76abcacTEMPLATE' , but lock does not exist 2019-10-08 09:58:33,791Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] Trying to release a shared lock for key: 'a7e42574-be60-4c94-94a5-cc4b30fdb16fDISK' , but lock does not exist 2019-10-08 09:58:33,791Z WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] Trying to release exclusive lock which does not exist, lock key: 'centos-testvm-024VM_NAME' 2019-10-08 09:58:33,791Z INFO [org.ovirt.engine.core.bll.AddVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] Lock freed to object 'EngineLock:{exclusiveLocks='[centos-testvm-024=VM_NAME]', sharedLocks='[9ac6f4ad-58d0-4a7e-b424-91f2d76abcac=TEMPLATE, a7e42574-be60-4c94-94a5-cc4b30fdb16f=DISK]'}' 2019-10-08 09:58:33,804Z ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [] EVENT_ID: USER_ADD_VM_FINISHED_FAILURE(60), Failed to complete VM centos-testvm-024 creation. 2019-10-08 09:58:33,824Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Failed invoking callback end method 'onFailed' for command '1b65f576-365d-4e8b-a920-621516cbdaed' with exception 'null', the callback is marked for end method retries but max number of retries have been attempted. The command will be marked as Failed. 2019-10-08 09:58:33,824Z INFO [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Exception in invoking callback of command AddVm (1b65f576-365d-4e8b-a920-621516cbdaed): NullPointerException: 2019-10-08 09:58:33,824Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Error invoking callback method 'onFailed' for 'FAILED' command '1b65f576-365d-4e8b-a920-621516cbdaed' 2019-10-08 09:58:33,824Z ERROR [org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [067ec489-ae6c-4871-8ab6-8296016ca1ce] Exception: javax.ejb.EJBTransactionRolledbackException at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:203) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:420) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:148) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81) [weld-ejb-3.1.1.Final.jar:3.1.1.Final] at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-17.0.1.Final.jar:17.0.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:618) at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198) at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81) at org.ovirt.engine.core.bll.interfaces.BackendInternal$$$view3.endAction(Unknown Source) [bll.jar:] at sun.reflect.GeneratedMethodAccessor1032.invoke(Unknown Source) [:1.8.0_222] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_222] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_222] at org.jboss.weld.util.reflection.Reflections.invokeAndUnwrap(Reflections.java:410) [weld-core-impl-3.1.1.Final.jar:3.1.1.Final] at org.jboss.weld.module.ejb.EnterpriseBeanProxyMethodHandler.invoke(EnterpriseBeanProxyMethodHandler.java:134) [weld-ejb-3.1.1.Final.jar:3.1.1.Final] at org.jboss.weld.bean.proxy.EnterpriseTargetBeanInstance.invoke(EnterpriseTargetBeanInstance.java:56) [weld-core-impl-3.1.1.Final.jar:3.1.1.Final] at org.jboss.weld.module.ejb.InjectionPointPropagatingEnterpriseTargetBeanInstance.invoke(InjectionPointPropagatingEnterpriseTargetBeanInstance.java:68) [weld-ejb-3.1.1.Final.jar:3.1.1.Final] at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) [weld-core-impl-3.1.1.Final.jar:3.1.1.Final] at org.ovirt.engine.core.bll.BackendCommandObjectsHandler$BackendInternal$BackendLocal$2049259618$Proxy$_$$_Weld$EnterpriseProxy$.endAction(Unknown Source) [bll.jar:] at org.ovirt.engine.core.bll.VmCommand.endActionOnDisks(VmCommand.java:266) [bll.jar:] at org.ovirt.engine.core.bll.AddVmCommand.endWithFailure(AddVmCommand.java:1452) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:736) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:658) [bll.jar:] at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2003) [bll.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137) [utils.jar:] at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:] at org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:520) [bll.jar:] at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:134) [bll.jar:] at org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:174) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:67) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:166) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109) [bll.jar:] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_222] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_222] at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent-1.0.jar:] at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent-1.0.jar:] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_222] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_222] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_222] at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent-1.0.jar:] Caused by: java.lang.NullPointerException Ansible output: The full traceback is: Traceback (most recent call last): File "/var/folders/40/w2c8fp151854mddz_4n3czwm0000gn/T/ansible_ovirt_vm_payload_uy4lqway/__main__.py", line 2024, in main clone_permissions=module.params['clone_permissions'], File "/var/folders/40/w2c8fp151854mddz_4n3czwm0000gn/T/ansible_ovirt_vm_payload_uy4lqway/ansible_ovirt_vm_payload.zip/ansible/module_utils/ovirt.py", line 610, in create poll_interval=self._module.params['poll_interval'], File "/var/folders/40/w2c8fp151854mddz_4n3czwm0000gn/T/ansible_ovirt_vm_payload_uy4lqway/ansible_ovirt_vm_payload.zip/ansible/module_utils/ovirt.py", line 341, in wait raise Exception("Timeout exceed while waiting on result state of the entity.") Exception: Timeout exceed while waiting on result state of the entity. fatal: [centos-testvm-024.avinity.tv -> localhost]: FAILED! => { "changed": false, "invocation": { "module_args": { "affinity_group_mappings": [], "affinity_label_mappings": [], "allow_partial_import": null, "ballooning_enabled": null, "boot_devices": null, "boot_menu": null, "cd_iso": null, "clone": false, "clone_permissions": false, "cloud_init": { "authorized_ssh_keys": "ssh-rsa removed pubkey", "host_name": "centos-testvm-024.avinity.tv", "user_name": "centos" }, "cloud_init_nics": [], "cloud_init_persist": false, "cluster": "avshared1", "cluster_mappings": [], "comment": "oVirt Template Bakery Validation", "cpu_cores": null, "cpu_mode": null, "cpu_pinning": null, "cpu_shares": null, "cpu_sockets": null, "cpu_threads": null, "custom_compatibility_version": null, "custom_properties": null, "delete_protected": null, "description": null, "disk_format": "cow", "disks": [], "domain_mappings": [], "fetch_nested": false, "force": false, "graphical_console": null, "high_availability": null, "high_availability_priority": null, "host": null, "host_devices": null, "id": null, "initrd_path": null, "instance_type": "Medium", "io_threads": null, "kernel_params": null, "kernel_path": null, "kvm": null, "lease": null, "lun_mappings": [], "memory": null, "memory_guaranteed": null, "memory_max": null, "name": "centos-testvm-024", "nested_attributes": [], "nics": [ { "interface": "virtio", "name": "nic1", "profile_name": "tenant1" } ], "numa_nodes": [], "numa_tune_mode": null, "operating_system": null, "placement_policy": null, "poll_interval": 3, "quota_id": null, "reassign_bad_macs": null, "rng_device": null, "role_mappings": [], "serial_console": null, "serial_policy": null, "serial_policy_value": null, "smartcard_enabled": null, "soundcard_enabled": null, "sso": null, "state": "running", "stateless": null, "storage_domain": null, "sysprep": null, "template": "av-centos-75-baseimage_nfs9000", "template_version": null, "ticket": null, "timeout": 180, "timezone": null, "type": null, "usb_support": null, "use_latest_template_version": null, "vmware": null, "vnic_profile_mappings": [], "wait": true, "watchdog": null, "xen": null } }, "msg": "Timeout exceed while waiting on result state of the entity." }