Description of problem: When creating a snapshot with memory there are two additional disks created, memory disk and a metadata disk. If we fail after their creation is completed they will be removed from the engine but remain on the storage Version-Release number of selected component (if applicable): How reproducible: 100% Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info: There is an attempt to remove them but it fails because the task creating the volume is already cleared and the revert attempt fails: 2018-04-18 14:19:27,960+03 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (org.ovirt.thread.pool-6-thread-43) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] CommandMultiAsyncTasks::attachTask: Attaching task '799342fa-8776-4545-bf41-f26f48470f12' to command '0faf9de2-f09f-4346-8cc5-f0dd9fc70822'. 2018-04-18 14:19:27,994+03 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (org.ovirt.thread.pool-6-thread-43) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] Adding task '799342fa-8776-4545-bf41-f26f48470f12' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2018-04-18 14:19:28,034+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-43) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] BaseAsyncTask::startPollingTask: Starting to poll task '799342fa-8776-4545-bf41-f26f48470f12'. 2018-04-18 14:19:31,269+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler6) [2d41f2e9] SPMAsyncTask::PollTask: Polling task '799342fa-8776-4545-bf41-f26f48470f12' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'running'. 2018-04-18 14:19:41,333+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler7) [3512f268] SPMAsyncTask::PollTask: Polling task '799342fa-8776-4545-bf41-f26f48470f12' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2018-04-18 14:19:41,342+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler7) [3512f268] BaseAsyncTask::onTaskEndSuccess: Task '799342fa-8776-4545-bf41-f26f48470f12' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2018-04-18 14:19:41,352+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-47) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '799342fa-8776-4545-bf41-f26f48470f12' 2018-04-18 14:19:41,355+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-47) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='5ad33afd-009f-0144-0197-0000000001de', ignoreFailoverLimit='false', taskId='799342fa-8776-4545-bf41-f26f48470f12'}), log id: 66513807 2018-04-18 14:19:41,356+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-47) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] START, HSMClearTaskVDSCommand(HostName = host, HSMTaskGuidBaseVDSCommandParameters:{runAsync='true', hostId='8c3b55e1-c296-4546-aee6-5b78ab37faf4', taskId='799342fa-8776-4545-bf41-f26f48470f12'}), log id: 46e22134 2018-04-18 14:19:41,456+03 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-6-thread-47) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] BaseAsyncTask::removeTaskFromDB: Removed task '799342fa-8776-4545-bf41-f26f48470f12' from DataBase 2018-04-18 14:21:38,608+03 WARN [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler2) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] Polling tasks. Task ID '799342fa-8776-4545-bf41-f26f48470f12' doesn't exist in the manager -> assuming 'finished'. 2018-04-18 14:21:38,613+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMRevertTaskVDSCommand] (DefaultQuartzScheduler2) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] START, SPMRevertTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{runAsync='true', storagePoolId='5ad33afd-009f-0144-0197-0000000001de', ignoreFailoverLimit='false', taskId='799342fa-8776-4545-bf41-f26f48470f12'}), log id: 12c42fb7 2018-04-18 14:21:38,641+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMRevertTaskVDSCommand] (DefaultQuartzScheduler2) [257ecc4d-c7e0-4529-9a1d-e321dcdc16e0] Trying to revert unknown task '799342fa-8776-4545-bf41-f26f48470f12' In Vdsm: 2018-04-18 14:19:28,195+0300 INFO (jsonrpc/5) [vdsm.api] START createVolume(sdUUID=u'edc4aa26-e4f4-41d5-b325-6ec6fd7da9bb', spUUID=u'5ad33afd-009f-0144-0197-0000000001de', imgUUID=u'4863bfdb-dce5-4fbf-bc09-fad1aee22eaf', size=u'10240', volFormat=5, preallocate=1, diskType=2, volUUID=u'e5cbf97e-f7f1-4bd6-a90d-adc0165e201d', desc=u'{"DiskAlias":"snapshot_metadata","DiskDescription":""}', srcImgUUID=u'00000000-0000-0000-0000-000000000000', srcVolUUID=u'00000000-0000-0000-0000-000000000000', initialSize=None) from=::ffff:10.35.206.92,56174, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=6e4b2753-e341-4327-be49-228e1a6a6683 (api:47) 2018-04-18 14:19:28,496+0300 INFO (tasks/4) [storage.Volume] Changing volume u'/rhev/data-center/mnt/10.35.0.233:_root_storage__domains_sd5/edc4aa26-e4f4-41d5-b325-6ec6fd7da9bb/images/b83c1346-22a8-47ec-833d-6031603e8b99/d750c1a9-7be3-4b67-aada-f3bd93c74282' permission to 0660 (fileVolume:478) 2018-04-18 14:19:28,523+0300 INFO (jsonrpc/5) [vdsm.api] FINISH createVolume return=None from=::ffff:10.35.206.92,56174, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=6e4b2753-e341-4327-be49-228e1a6a6683 (api:53) 2018-04-18 14:19:28,727+0300 INFO (tasks/1) [storage.Volume] Creating volume 97e38253-dc90-4a35-b8ef-df96d25627f2 (volume:1192) 2018-04-18 14:19:29,005+0300 INFO (periodic/3) [vdsm.api] START getVolumeSize(sdUUID=u'edc4aa26-e4f4-41d5-b325-6ec6fd7da9bb', spUUID=u'5ad33afd-009f-0144-0197-0000000001de', imgUUID=u'b83c1346-22a8-47ec-833d-6031603e8b99', volUUID=u'67bffbc4-48bd-4797-9a09-a40c7ca72f56', options=None) from=internal, task_id=4c1637aa-def9-426d-bf0e-cfc7e0b9e1d9 (api:47) 2018-04-18 14:19:29,007+0300 INFO (periodic/3) [vdsm.api] FINISH getVolumeSize return={'truesize': '0', 'apparentsize': '1073741824'} from=internal, task_id=4c1637aa-def9-426d-bf0e-cfc7e0b9e1d9 (api:53) 2018-04-18 14:19:29,151+0300 INFO (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Volume.create succeeded in 0.96 seconds (__init__:311) 2018-04-18 14:19:29,151+0300 INFO (tasks/6) [storage.ThreadPool.WorkerThread] START task 6e4b2753-e341-4327-be49-228e1a6a6683 (cmd=<bound method Task.commit of <vdsm.storage.task.Task instance at 0x7fecec04a5f0>>, args=None) (threadPool:208) ------------- Revert attempt -------------------------- 2018-04-18 14:21:38,625+0300 INFO (jsonrpc/7) [vdsm.api] START revertTask(taskID=u'799342fa-8776-4545-bf41-f26f48470f12', spUUID=None, options=Non e) from=::ffff:10.35.206.92,56874, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=190fd7fd-fbe2-44cf-90c6-d0fa53a4a112 (api:47) 2018-04-18 14:21:38,625+0300 INFO (jsonrpc/7) [vdsm.api] FINISH revertTask error=Task id unknown: (u'799342fa-8776-4545-bf41-f26f48470f12',) from= ::ffff:10.35.206.92,56874, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=190fd7fd-fbe2-44cf-90c6-d0fa53a4a112 (api:51) 2018-04-18 14:21:38,625+0300 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='190fd7fd-fbe2-44cf-90c6-d0fa53a4a112') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in revertTask File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 49, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2288, in revertTask return self.taskMng.revertTask(taskID=taskID) File "/usr/lib/python2.7/site-packages/vdsm/storage/taskManager.py", line 165, in revertTask t = self.__getTask(taskID) File "/usr/lib/python2.7/site-packages/vdsm/storage/taskManager.py", line 85, in __getTask raise se.UnknownTask(taskID) UnknownTask: Task id unknown: (u'799342fa-8776-4545-bf41-f26f48470f12',) 2018-04-18 14:21:38,625+0300 INFO (jsonrpc/7) [storage.TaskManager.Task] (Task='190fd7fd-fbe2-44cf-90c6-d0fa53a4a112') aborting: Task is aborted: u"Task id unknown: (u'799342fa-8776-4545-bf41-f26f48470f12',)" - code 100 (task:1181) 2018-04-18 14:21:38,625+0300 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH revertTask error=Task id unknown: (u'799342fa-8776-4545-bf41-f26f48470f1 2',) (dispatcher:82) 2018-04-18 14:21:38,625+0300 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Task.revert failed (error 401) in 0.00 seconds (__init__:311) 2018-04-18 14:21:38,789+0300 INFO (jsonrpc/3) [vdsm.api] START revertTask(taskID=u'6e4b2753-e341-4327-be49-228e1a6a6683', spUUID=None, options=Non e) from=::ffff:10.35.206.92,56874, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=989bb575-c599-4ef9-b23f-f14cb17cee99 (api:47) 2018-04-18 14:21:38,789+0300 INFO (jsonrpc/3) [vdsm.api] FINISH revertTask error=Task id unknown: (u'6e4b2753-e341-4327-be49-228e1a6a6683',) from=::ffff:10.35.206.92,56874, flow_id=257ecc4d-c7e0-4529-9a1d-e321dcdc16e0, task_id=989bb575-c599-4ef9-b23f-f14cb17cee99 (api:51)
Severity... ?
(In reply to Yaniv Kaul from comment #1) > Severity... ? Not a regression and very much corner case since the failure is after all the storage operations are completed successfully but something is wrong with the database connection, setting severity to low
Closing old bugs, reopen if still needed.