Bug 1565183
| Summary: | Snapshot creation with memory fails on permission validation | ||
|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Benny Zlotnik <bzlotnik> |
| Component: | BLL.Virt | Assignee: | Liran Rotenberg <lrotenbe> |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Qin Yuan <qiyuan> |
| Severity: | high | Docs Contact: | |
| Priority: | medium | ||
| Version: | future | CC: | ahadas, bugs, dfodor, mavital, michal.skrivanek, mperina, mzamazal, qiyuan, sasha, tnisan |
| Target Milestone: | ovirt-4.5.3 | Keywords: | PrioBumpQA |
| Target Release: | --- | Flags: | pm-rhel:
ovirt-4.5?
|
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2022-12-05 12:46:31 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | Virt | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
Re-targeting, since this may be important for security (users without permissions to all objects shouldn't be able to perform the action at all) (In reply to Ryan Barry from comment #1) > Re-targeting, since this may be important for security (users without > permissions to all objects shouldn't be able to perform the action at all) Ryan are you sure 4.5 is right target given above comment? You're right, Sandro. Thanks we need to make sure to pick a storage domain that the user has permissions on (and there needs to be one because it's probably not a diskless vm) Tested with ovirt-engine-4.5.2.1-0.1.el8ev.noarch Steps: 1. Create a VM with one disk on storage domain nfs_0, the disk alias is latest-rhel-guest-image-8.6-infra 2. Create a non-admin user - with UserVmManager permission - with attach disk profile permission on storage domain nfs_1 - without attach disk profile permission on storage domain nfs_0 3. Create two disks on storage domain nfs_1, aliases are a-disk, z-disk 4. With the user, attempt to create a live snapshot with memory 5. Attach disk z-disk to the VM 6. With the user, attempt to create a live snapshot with memory 7. Attach disk a-disk to the VM 8. With the user, attempt to create a live snapshot with memory Results: 1. When the VM only has one disk on storage domain nfs_0, creating live snapshot with memory failed: 2022-08-08 13:45:31,084+03 INFO [org.ovirt.engine.core.bll.memory.MemoryStorageHandler] (default task-90) [546713ad-c594-4c7e-8adb-8abb69847ab6] The memory volumes of VM (name 'golden_env_mixed_virtio_0', id '56066d4f-63c0-43b4-9a75-8b596681391c') will be stored in storage domain (name 'nfs_0', id 'c76c2853-666b-4324-93f3-f963adb1790a') ... 2022-08-08 13:45:31,329+03 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (default task-90) [546713ad-c594-4c7e-8adb-8abb69847ab6] Validation of action 'AddDisk' failed for user user1@internal-authz. Reasons: VAR__ACTION__ADD,VAR__TYPE__DISK,USER_NOT_AUTHORIZED_TO_ATTACH_DISK_PROFILE ... 2022-08-08 13:45:31,337+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-90) [546713ad-c594-4c7e-8adb-8abb69847ab6] Command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' failed: EngineException: Failed to create disk! golden_env_mixed_virtio_0_snapshot_memory (Failed with error ENGINE and code 5001) ... 2022-08-08 13:45:31,355+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-90) [546713ad-c594-4c7e-8adb-8abb69847ab6] EVENT_ID: USER_FAILED_CREATE_SNAPSHOT(117), Failed to create Snapshot snap1 for VM golden_env_mixed_virtio_0 (User: user1@internal-authz). 2. When disk z-disk is attached to the VM, creating live snapshot with memory failed: 2022-08-08 13:50:59,996+03 INFO [org.ovirt.engine.core.bll.memory.MemoryStorageHandler] (default task-99) [05833de3-1a9d-4822-9b4a-4c12bced2ba8] The memory volumes of VM (name 'golden_env_mixed_virtio_0', id '56066d4f-63c0-43b4-9a75-8b596681391c') will be stored in storage domain (name 'nfs_0', id 'c76c2853-666b-4324-93f3-f963adb1790a') ... 2022-08-08 13:51:00,482+03 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (default task-99) [05833de3-1a9d-4822-9b4a-4c12bced2ba8] Validation of action 'AddDisk' failed for user user1@internal-authz. Reasons: VAR__ACTION__ADD,VAR__TYPE__DISK,USER_NOT_AUTHORIZED_TO_ATTACH_DISK_PROFILE ... 2022-08-08 13:51:00,491+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-99) [05833de3-1a9d-4822-9b4a-4c12bced2ba8] Command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' failed: EngineException: Failed to create disk! golden_env_mixed_virtio_0_snapshot_memory (Failed with error ENGINE and code 5001) ... 2022-08-08 13:51:00,501+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-99) [05833de3-1a9d-4822-9b4a-4c12bced2ba8] EVENT_ID: USER_FAILED_CREATE_SNAPSHOT(117), Failed to create Snapshot snap1 for VM golden_env_mixed_virtio_0 (User: user1@internal-authz). 3. When disk a-disk is attached to the VM, creating live snapshot with memory succeeded: 2022-08-08 13:58:44,416+03 INFO [org.ovirt.engine.core.bll.memory.MemoryStorageHandler] (default task-93) [5ea9d0fb-6407-414d-85d6-a648e4098f78] The memory volumes of VM (name 'golden_env_mixed_virtio_0', id '56066d4f-63c0-43b4-9a75-8b596681391c') will be stored in storage domain (name 'nfs_1', id '3b052619-5922-46eb-834c-17077b66f991') ... 2022-08-08 13:59:10,371+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_SUCCESS(68), Snapshot 'snap1' creation for VM 'golden_env_mixed_virtio_0' has been completed. According to the tests, it seems that the storage domain of the first disk of the VM will be selected to store the memory volumes of VM when creating live snapshot with memory. If the user doesn't have attach disk profile permission on that storage domain, creating snapshot will fail at adding disk because of USER_NOT_AUTHORIZED_TO_ATTACH_DISK_PROFILE. Another issue is, do we need to consider the situation that the user with UserVmManager permission doesn't have attach disk profile permission on any of the VM disk storage domains? will it happen in customer use cases? The strange thing is that the user is using a storage domain without permission, seem it works for step 8 (a-disk on nfs_1 which the user have permission). Another, is without permission to nfs_0, it still being used (maybe something wrong with the query, or handling the result). The current PR changed to query only SDs the user have permission to use for memory snapshot. Therefore, if we wish to prevent the command, we may validate it on the command to prevent the whole command. Verified with: ovirt-engine-4.5.3-0.2.el8ev.noarch Steps: The same steps as in comment #5 Results: Live snapshot with memory can be created successfully when the non-admin user has UserVmManager permission but don't have the "attach disk profile" permission. The needinfo request[s] on this closed bug have been removed as they have been unresolved for 120 days |
Not sure about the team/component, please move Description of problem: A user without the "attach disk profile" permission is able to initiate snapshot creation with memory but will fail on memory disk creation validation due to lack of permissions 2018-04-09 17:35:20,810+03 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Validation of action 'AddDisk' failed for user benny@secondary-authz. Reasons: VAR__ACTION__ADD,VAR__TYPE__DISK,USER_NOT_AUTHORIZED_TO_ATTACH_DISK_PROFILE Version-Release number of selected component (if applicable): How reproducible: 100% Steps to Reproduce: 1. Create a VM with a disk 2. Give UserVmManager permission to a non-admin user 3. With that user attempt to create a live snapshot with memory Actual results: The operation will fail on validation at the Add disk stage Expected results: The user should either be able to go through with the entire operation or fail at the initial snapshot creation attempt Additional info: 2018-04-09 17:35:19,993+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Running command: CreateSnapshotCommand internal: true. Entities affected : ID: 00000000-0000-0000-0000-000000000000 Type: Storage 2018-04-09 17:35:20,047+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] START, CreateVolumeVDSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='55ab06f0-3b0b-11e8-9eaa-507b9dec63c2', ignoreFailoverLimit='false', storageDomainId='77847bfc-b39c-4406-8377-a9515267318a', imageGroupId='0aab2373-7323-4d79-8dc4-18b969f38b8d', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='5666177e-f9f4-4ea0-9389-1caab737ca1e', imageType='Sparse', newImageDescription='', imageInitialSizeInBytes='0', imageId='b7b5ca32-aec6-493f-bb9b-160d3c3fc288', sourceImageGroupId='0aab2373-7323-4d79-8dc4-18b969f38b8d'}), log id: 7bf6fa03 2018-04-09 17:35:20,694+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] FINISH, CreateVolumeVDSCommand, return: 5666177e-f9f4-4ea0-9389-1caab737ca1e, log id: 7bf6fa03 2018-04-09 17:35:20,700+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '9c20d916-1157-4390-91b2-fa0daf10eaff' 2018-04-09 17:35:20,701+03 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] CommandMultiAsyncTasks::attachTask: Attaching task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' to command '9c20d916-1157-4390-91b2-fa0daf10eaff'. 2018-04-09 17:35:20,722+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Adding task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2018-04-09 17:35:20,767+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] BaseAsyncTask::startPollingTask: Starting to poll task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b'. 2018-04-09 17:35:20,810+03 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Validation of action 'AddDisk' failed for user benny@secondary-authz. Reasons: VAR__ACTION__ADD,VAR__TYPE__DISK,USER_NOT_AUTHORIZED_TO_ATTACH_DISK_PROFILE 2018-04-09 17:35:20,821+03 INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Lock freed to object 'EngineLock:{exclusiveLocks='[34eeb56c-a452-49e7-baca-7c0e5b6d996f=VM]', sharedLocks=''}' 2018-04-09 17:35:20,837+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' failed: EngineException: Failed to create disk! snapshot_memory (Failed with error ENGINE and code 5001) 2018-04-09 17:35:20,849+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Transaction rolled-back for command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand'. 2018-04-09 17:35:20,851+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Transaction rolled-back for command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand'. 2018-04-09 17:35:20,852+03 INFO [org.ovirt.engine.core.bll.tasks.CommandCoordinatorImpl] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Rollback for command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand' 2018-04-09 17:35:20,853+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Attempting to cancel task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b'. 2018-04-09 17:35:20,853+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] SPMAsyncTask::StopTask: Attempting to stop task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'). 2018-04-09 17:35:20,856+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMStopTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] START, SPMStopTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='55ab06f0-3b0b-11e8-9eaa-507b9dec63c2', ignoreFailoverLimit='false', taskId='2faf3f1f-9dcb-4a35-908d-4a398f95c31b'}), log id: 74daea64 2018-04-09 17:35:20,869+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMStopTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] START, HSMStopTaskVDSCommand(HostName = hosto, HSMTaskGuidBaseVDSCommandParameters:{hostId='371524e4-b614-4edc-a462-2991f090eca1', taskId='2faf3f1f-9dcb-4a35-908d-4a398f95c31b'}), log id: 4ac67150 2018-04-09 17:35:20,879+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMStopTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] FINISH, HSMStopTaskVDSCommand, log id: 4ac67150 2018-04-09 17:35:20,879+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMStopTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-80) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] FINISH, SPMStopTaskVDSCommand, log id: 74daea64 2018-04-09 17:35:20,881+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] EVENT_ID: USER_FAILED_CREATE_SNAPSHOT(117), Failed to create Snapshot s1 for VM vm (User: benny@secondary-authz). 2018-04-09 17:35:20,886+03 WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Trying to release exclusive lock which does not exist, lock key: '34eeb56c-a452-49e7-baca-7c0e5b6d996fVM' 2018-04-09 17:35:20,886+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedThreadFactory-engine-Thread-79) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Lock freed to object 'EngineLock:{exclusiveLocks='[34eeb56c-a452-49e7-baca-7c0e5b6d996f=VM]', sharedLocks=''}' 2018-04-09 17:35:22,016+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-39) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotForVm' (id: 'e2b5d216-c2fd-422d-8689-48481468c6eb') waiting on child command id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d' type:'CreateSnapshotDisk' to complete 2018-04-09 17:35:22,025+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-39) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotDisk' (id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d') waiting on child command id: '9c20d916-1157-4390-91b2-fa0daf10eaff' type:'CreateSnapshot' to complete 2018-04-09 17:35:26,072+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-83) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotForVm' (id: 'e2b5d216-c2fd-422d-8689-48481468c6eb') waiting on child command id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d' type:'CreateSnapshotDisk' to complete 2018-04-09 17:35:26,090+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-83) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotDisk' (id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d') waiting on child command id: '9c20d916-1157-4390-91b2-fa0daf10eaff' type:'CreateSnapshot' to complete 2018-04-09 17:35:30,646+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now 2018-04-09 17:35:30,691+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM hosto command HSMGetAllTasksStatusesVDS failed: shutting down 2018-04-09 17:35:30,695+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] SPMAsyncTask::PollTask: Polling task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'. 2018-04-09 17:35:30,707+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] BaseAsyncTask::logEndTaskFailure: Task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' (Parent Command 'CreateSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = shutting down', -- Exception: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = shutting down' 2018-04-09 17:35:30,710+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '9c20d916-1157-4390-91b2-fa0daf10eaff' has ended -> executing 'endAction' 2018-04-09 17:35:30,710+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-90) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '9c20d916-1157-4390-91b2-fa0daf10eaff'): calling endAction '. 2018-04-09 17:35:30,728+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'CreateSnapshot', 2018-04-09 17:35:30,772+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command [id=9c20d916-1157-4390-91b2-fa0daf10eaff]: Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. 2018-04-09 17:35:30,772+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshot' completed, handling the result. 2018-04-09 17:35:30,773+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'CreateSnapshot' succeeded, clearing tasks. 2018-04-09 17:35:30,773+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' 2018-04-09 17:35:30,782+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='55ab06f0-3b0b-11e8-9eaa-507b9dec63c2', ignoreFailoverLimit='false', taskId='2faf3f1f-9dcb-4a35-908d-4a398f95c31b'}), log id: 14cd28b7 2018-04-09 17:35:30,787+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] START, HSMClearTaskVDSCommand(HostName = hosto, HSMTaskGuidBaseVDSCommandParameters:{hostId='371524e4-b614-4edc-a462-2991f090eca1', taskId='2faf3f1f-9dcb-4a35-908d-4a398f95c31b'}), log id: 71a3b6b3 2018-04-09 17:35:30,815+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] FINISH, HSMClearTaskVDSCommand, log id: 71a3b6b3 2018-04-09 17:35:30,815+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] FINISH, SPMClearTaskVDSCommand, log id: 14cd28b7 2018-04-09 17:35:30,820+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] BaseAsyncTask::removeTaskFromDB: Removed task '2faf3f1f-9dcb-4a35-908d-4a398f95c31b' from DataBase 2018-04-09 17:35:30,820+03 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-81) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity '9c20d916-1157-4390-91b2-fa0daf10eaff' 2018-04-09 17:35:34,149+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-99) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotForVm' (id: 'e2b5d216-c2fd-422d-8689-48481468c6eb') waiting on child command id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d' type:'CreateSnapshotDisk' to complete 2018-04-09 17:35:34,176+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-99) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotDisk' id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d' child commands '[9c20d916-1157-4390-91b2-fa0daf10eaff]' executions were completed, status 'FAILED' 2018-04-09 17:35:34,177+03 INFO [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-99) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotDisk' id: 'ec8acbc8-0732-487b-9adf-5e2411406d3d' Updating status to 'FAILED', The command end method logic will be executed by one of its parent commands. 2018-04-09 17:35:36,289+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-26) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotForVm' id: 'e2b5d216-c2fd-422d-8689-48481468c6eb' execution didn't complete, not proceeding to perform the next operation 2018-04-09 17:35:36,290+03 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-26) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Command 'CreateSnapshotForVm' id: 'e2b5d216-c2fd-422d-8689-48481468c6eb' child commands '[ec8acbc8-0732-487b-9adf-5e2411406d3d, 51befcf9-3a62-4ed4-87c0-6affa1db0ce0]' executions were completed, status 'FAILED' 2018-04-09 17:35:37,382+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' with failure. 2018-04-09 17:35:37,391+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand' with failure. 2018-04-09 17:35:37,399+03 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand' with failure. 2018-04-09 17:35:37,484+03 INFO [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' successfully. 2018-04-09 17:35:37,484+03 WARN [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] VM is null - no unlocking 2018-04-09 17:35:37,497+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [b15b479a-c609-4fec-b4c1-ee06cf1c16ed] EVENT_ID: USER_ADD_DISK_FINISHED_SUCCESS(2,021), The disk 'snapshot_memory' was successfully added. 2018-04-09 17:35:37,503+03 WARN [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] Trying to release exclusive lock which does not exist, lock key: '34eeb56c-a452-49e7-baca-7c0e5b6d996fVM' 2018-04-09 17:35:37,504+03 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] Lock freed to object 'EngineLock:{exclusiveLocks='[34eeb56c-a452-49e7-baca-7c0e5b6d996f=VM]', sharedLocks=''}' 2018-04-09 17:35:37,534+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-27) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_FAILURE(69), Failed to complete snapshot 's1' creation for VM 'vm'.