Created attachment 1119908 [details]
engine logs

Description of problem:
When undoing a snapshot, the job is reported as successful and is cleared from the list of running jobs. It make take a few extra seconds to clear the task, and the gap between the running jobs and the active tasks can cause failures in powering on VM (as an example)

Version-Release number of selected component (if applicable):
3.6.2.6-0.1

How reproducible:
50%

Steps to Reproduce:
1. Create a VM
2. Create a snapshot
3. Preview snapshot
4. Undo snapshot
5. Note the time that the job is reported as completed, and compare with the time that the task is cleared

Actual results:
There may be a gap of a few seconds between the completion times. This causes a failure on our Live merge tests since we ensure that the relevant snapshot jobs have been completed

Expected results:


Additional info:

engine.log relevant info (also attached, in addition all host logs):
2016-01-31 00:53:00,426 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-6) [1b7afe7c] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'RestoreFromSnapshot', executionIndex: '0'
2016-01-31 00:53:00,436 INFO  [org.ovirt.engine.core.bll.RestoreFromSnapshotCommand] (org.ovirt.thread.pool-7-thread-11) [55ea723c] Ending command 'org.ovirt.engine.core.bll.RestoreFromSnapshotCommand' successfully.
2016-01-31 00:53:00,441 INFO  [org.ovirt.engine.core.bll.RestoreFromSnapshotCommand] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] Ending command 'org.ovirt.engine.core.bll.RestoreFromSnapshotCommand' successfully.
2016-01-31 00:53:00,445 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-11) [55ea723c] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'RestoreFromSnapshot' completed, handling the result.
2016-01-31 00:53:00,445 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-11) [55ea723c] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'RestoreFromSnapshot' succeeded, clearing tasks.
2016-01-31 00:53:00,446 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'RestoreFromSnapshot' completed, handling the result.
2016-01-31 00:53:00,446 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'RestoreFromSnapshot' succeeded, clearing tasks.
2016-01-31 00:53:00,449 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-11) [55ea723c] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '8a18228b-790f-4aa8-8b4d-5d320122ce0b'
2016-01-31 00:53:00,450 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-11) [55ea723c] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='ed6c80c2-e546-4658-987c-4271740a8291', ignoreFailoverLimit='false', taskId='8a18228b-790f-4aa8-8b4d-5d320122ce0b'}), log id: 65184163
2016-01-31 00:53:00,450 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '61a6be12-1614-4977-b3a6-c9d4a0168454'
2016-01-31 00:53:00,451 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='ed6c80c2-e546-4658-987c-4271740a8291', ignoreFailoverLimit='false', taskId='61a6be12-1614-4977-b3a6-c9d4a0168454'}), log id: 10b4377a
2016-01-31 00:53:00,451 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-11) [55ea723c] START, HSMClearTaskVDSCommand(HostName = host_mixed_3, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='c2e9c875-391b-4707-acb0-4da7d1dcbb2d', taskId='8a18228b-790f-4aa8-8b4d-5d320122ce0b'}), log id: 1b6cfe6f
2016-01-31 00:53:01,359 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-11) [55ea723c] FINISH, HSMClearTaskVDSCommand, log id: 1b6cfe6f
2016-01-31 00:53:01,359 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-11) [55ea723c] FINISH, SPMClearTaskVDSCommand, log id: 65184163
2016-01-31 00:53:01,360 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] START, HSMClearTaskVDSCommand(HostName = host_mixed_3, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='c2e9c875-391b-4707-acb0-4da7d1dcbb2d', taskId='61a6be12-1614-4977-b3a6-c9d4a0168454'}), log id: 196bf4b4
2016-01-31 00:53:01,364 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-11) [55ea723c] BaseAsyncTask::removeTaskFromDB: Removed task '8a18228b-790f-4aa8-8b4d-5d320122ce0b' from DataBase
2016-01-31 00:53:01,364 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-11) [55ea723c] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'fc547382-e6e6-4c0b-9d2e-0a06ea6d9a88'
2016-01-31 00:53:01,957 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8702-10) [vms_delete_121d5e52-7bd7-4685] Lock Acquired to object 'EngineLock:{exclusiveLocks='[526e74d4-cb48-423c-a03d-9232e004b906=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
2016-01-31 00:53:02,006 WARN  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8702-10) [vms_delete_121d5e52-7bd7-4685] CanDoAction of action 'RemoveVm' failed for user admin@internal. Reasons: VAR__ACTION__REMOVE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VM_IS_DURING_SNAPSHOT
2016-01-31 00:53:02,006 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8702-10) [vms_delete_121d5e52-7bd7-4685] Lock freed to object 'EngineLock:{exclusiveLocks='[526e74d4-cb48-423c-a03d-9232e004b906=<VM, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
2016-01-31 00:53:02,011 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8702-10) [] Operation Failed: [Cannot remove VM. The VM is performing an operation on a Snapshot. Please wait for the operation to finish, and try again.]
2016-01-31 00:53:02,310 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (DefaultQuartzScheduler_Worker-72) [a0f87b2] Command 'RestoreAllSnapshots' id: 'b0eda3fa-d100-4230-8b0a-a12782313309' child commands '[fc547382-e6e6-4c0b-9d2e-0a06ea6d9a88, afe87a10-47d9-4dce-8f8e-722901b1c33b]' executions were completed, status 'SUCCEEDED'
2016-01-31 00:53:02,384 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] FINISH, HSMClearTaskVDSCommand, log id: 196bf4b4
2016-01-31 00:53:02,384 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] FINISH, SPMClearTaskVDSCommand, log id: 10b4377a
2016-01-31 00:53:02,387 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] BaseAsyncTask::removeTaskFromDB: Removed task '61a6be12-1614-4977-b3a6-c9d4a0168454' from DataBase
2016-01-31 00:53:02,387 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-6) [a0f87b2] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'afe87a10-47d9-4dce-8f8e-722901b1c33b'
2016-01-31 00:53:03,320 INFO  [org.ovirt.engine.core.bll.RestoreAllSnapshotsCommand] (DefaultQuartzScheduler_Worker-63) [a0f87b2] Ending command 'org.ovirt.engine.core.bll.RestoreAllSnapshotsCommand' successfully.