Bug 1443548

Summary: Clone VM from snapshot fails with error = low level Image copy failed, code = 261
Product: [oVirt] ovirt-engine Reporter: Raz Tamir <ratamir>
Component: BLL.StorageAssignee: Liron Aravot <laravot>
Status: CLOSED CURRENTRELEASE QA Contact: Raz Tamir <ratamir>
Severity: high Docs Contact:
Priority: unspecified    
Version: futureCC: amureini, bugs, tnisan
Target Milestone: ovirt-4.2.0Keywords: Automation, Regression
Target Release: ---Flags: rule-engine: ovirt-4.2+
rule-engine: blocker+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-12-20 11:40:40 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
engine and vdsm logs none

Description Raz Tamir 2017-04-19 12:53:26 UTC 
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
Comment 1 Tal Nisan 2017-04-19 19:22:29 UTC 
Liron, please note that it's only broken in master, 4.1 works correctly
Comment 2 Red Hat Bugzilla Rules Engine 2017-04-19 19:22:39 UTC 
This bug report has Keywords: Regression or TestBlocker.
Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP.
Comment 3 Raz Tamir 2017-05-07 13:41:24 UTC 
Can this be moved to ON_QA?
Comment 4 Allon Mureinik 2017-05-08 09:15:46 UTC 
(In reply to Raz Tamir from comment #3)
> Can this be moved to ON_QA?

It's a 4.2 bug.
Since there are no official builds, it cannot be moved to ON_QA.
You could verify it against the upstream master, though, if you wish.
Comment 5 Raz Tamir 2017-05-08 10:56:29 UTC 
Verified on ovirt-engine-4.2.0-0.0.master.20170502114329.git820f2f4.el7.centos

Ran tier 1, 2, 3 of all our clone VM from snapshot TP
Comment 6 Sandro Bonazzola 2017-12-20 11:40:40 UTC 
This bugzilla is included in oVirt 4.2.0 release, published on Dec 20th 2017.

Since the problem described in this bug report should be
resolved in oVirt 4.2.0 release, published on Dec 20th 2017, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.