Bug 1448606 - Creating template from VM with converted disk format fails only on iscsi SD - RAW to QCOW
Summary: Creating template from VM with converted disk format fails only on iscsi SD -...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: vdsm
Classification: oVirt
Component: Core
Version: 4.19.12
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.1.2
: ---
Assignee: Fred Rolland
QA Contact: Raz Tamir
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-05-05 23:23 UTC by Raz Tamir
Modified: 2017-05-23 08:22 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-05-23 08:22:30 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.1+
rule-engine: blocker+

Attachments (Terms of Use)
engine and vdsm logs (1.63 MB, application/x-gzip)
2017-05-05 23:23 UTC, Raz Tamir 		no flags Details
new engine and vdsm logs (938.61 KB, application/x-gzip)
2017-05-15 13:20 UTC, Raz Tamir 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 76578 0 master MERGED image: prepare volume before calculating size 2017-05-10 21:31:29 UTC
oVirt gerrit 76670 0 ovirt-4.1 MERGED image: prepare volume before calculating size 2017-05-11 11:55:02 UTC
oVirt gerrit 76883 0 master MERGED image: estimate_qcow2_size max size calculation 2017-05-18 11:32:35 UTC
oVirt gerrit 76886 0 master ABANDONED image: add tests for estimate_qcow2_size 2018-09-16 01:58:48 UTC
oVirt gerrit 76987 0 ovirt-4.1 MERGED image: estimate_qcow2_size max size calculation 2017-05-18 11:55:05 UTC

Description Raz Tamir 2017-05-05 23:23:51 UTC 
Created attachment 1276710 [details]
engine and vdsm logs

Description of problem:
Creation of template from VM with RAW disk will fail in case the template disk's format will be selected as qcow

From emgine.log:

2017-05-06 02:04:31,803+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler7) [] 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-05-06 02:04:31,804+03 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler7) [] Task id '2442027a-8ad4-424b-80a8-9bc070a59bc3' has passed pre-polling period time and should be polled. Pre-polling period is 60000 millis. 
2017-05-06 02:04:31,804+03 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler7) [] SPMAsyncTask::PollTask: Polling task '2442027a-8ad4-424b-80a8-9bc070a59bc3' (Parent Command 'CreateAllTemplateDisks', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2017-05-06 02:04:31,804+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler7) [] BaseAsyncTask::logEndTaskFailure: Task '2442027a-8ad4-424b-80a8-9bc070a59bc3' (Parent Command 'CreateAllTemplateDisks', 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'

from vdsm.log:

2017-05-06 01:02:47,307+0300 ERROR (tasks/2) [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)
  File "/usr/share/vdsm/storage/image.py", line 971, in calculate_vol_alloc
    return self.estimate_qcow2_size(src_vol_params, dst_sd_id)
  File "/usr/share/vdsm/storage/image.py", line 184, in estimate_qcow2_size
    estimated_size = qcow2.estimate_size(src_vol_params['path'])
  File "/usr/lib/python2.7/site-packages/vdsm/storage/qcow2.py", line 153, in estimate_size
    info = qemuimg.info(filename)
  File "/usr/lib/python2.7/site-packages/vdsm/qemuimg.py", line 94, in info
    out = _run_cmd(cmd)
  File "/usr/lib/python2.7/site-packages/vdsm/qemuimg.py", line 416, in _run_cmd
    raise QImgError(cmd, rc, out, err)
QImgError: cmd=['/usr/bin/qemu-img', 'info', '--output', 'json', '/rhev/data-center/06b8b5b0-5e8c-4d5b-a6dd-80e2e570b5e7/d1854a98-2e13-49e2-a741-46cfa2d33482/images/c095f6cf-1f49-4dcd-bfa4-e707350c9b1f/2893560e-0959-46c1-adf6-d48236ae62d5'], ecode=1, stdout=, stderr=qemu-img: Could not open '/rhev/data-center/06b8b5b0-5e8c-4d5b-a6dd-80e2e570b5e7/d1854a98-2e13-49e2-a741-46cfa2d33482/images/c095f6cf-1f49-4dcd-bfa4-e707350c9b1f/2893560e-0959-46c1-adf6-d48236ae62d5': Could not open '/rhev/data-center/06b8b5b0-5e8c-4d5b-a6dd-80e2e570b5e7/d1854a98-2e13-49e2-a741-46cfa2d33482/images/c095f6cf-1f49-4dcd-bfa4-e707350c9b1f/2893560e-0959-46c1-adf6-d48236ae62d5': No such file or directory
, message=None
2017-05-06 01:02:47,310+0300 INFO  (tasks/2) [storage.VolumeManifest] Tearing down volume d1854a98-2e13-49e2-a741-46cfa2d33482/2893560e-0959-46c1-adf6-d48236ae62d5 justme False (blockVolume:399)
2017-05-06 01:02:47,311+0300 DEBUG (tasks/2) [storage.ResourceManager] Trying to release resource '03_lvm_d1854a98-2e13-49e2-a741-46cfa2d33482.2893560e-0959-46c1-adf6-d48236ae62d5' (resourceManager:566)
2017-05-06 01:02:47,312+0300 ERROR (tasks/2) [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 1321, in teardown
    return cls.manifestClass.teardown(sdUUID, volUUID, justme)
  File "/usr/share/vdsm/storage/blockVolume.py", line 402, in teardown
    rm.releaseResource(lvmActivationNamespace, volUUID)
  File "/usr/share/vdsm/storage/resourceManager.py", line 1029, in releaseResource
    _manager.releaseResource(namespace, name)
  File "/usr/share/vdsm/storage/resourceManager.py", line 581, in releaseResource
    "registered" % (namespace, name))
ValueError: Resource '03_lvm_d1854a98-2e13-49e2-a741-46cfa2d33482.2893560e-0959-46c1-adf6-d48236ae62d5' is not currently registered


From lvs on the host I can see that the "problematic" lv, 2893560e-0959-46c1-adf6-d48236ae62d5, is not active and might be the cause for "No such file or directory error"

[root@storage-ge5-vdsm1 ~]# lvs
  LV                                   VG                                   Attr       LSize   Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  061634ff-ccf0-447a-a502-943a91d4368d d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-------   1.00g                                                    
  21d17ff8-52bb-4bf9-89ee-1c5c7a964926 d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-------   1.00g                                                    
  2893560e-0959-46c1-adf6-d48236ae62d5 d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-------   1.00g                                                    
  33729811-6c1b-4efb-9279-634b3320a749 d1854a98-2e13-49e2-a741-46cfa2d33482 -wi------- 128.00m                                                    
  3911350e-8212-4a8b-bb9f-92665280e898 d1854a98-2e13-49e2-a741-46cfa2d33482 -wi------- 128.00m                                                    
  6775371d-2893-4dd1-955c-2bc1f5e49360 d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-------   6.00g                                                    
  ids                                  d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-ao---- 128.00m                                                    
  inbox                                d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a----- 128.00m                                                    
  leases                               d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a-----   2.00g                                                    
  master                               d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a-----   1.00g                                                    
  metadata                             d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a----- 512.00m                                                    
  outbox                               d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a----- 128.00m                                                    
  xleases                              d1854a98-2e13-49e2-a741-46cfa2d33482 -wi-a-----   1.00g                                                    

* Marking as regression because of bug #1435967


Version-Release number of selected component (if applicable):
vdsm-4.19.12-1.el7ev.x86_64
ovirt-engine-4.1.2.1-0.1.el7.noarch

How reproducible:
100%

Steps to Reproduce:
1. Create a VM with 1 RAW preallocated disk
2. Create template from that VM and select the format as qcow
3.

Actual results:
operation failed

Expected results:


Additional info:
Comment 1 Allon Mureinik 2017-05-07 14:19:10 UTC 
This is troubling... Fred, can you take a look please?
Comment 2 Red Hat Bugzilla Rules Engine 2017-05-07 14:19:15 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 Fred Rolland 2017-05-08 07:49:10 UTC 
Looking at it
Comment 4 rhev-integ 2017-05-12 15:10:46 UTC 
INFO: Bug status wasn't changed from MODIFIED to ON_QA due to the following reason:

[Tag 'v4.19.14' doesn't contain patch 'https://gerrit.ovirt.org/76670']
gitweb: https://gerrit.ovirt.org/gitweb?p=vdsm.git;a=shortlog;h=refs/tags/v4.19.14

For more info please contact: infra
Comment 5 Anton Marchukov 2017-05-13 09:59:12 UTC 
The tag v4.19.14 does contain the patch https://gerrit.ovirt.org/76670
Moving to ON_QA
Comment 6 Raz Tamir 2017-05-14 11:46:34 UTC 
Verified on rhevm-4.1.2.2-0.1.el7.

Ran relevant TPs in automation (tier1/2/3) - Passed
Comment 7 Raz Tamir 2017-05-15 12:53:47 UTC 
We still see this issue - will test again before reopen
Comment 8 Raz Tamir 2017-05-15 13:19:36 UTC 
Tested on 3 different environments with:
- ovirt-engine-4.1.2.2-0.1.el7.noarch
- vdsm-4.19.14-1.el7ev.x86_64

From engine.log:

2017-05-15 16:00:54,664+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler8) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: VDSM host_mixed_3 command HSMGetAllTasksStatusesVDS failed: low level Image copy failed
2017-05-15 16:00:54,664+03 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler8) [] Task id 'f4c801f3-3180-4335-9b60-a3e8202ec3bc' has passed pre-polling period time and should be polled. Pre-polling period is 60000 millis. 
2017-05-15 16:00:54,664+03 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler8) [] SPMAsyncTask::PollTask: Polling task 'f4c801f3-3180-4335-9b60-a3e8202ec3bc' (Parent Command 'CreateAllTemplateDisks', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2017-05-15 16:00:54,666+03 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler8) [] BaseAsyncTask::logEndTaskFailure: Task 'f4c801f3-3180-4335-9b60-a3e8202ec3bc' (Parent Command 'CreateAllTemplateDisks', 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-05-15 16:00:54,666+03 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler8) [] Task with DB Task ID 'e2db4747-f491-46cd-936f-4554a562e66c' and VDSM Task ID '1728d7f0-598a-4057-acaf-e4aa0a85739c' is in state Polling. End action for command 10a8b21f-6010-43cc-a458-719a048b88f4 will proceed when all the entity's tasks are completed.


From vdsm.log:
2017-05-15 15:03:13,800+0300 ERROR (jsonrpc/2) [storage.HSM] Empty or not found image f63fabda-92b2-471e-892d-4916c2f4c683 in SD d1854a98-2e13-49e2-a741-46cfa2d33482. {'33729811-6c1b-4efb-9279-634b3320a749': ImgsPa
r(imgs=['42b0d169-5dc1-420e-a5c5-8d21650519a2'], parent='00000000-0000-0000-0000-000000000000'), 'f5b259cb-8ea8-4bd1-9a58-5655c3651693': ImgsPar(imgs=['72a6312c-128c-48ec-b77c-5c0a5f8f85ac'], parent='00000000-0000-
0000-0000-000000000000'), '061634ff-ccf0-447a-a502-943a91d4368d': ImgsPar(imgs=['df0de6cf-1088-4499-a914-1c557a6a6119'], parent='6775371d-2893-4dd1-955c-2bc1f5e49360'), '9c03520d-03b0-4bd5-88d4-0b4fe6c816a2': ImgsP
ar(imgs=['3e181891-3b8d-4729-8982-9845c5abde16'], parent='00000000-0000-0000-0000-000000000000'), '3911350e-8212-4a8b-bb9f-92665280e898': ImgsPar(imgs=['7798142c-71e4-42fd-88b3-ab959d3bc87b'], parent='00000000-0000
-0000-0000-000000000000'), '21d17ff8-52bb-4bf9-89ee-1c5c7a964926': ImgsPar(imgs=['6c07ceda-c6f9-41ba-9bd4-85a37a80cfd5'], parent='6775371d-2893-4dd1-955c-2bc1f5e49360'), '0e344629-2433-4f99-b9eb-e32fa880723a': Imgs
Par(imgs=['c148d186-e0ee-41aa-b5e1-63ae4405ee0c'], parent='6775371d-2893-4dd1-955c-2bc1f5e49360'), '7e2b926b-fd2f-465f-8d95-c612690926b6': ImgsPar(imgs=['ce77191b-010f-43de-beb1-303cff9da90a'], parent='00000000-000
0-0000-0000-000000000000'), '6775371d-2893-4dd1-955c-2bc1f5e49360': ImgsPar(imgs=['99ae5405-5d8a-4a31-977a-8221b1017d89', 'df0de6cf-1088-4499-a914-1c557a6a6119', '6c07ceda-c6f9-41ba-9bd4-85a37a80cfd5', 'c148d186-e0
ee-41aa-b5e1-63ae4405ee0c'], parent='00000000-0000-0000-0000-000000000000')} (hsm:1455)
2017-05-15 15:03:13,801+0300 ERROR (jsonrpc/2) [storage.TaskManager.Task] (Task='5bf7655d-4f5d-44a0-85a9-dde0a4b912f1') Unexpected error (task:870)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 877, in _run
    return fn(*args, **kargs)
  File "/usr/lib/python2.7/site-packages/vdsm/logUtils.py", line 52, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 1456, in deleteImage
    raise se.ImageDoesNotExistInSD(imgUUID, sdUUID)
ImageDoesNotExistInSD: Image does not exist in domain: 'image=f63fabda-92b2-471e-892d-4916c2f4c683, domain=d1854a98-2e13-49e2-a741-46cfa2d33482'


***** There are mismach in timezones so ignore the differences in times between engine and vdsm
Comment 9 Red Hat Bugzilla Rules Engine 2017-05-15 13:19:41 UTC 
Target release should be placed once a package build is known to fix a issue. Since this bug is not modified, the target version has been reset. Please use target milestone to plan a fix for a oVirt release.
Comment 10 Raz Tamir 2017-05-15 13:20:13 UTC 
Created attachment 1278996 [details]
new engine and vdsm logs
Comment 11 rhev-integ 2017-05-18 14:56:01 UTC 
INFO: Bug status wasn't changed from MODIFIED to ON_QA due to the following reason:

[Open patch attached]

For more info please contact: infra
Comment 12 Raz Tamir 2017-05-20 22:19:10 UTC 
Verified on vdsm-4.19.15-1.el7ev.x86_64
Note You need to log in before you can comment on or make changes to this bug.