Created attachment 1272597 [details]
engine and vdsm logs

Description of problem:
Clone VM from snapshot fails with error code 261.

From engine.log:
2017-04-19 15:29:32,131+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler4) [59fa7915] Failed in 'HSMGetAllTasksStatusesVDS' method
2017-04-19 15:29:32,181+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler4) [59fa7915] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM host_mixed_1 command HSMGetAllTasksStatusesVDS failed: low level Image copy failed
2017-04-19 15:29:32,182+03 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler4) [59fa7915] SPMAsyncTask::PollTask: Polling task '6f308714-e66c-4f1e-8965-2df12fdc74b7' (Parent Command 'AddVmFromSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2017-04-19 15:29:32,209+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler4) [59fa7915] BaseAsyncTask::logEndTaskFailure: Task '6f308714-e66c-4f1e-8965-2df12fdc74b7' (Parent Command 'AddVmFromSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanSuccess'
-- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = low level Image copy failed, code = 261',
-- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = low level Image copy failed, code = 261'
2017-04-19 15:29:32,215+03 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler4) [59fa7915] CommandAsyncTask::endActionIfNecessary: All tasks of command '54422280-834a-4270-b4ec-5cc6a8c254d6' has ended -> executing 'endAction'
2017-04-19 15:29:32,215+03 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler4) [59fa7915] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '54422280-834a-4270-b4ec-5cc6a8c254d6'): calling endAction '.
2017-04-19 15:29:32,215+03 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-20) [59fa7915] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'AddVmFromSnapshot',
2017-04-19 15:29:32,318+03 ERROR [org.ovirt.engine.core.bll.AddVmFromSnapshotCommand] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] Ending command 'org.ovirt.engine.core.bll.AddVmFromSnapshotCommand' with failure.
2017-04-19 15:29:32,386+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupCommand' with failure.
2017-04-19 15:29:32,415+03 INFO  [org.ovirt.engine.core.bll.storage.disk.image.RemoveImageCommand] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] Running command: RemoveImageCommand internal: true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2017-04-19 15:29:32,881+03 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] START, DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{runAsync='true', storagePoolId='5e97444e-78e5-416e-b42a-666caafadcbf', ignoreFailoverLimit='false', storageDomainId='800914ad-4ee0-4aa3-9451-bfefd87d84af', imageGroupId='8416f193-cbf4-4c09-99c7-94227fbe9a4f', postZeros='false', discard='false', forceDelete='false'}), log id: 41c48e8b
2017-04-19 15:29:33,030+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] EVENT_ID: IRS_BROKER_COMMAND_FAILURE(10,803), Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM command DeleteImageGroupVDS failed: Image does not exist in domain: 'image=8416f193-cbf4-4c09-99c7-94227fbe9a4f, domain=800914ad-4ee0-4aa3-9451-bfefd87d84af'
2017-04-19 15:29:33,031+03 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (org.ovirt.thread.pool-7-thread-20) [d31c82f9-fb28-4d9e-afc6-7d52cd2de2b2] Command 'DeleteImageGroupVDSCommand( DeleteImageGroupVDSCommandParameters:{runAsync='true', storagePoolId='5e97444e-78e5-416e-b42a-666caafadcbf', ignoreFailoverLimit='false', storageDomainId='800914ad-4ee0-4aa3-9451-bfefd87d84af', imageGroupId='8416f193-cbf4-4c09-99c7-94227fbe9a4f', postZeros='false', discard='false', forceDelete='false'})' execution failed: IRSGenericException: IRSErrorException: Image does not exist in domain: 'image=8416f193-cbf4-4c09-99c7-94227fbe9a4f, domain=800914ad-4ee0-4aa3-9451-bfefd87d84af'


From vdsm.log:
2017-04-19 15:29:25,953+0300 INFO  (tasks/0) [storage.Image] sdUUID=800914ad-4ee0-4aa3-9451-bfefd87d84af vmUUID= srcImgUUID=ec1f8a00-a025-4489-b368-1c88be4304ce srcVolUUID=18e1d765-0ffa-480f-9720-80142c418609 dstIm
gUUID=8416f193-cbf4-4c09-99c7-94227fbe9a4f dstVolUUID=d8573794-8851-4ab1-95d7-f3c0109863e3 dstSdUUID=800914ad-4ee0-4aa3-9451-bfefd87d84af volType=8 volFormat=COW preallocate=SPARSE force=False postZero=False discar
d=False (image:801)
2017-04-19 15:29:26,036+0300 ERROR (tasks/0) [storage.Image] Unexpected error (image:879)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/image.py", line 832, in copyCollapsed
    sdUUID, volParams, dstSdUUID. dstVolFormat)
AttributeError: 'str' object has no attribute 'dstVolFormat'
2017-04-19 15:29:26,038+0300 INFO  (tasks/0) [storage.VolumeManifest] Tearing down volume 800914ad-4ee0-4aa3-9451-bfefd87d84af/18e1d765-0ffa-480f-9720-80142c418609 justme False (blockVolume:396)
2017-04-19 15:29:26,039+0300 ERROR (tasks/0) [storage.Image] Unexpected error (image:772)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/image.py", line 768, in __cleanupCopy
    srcVol.teardown(sdUUID=srcVol.sdUUID, volUUID=srcVol.volUUID)
  File "/usr/share/vdsm/storage/volume.py", line 1308, in teardown
    return cls.manifestClass.teardown(sdUUID, volUUID, justme)
  File "/usr/share/vdsm/storage/blockVolume.py", line 399, in teardown
    rm.releaseResource(lvmActivationNamespace, volUUID)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/resourceManager.py", line 1032, in releaseResource
    _manager.releaseResource(namespace, name)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/resourceManager.py", line 584, in releaseResource
    "registered" % (namespace, name))
ValueError: Resource '03_lvm_800914ad-4ee0-4aa3-9451-bfefd87d84af.18e1d765-0ffa-480f-9720-80142c418609' is not currently registered
2017-04-19 15:29:26,041+0300 ERROR (tasks/0) [storage.TaskManager.Task] (Task='6f308714-e66c-4f1e-8965-2df12fdc74b7') Unexpected error (task:871)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 878, in _run
    return fn(*args, **kargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 334, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/securable.py", line 79, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/share/vdsm/storage/sp.py", line 1607, in copyImage
    postZero, force, discard)
  File "/usr/share/vdsm/storage/image.py", line 881, in copyCollapsed
    (dstVolUUID, str(e)))
CopyImageError: low level Image copy failed: ("Destination volume d8573794-8851-4ab1-95d7-f3c0109863e3 error: 'str' object has no attribute 'dstVolFormat'",)



Version-Release number of selected component (if applicable):
oVirt Engine Version: 4.2.0-0.0.master.20170418141347.git09eeed0.el7.centos
vdsm-4.20.0-633.git09421a2.el7.centos.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Create a VM with 1 disk (file or block)
2. Create a snapshot
3. Clone a new VM from the snapshot

Actual results:
The operation fails with "Failed to complete VM cloned_from_snaps_nfs creation."

Expected results:
Cloned VM should work

Additional info:
Regression flag because - bug #1201268