Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be available on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1568887 - If creation of a snapshot with memory fails, the memory disks will remain on the storage
Summary: If creation of a snapshot with memory fails, the memory disks will remain on ...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: future
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ovirt-4.3.0
: ---
Assignee: Benny Zlotnik
QA Contact: Elad
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-04-18 11:32 UTC by Benny Zlotnik
Modified: 2018-09-03 08:54 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-09-03 08:54:17 UTC
oVirt Team: Storage
rule-engine: ovirt-4.3+

Attachments (Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Description Benny Zlotnik 2018-04-18 11:32:29 UTC 
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)
Comment 1 Yaniv Kaul 2018-04-22 07:56:28 UTC 
Severity... ?
Comment 2 Tal Nisan 2018-04-22 08:12:50 UTC 
(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
Comment 3 Tal Nisan 2018-09-03 08:54:17 UTC 
Closing old bugs, reopen if still needed.
Note You need to log in before you can comment on or make changes to this bug.