Bug 1270003 - Failed to import vm template
Summary: Failed to import vm template
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine
Version: 3.6.0
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: ovirt-3.6.0-rc3
: 3.6.0
Assignee: Martin Mucha
QA Contact: Michael Burman
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-10-08 18:25 UTC by Israel Pinto
Modified: 2016-04-20 01:37 UTC (History)
28 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-04-20 01:37:13 UTC
oVirt Team: Network
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
engine_log (293.83 KB, application/zip)
2015-10-08 18:29 UTC, Israel Pinto 		no flags Details
vdsm_log (1.45 MB, application/zip)
2015-10-08 18:30 UTC, Israel Pinto 		no flags Details
engine.log x86 (295.24 KB, text/plain)
2015-10-26 22:19 UTC, Carlos Mestre González 		no flags Details
vdsm.log x86 (7.27 MB, text/plain)
2015-10-26 22:22 UTC, Carlos Mestre González 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 47880 0 master MERGED core: fixing NPE when importing nic with null valued mac Never
oVirt gerrit 47881 0 ovirt-engine-3.6 ABANDONED core: nic with null valued mac cannot be plugged into DC. Never
oVirt gerrit 47932 0 ovirt-engine-3.6 MERGED core: fixing NPE when importing nic with null valued mac Never
oVirt gerrit 47933 0 ovirt-engine-3.6.0 MERGED core: fixing NPE when importing nic with null valued mac Never

Description Israel Pinto 2015-10-08 18:25:25 UTC 
Description of problem:
Failed to import template form export domain
Note: Check with non PPC host and it working

Version-Release number of selected component (if applicable):
PPC setup:
RHEVM: rhevm-3.6.0-0.18.el6
VDSM: vdsm-4.17.8-1.el7ev
libvirt: vdsm-4.17.8-1.el7ev

How reproducible:
All the time

 
Steps to Reproduce:
1. Export domain with template
2. Import template via GUI

Actual results:
Failed to import template,
From engine event log:
  Failed to complete copy of Template golden_env_ppc_template to Domain <UNKNOWN>.
From vdsm log:
 File "/usr/share/vdsm/storage/image.py", line 859, in copyCollapsed
    (srcImgUUID, dstImgUUID, str(e)))

Note: See below more info.



Expected results:
Import should succeed 

Additional info:
From engine log:
2015-10-08 14:36:26,132 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-80) [] SPMAsyncTask::PollTask: Polling task '2b75ff2e-723f-43d6-9d37-039a67b79f35' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'cleanSuccess'.
2015-10-08 14:36:26,168 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-80) [] BaseAsyncTask::logEndTaskFailure: Task '2b75ff2e-723f-43d6-9d37-039a67b79f35' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure:
-- Result: 'cleanSuccess'
-- Message: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = 2b75ff2e-723f-43d6-9d37-039a67b79f35',
-- Exception: 'VDSGenericException: VDSErrorException: Failed in vdscommand to HSMGetAllTasksStatusesVDS, error = 2b75ff2e-723f-43d6-9d37-039a67b79f35'
2015-10-08 14:36:26,396 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-80) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'd0162124-e42a-43f2-bdbb-75af093821d6' has ended -> executing 'endAction'
2015-10-08 14:36:26,396 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-80) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'd0162124-e42a-43f2-bdbb-75af093821d6'): calling endAction '.
2015-10-08 14:36:26,396 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-28) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'ImportVmTemplate', executionIndex: '0'
2015-10-08 14:36:26,831 ERROR [org.ovirt.engine.core.bll.ImportVmTemplateCommand] (org.ovirt.thread.pool-7-thread-28) [] Ending command 'org.ovirt.engine.core.bll.ImportVmTemplateCommand' with failure.
2015-10-08 14:36:27,035 ERROR [org.ovirt.engine.core.bll.CopyImageGroupCommand] (org.ovirt.thread.pool-7-thread-28) [76a3396a] Ending command 'org.ovirt.engine.core.bll.CopyImageGroupCommand' with failure.
2015-10-08 14:36:27,047 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetVmsInfoVDSCommand] (ajp-/127.0.0.1:8702-12) [] START, GetVmsInfoVDSCommand( GetVmsInfoVDSCommandParameters:{runAsync='true', storagePoolId='fc6a619b-f98a-4594-86ba-ba4dac253a87', ignoreFailoverLimit='false', storageDomainId='871a92d1-0a98-40ff-a3c8-36ede1ee589c', vmIdList='null'}), log id: 1cd8824
2015-10-08 14:36:27,348 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-7-thread-28) [] Correlation ID: 178d4562, Call Stack: null, Custom Event ID: -1, Message: Failed to complete copy of Template golden_env_ppc_template to Domain <UNKNOWN>.
2015-10-08 14:36:27,348 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-7-thread-28) [] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'ImportVmTemplate' completed, handling the result.

From vdsm log:
Thread-160::DEBUG::2015-10-08 07:36:18,375::task::993::Storage.TaskManager.Task::(_decref) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::ref 0 aborting False
84231190-a720-464a-8cae-406da1b4d7aa::DEBUG::2015-10-08 07:36:18,376::threadPool::51::Storage.ThreadPool::(setRunningTask) Number of running tasks: 1
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,376::threadPool::194::Storage.ThreadPool.WorkerThread::(_processNextTask) Task: 2b75ff2e-723f-43d6-9d37-039a67b79f35 running: <bound method Task.commit of <storage.task.Task instance at 0x3fff081edc20>> with: None
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,376::task::1200::Storage.TaskManager.Task::(commit) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::committing task: 2b75ff2e-723f-43d6-9d37-039a67b79f35
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,376::task::595::Storage.TaskManager.Task::(_updateState) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::moving from state queued -> state running
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,376::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,386::task::905::Storage.TaskManager.Task::(_runJobs) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Task.run: running job 0: copyImage_f99d83ec-3a52-4e68-ab2c-67e7863c1288: <bound method StoragePool.copyImage of <storage.sp.StoragePool object at 0x3fff081f3710>> (args: ('871a92d1-0a98-40ff-a3c8-36ede1ee589c', '', 'f99d83ec-3a52-4e68-ab2c-67e7863c1288', 'be5e78f0-c472-4af5-8302-0ca94b908b86', 'f99d83ec-3a52-4e68-ab2c-67e7863c1288', 'be5e78f0-c472-4af5-8302-0ca94b908b86', '', '941b820a-0b82-4b96-8a79-8818d82bbcf0', 6, 5, 2, False, False) kwargs: {})
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,387::task::329::Storage.TaskManager.Task::(run) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Job.run: running copyImage_f99d83ec-3a52-4e68-ab2c-67e7863c1288: <bound method StoragePool.copyImage of <storage.sp.StoragePool object at 0x3fff081f3710>> (args: ('871a92d1-0a98-40ff-a3c8-36ede1ee589c', '', 'f99d83ec-3a52-4e68-ab2c-67e7863c1288', 'be5e78f0-c472-4af5-8302-0ca94b908b86', 'f99d83ec-3a52-4e68-ab2c-67e7863c1288', 'be5e78f0-c472-4af5-8302-0ca94b908b86', '', '941b820a-0b82-4b96-8a79-8818d82bbcf0', 6, 5, 2, False, False) kwargs: {}) callback None
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,387::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288`ReqID=`90e4b0b0-7487-4d6a-94c4-e67f7a6ba8be`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1505' at 'copyImage'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,387::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' for lock type 'shared'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,389::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,390::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86`ReqID=`6e64c3fc-a0b9-462f-a925-4634c5f1b367`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '164' at '__getResourceCandidatesList'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86' for lock type 'shared'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::601::Storage.ResourceManager::(registerResource) Resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86' is free. Now locking as 'shared' (1 active user)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86`ReqID=`6e64c3fc-a0b9-462f-a925-4634c5f1b367`::Granted request
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::601::Storage.ResourceManager::(registerResource) Resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' is free. Now locking as 'shared' (1 active user)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,393::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288`ReqID=`90e4b0b0-7487-4d6a-94c4-e67f7a6ba8be`::Granted request
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,394::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288`ReqID=`8642e9e8-fdd1-4dba-bdba-d217fc21cd96`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1507' at 'copyImage'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,394::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' for lock type 'exclusive'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,395::resourceFactories::125::Storage.ResourcesFactories::(__getResourceCandidatesList) Image f99d83ec-3a52-4e68-ab2c-67e7863c1288 does not exist in domain 941b820a-0b82-4b96-8a79-8818d82bbcf0
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,395::resourceManager::601::Storage.ResourceManager::(registerResource) Resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' is free. Now locking as 'exclusive' (1 active user)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,395::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288`ReqID=`8642e9e8-fdd1-4dba-bdba-d217fc21cd96`::Granted request
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,395::image::731::Storage.Image::(copyCollapsed) sdUUID=871a92d1-0a98-40ff-a3c8-36ede1ee589c vmUUID= srcImgUUID=f99d83ec-3a52-4e68-ab2c-67e7863c1288 srcVolUUID=be5e78f0-c472-4af5-8302-0ca94b908b86 dstImgUUID=f99d83ec-3a52-4e68-ab2c-67e7863c1288 dstVolUUID=be5e78f0-c472-4af5-8302-0ca94b908b86 dstSdUUID=941b820a-0b82-4b96-8a79-8818d82bbcf0 volType=6 volFormat=RAW preallocate=SPARSE force=False postZero=False
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,395::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,403::image::781::Storage.Image::(copyCollapsed) copy source 871a92d1-0a98-40ff-a3c8-36ede1ee589c:f99d83ec-3a52-4e68-ab2c-67e7863c1288:be5e78f0-c472-4af5-8302-0ca94b908b86 vol size 20971520 destination 941b820a-0b82-4b96-8a79-8818d82bbcf0:f99d83ec-3a52-4e68-ab2c-67e7863c1288:be5e78f0-c472-4af5-8302-0ca94b908b86 apparentsize 20971520
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,403::image::295::Storage.Image::(isLegal) image f99d83ec-3a52-4e68-ab2c-67e7863c1288 in domain 941b820a-0b82-4b96-8a79-8818d82bbcf0 has vollist []
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,403::image::122::Storage.Image::(create) Create placeholder /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/941b820a-0b82-4b96-8a79-8818d82bbcf0/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288 for image's volumes
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,404::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,415::volume::415::Storage.Volume::(create) Creating volume be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,416::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,430::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,448::fileVolume::133::Storage.Volume::(_create) Request to create RAW volume /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/941b820a-0b82-4b96-8a79-8818d82bbcf0/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86 with size = 20480 sectors
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,450::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,470::fileVolume::384::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=be5e78f0-c472-4af5-8302-0ca94b908b86 sdUUID=941b820a-0b82-4b96-8a79-8818d82bbcf0, metaId=(u'/rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/941b820a-0b82-4b96-8a79-8818d82bbcf0/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86',)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,593::task::752::Storage.TaskManager.Task::(_save) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::_save: orig /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35 temp /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/master/tasks/2b75ff2e-723f-43d6-9d37-039a67b79f35.temp
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,610::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,614::volume::767::Storage.Volume::(prepare) Volume: preparing volume 871a92d1-0a98-40ff-a3c8-36ede1ee589c/be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::INFO::2015-10-08 07:36:18,617::volume::767::Storage.Volume::(prepare) Volume: preparing volume 941b820a-0b82-4b96-8a79-8818d82bbcf0/be5e78f0-c472-4af5-8302-0ca94b908b86
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,622::utils::676::root::(execCmd) /usr/bin/qemu-img --help (cwd None)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,634::utils::694::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,634::utils::676::root::(execCmd) /usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/qemu-img convert -t none -T none -f raw /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/871a92d1-0a98-40ff-a3c8-36ede1ee589c/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86 -O raw /rhev/data-center/mnt/10.16.29.93:_ipinto__storage__nfs__1/941b820a-0b82-4b96-8a79-8818d82bbcf0/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86 (cwd None)
mailbox.SPMMonitor::DEBUG::2015-10-08 07:36:19,003::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) dd if=/rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000 (cwd None)
mailbox.SPMMonitor::DEBUG::2015-10-08 07:36:19,023::storage_mailbox::735::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0123902 s, 82.6 MB/s\n'; <rc> = 0
Thread-317::DEBUG::2015-10-08 07:36:19,150::bindingxmlrpc::325::vds::(wrapper) client [10.35.161.169] flowID [76a3396a]
Thread-317::DEBUG::2015-10-08 07:36:19,150::task::595::Storage.TaskManager.Task::(_updateState) Task=`98f0e46f-56ff-4916-8471-1b4bb9823541`::moving from state init -> state preparing
Thread-317::INFO::2015-10-08 07:36:19,150::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='2b75ff2e-723f-43d6-9d37-039a67b79f35', spUUID=None, options=None)
Thread-317::DEBUG::2015-10-08 07:36:19,150::taskManager::155::Storage.TaskManager::(stopTask) Entry. taskID: 2b75ff2e-723f-43d6-9d37-039a67b79f35
Thread-317::DEBUG::2015-10-08 07:36:19,150::task::1246::Storage.TaskManager.Task::(stop) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::stopping in state running (force False)
Thread-317::DEBUG::2015-10-08 07:36:19,151::task::993::Storage.TaskManager.Task::(_decref) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::ref 1 aborting True
Thread-317::DEBUG::2015-10-08 07:36:19,151::taskManager::158::Storage.TaskManager::(stopTask) Return.
Thread-317::INFO::2015-10-08 07:36:19,151::logUtils::51::dispatcher::(wrapper) Run and protect: stopTask, Return response: True
Thread-317::DEBUG::2015-10-08 07:36:19,151::task::1191::Storage.TaskManager.Task::(prepare) Task=`98f0e46f-56ff-4916-8471-1b4bb9823541`::finished: True
Thread-317::DEBUG::2015-10-08 07:36:19,151::task::595::Storage.TaskManager.Task::(_updateState) Task=`98f0e46f-56ff-4916-8471-1b4bb9823541`::moving from state preparing -> state finished
Thread-317::DEBUG::2015-10-08 07:36:19,151::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-317::DEBUG::2015-10-08 07:36:19,151::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-317::DEBUG::2015-10-08 07:36:19,151::task::993::Storage.TaskManager.Task::(_decref) Task=`98f0e46f-56ff-4916-8471-1b4bb9823541`::ref 0 aborting False
Thread-317::DEBUG::2015-10-08 07:36:19,392::bindingxmlrpc::325::vds::(wrapper) client [10.35.161.169]
Thread-317::DEBUG::2015-10-08 07:36:19,392::task::595::Storage.TaskManager.Task::(_updateState) Task=`508ad125-4a3a-4516-aff1-888cef294e09`::moving from state init -> state preparing
Thread-317::INFO::2015-10-08 07:36:19,392::logUtils::48::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='fc6a619b-f98a-4594-86ba-ba4dac253a87', options=None)
Thread-317::INFO::2015-10-08 07:36:19,441::logUtils::51::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
Thread-317::DEBUG::2015-10-08 07:36:19,441::task::1191::Storage.TaskManager.Task::(prepare) Task=`508ad125-4a3a-4516-aff1-888cef294e09`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 2L}}
Thread-317::DEBUG::2015-10-08 07:36:19,441::task::595::Storage.TaskManager.Task::(_updateState) Task=`508ad125-4a3a-4516-aff1-888cef294e09`::moving from state preparing -> state finished
Thread-317::DEBUG::2015-10-08 07:36:19,441::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-317::DEBUG::2015-10-08 07:36:19,441::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-317::DEBUG::2015-10-08 07:36:19,441::task::993::Storage.TaskManager.Task::(_decref) Task=`508ad125-4a3a-4516-aff1-888cef294e09`::ref 0 aborting False
Reactor thread::INFO::2015-10-08 07:36:19,550::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from 127.0.0.1:50176
Reactor thread::DEBUG::2015-10-08 07:36:19,559::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-10-08 07:36:19,559::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from 127.0.0.1:50176
Reactor thread::DEBUG::2015-10-08 07:36:19,559::bindingxmlrpc::1297::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 50176)
BindingXMLRPC::INFO::2015-10-08 07:36:19,559::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for 127.0.0.1:50176
Thread-364::INFO::2015-10-08 07:36:19,560::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:50176 started
Thread-364::INFO::2015-10-08 07:36:19,561::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:50176 stopped
2b75ff2e-723f-43d6-9d37-039a67b79f35::ERROR::2015-10-08 07:36:19,638::image::857::Storage.Image::(copyCollapsed) Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/image.py", line 836, in copyCollapsed
    volume.fmt2str(dstVolFormat))
  File "/usr/lib/python2.7/site-packages/vdsm/qemuimg.py", line 206, in convert
    ioclass=utils.IOCLASS.IDLE)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 718, in watchCmd
    raise ActionStopped()
ActionStopped: Action was stopped: ()
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,639::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,639::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' (0 active users)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,639::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' is free, finding out if anyone is waiting for it.
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,639::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource '941b820a-0b82-4b96-8a79-8818d82bbcf0_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288', Clearing records.
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' (0 active users)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288' is free, finding out if anyone is waiting for it.
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86'
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86' (0 active users)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86' is free, finding out if anyone is waiting for it.
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_volumeNS.be5e78f0-c472-4af5-8302-0ca94b908b86', Clearing records.
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource '871a92d1-0a98-40ff-a3c8-36ede1ee589c_imageNS.f99d83ec-3a52-4e68-ab2c-67e7863c1288', Clearing records.
2b75ff2e-723f-43d6-9d37-039a67b79f35::ERROR::2015-10-08 07:36:19,640::task::866::Storage.TaskManager.Task::(_setError) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/storage/task.py", line 332, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/share/vdsm/storage/securable.py", line 77, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/share/vdsm/storage/sp.py", line 1512, in copyImage
    postZero, force)
  File "/usr/share/vdsm/storage/image.py", line 859, in copyCollapsed
    (srcImgUUID, dstImgUUID, str(e)))
CopyImageError: low level Image copy failed: ('src image=f99d83ec-3a52-4e68-ab2c-67e7863c1288, dst image=f99d83ec-3a52-4e68-ab2c-67e7863c1288: msg=Action was stopped: ()',)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,640::task::885::Storage.TaskManager.Task::(_run) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Task._run: 2b75ff2e-723f-43d6-9d37-039a67b79f35 () {} failed - stopping task
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,641::task::1246::Storage.TaskManager.Task::(stop) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::stopping in state running (force False)
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,641::task::919::Storage.TaskManager.Task::(_runJobs) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::aborting: Task is aborted: u'2b75ff2e-723f-43d6-9d37-039a67b79f35' - code 411
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,641::task::993::Storage.TaskManager.Task::(_decref) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::ref 0 aborting True
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,641::task::928::Storage.TaskManager.Task::(_doAbort) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Task._doAbort: force False
2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:19,641::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Comment 1 Israel Pinto 2015-10-08 18:29:06 UTC 
Created attachment 1081074 [details]
engine_log
Comment 2 Israel Pinto 2015-10-08 18:30:08 UTC 
Created attachment 1081075 [details]
vdsm_log
Comment 3 Michal Skrivanek 2015-10-09 13:15:21 UTC 
any idea why is it failing in copy operation?
Comment 4 Allon Mureinik 2015-10-09 13:43:51 UTC 
Seems like the call to qemu-img gets killed. Odd.

Nir, can you take a look please?
Comment 5 Allon Mureinik 2015-10-09 13:44:46 UTC 
Israel - can you also specify which version of the qemu* RPMs you have there please?
Comment 6 Israel Pinto 2015-10-11 09:00:57 UTC 
[root@ibm-p8-rhevm-04 ~]# rpm -qa | grep qemu*
libvirt-daemon-driver-qemu-1.2.17-12.el7.ppc64le
qemu-kvm-rhev-2.3.0-28.el7.ppc64le
ipxe-roms-qemu-20130517-7.gitc4bce43.el7.noarch
qemu-kvm-common-rhev-2.3.0-28.el7.ppc64le
qemu-kvm-tools-rhev-2.3.0-29.el7.ppc64le
qemu-img-rhev-2.3.0-28.el7.ppc64le
Comment 7 Allon Mureinik 2015-10-11 09:03:11 UTC 
restoring needinfo on Nir, which was mistakenly removed.
Comment 8 Carlos Mestre González 2015-10-26 18:12:16 UTC 
This is not only happening in PPC64el, is happening in 100% of runs in x86 RHEL7.2 (same logs in engine and vdsm.log) importing a template:

ovirt - 3.6-0-17

qemu-kvm-rhev-2.3.0-31.el7.x86_64
libvirt-daemon-driver-qemu-1.2.17-13.el7.x86_64
qemu-kvm-common-rhev-2.3.0-31.el7.x86_64
qemu-kvm-tools-rhev-2.3.0-31.el7.x86_64
qemu-img-rhev-2.3.0-31.el7.x86_64
ipxe-roms-qemu-20130517-7.gitc4bce43.el7.noarch
vdsm-4.17.10-5.el7ev.noarch
libvirt-1.2.17-13.el7.x86_64

@Gil: should this be mark as blocker?
Comment 9 Gil Klein 2015-10-26 20:31:34 UTC 
Looks more urgent if it's reproduce also on x86_64.

Nir, per Allon's request, could you please assist?
Comment 10 Nir Soffer 2015-10-26 20:46:31 UTC 
(In reply to Carlos Mestre González from comment #8)
> This is not only happening in PPC64el, is happening in 100% of runs in x86
> RHEL7.2 (same logs in engine and vdsm.log) importing a template:

Carlos, can you attach vdsm and engine logs showing this failure on X86_64
showing this failure?
Comment 11 Nir Soffer 2015-10-26 20:53:46 UTC 
Israel, 

Does it work when running RHEV 3.6 on RHEL 7.1?
Does it work when running RHEV 3.5 on RHEL 7.2?
Comment 12 Nir Soffer 2015-10-26 21:23:35 UTC 
Looking in the current logs (from ppcele?)

1. Starting copyImage

Thread-160::INFO::2015-10-08 07:36:18,327::logUtils::48::dispatcher::(wrapper) Run and protect: copyImage(sdUUID='871a92d1-0a98-40ff-a3c8-36ede1ee589c', spUUID='fc6a619b-f98a-4594-86ba-ba4dac253a87', vmUUID='', srcImgUUID='f99d83ec-3a52-4e68-ab2c-67e7863c1288', srcVolUUID='be5e78f0-c472-4af5-8302-0ca94b908b86', dstImgUUID='f99d83ec-3a52-4e68-ab2c-67e7863c1288', dstVolUUID='be5e78f0-c472-4af5-8302-0ca94b908b86', description='', dstSdUUID='941b820a-0b82-4b96-8a79-8818d82bbcf0', volType=6, volFormat=5, preallocate=2, postZero='false', force='false')

2. Scheduling task 2b75ff2e-723f-43d6-9d37-039a67b79f35

Thread-160::DEBUG::2015-10-08 07:36:18,355::taskManager::78::Storage.TaskManager::(scheduleJob) scheduled job copyImage_f99d83ec-3a52-4e68-ab2c-67e7863c1288 for task 2b75ff2e-7
23f-43d6-9d37-039a67b79f35 

3. Starting qemu-img convert ...

2b75ff2e-723f-43d6-9d37-039a67b79f35::DEBUG::2015-10-08 07:36:18,634::utils::676::root::(execCmd) /usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/qemu-img convert -t none -T none -f raw /rhev/data-center/fc6a619b-f98a-4594-86ba-ba4dac253a87/871a92d1-0a98-40ff-a3c8-36ede1ee589c/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86 -O raw /rhev/data-center/mnt/10.16.29.93:_ipinto__storage__nfs__1/941b820a-0b82-4b96-8a79-8818d82bbcf0/images/f99d83ec-3a52-4e68-ab2c-67e7863c1288/be5e78f0-c472-4af5-8302-0ca94b908b86 (cwd None)

4. Stopping task 2b75ff2e-723f-43d6-9d37-039a67b79f35

Thread-317::INFO::2015-10-08 07:36:19,150::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='2b75ff2e-723f-43d6-9d37-039a67b79f35', spUUID=None, options=None)

5. Task stopped

Thread-364::INFO::2015-10-08 07:36:19,561::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for 127.0.0.1:50176 stopped
2b75ff2e-723f-43d6-9d37-039a67b79f35::ERROR::2015-10-08 07:36:19,638::image::857::Storage.Image::(copyCollapsed) Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/image.py", line 836, in copyCollapsed
    volume.fmt2str(dstVolFormat))
  File "/usr/lib/python2.7/site-packages/vdsm/qemuimg.py", line 206, in convert
    ioclass=utils.IOCLASS.IDLE)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 718, in watchCmd
    raise ActionStopped()
ActionStopped: Action was stopped: ()

6. Bogus task error after task was stopped

2b75ff2e-723f-43d6-9d37-039a67b79f35::ERROR::2015-10-08 07:36:19,640::task::866::Storage.TaskManager.Task::(_setError) Task=`2b75ff2e-723f-43d6-9d37-039a67b79f35`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 873, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/storage/task.py", line 332, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/share/vdsm/storage/securable.py", line 77, in wrapper
    return method(self, *args, **kwargs)
  File "/usr/share/vdsm/storage/sp.py", line 1512, in copyImage
    postZero, force)
  File "/usr/share/vdsm/storage/image.py", line 859, in copyCollapsed
    (srcImgUUID, dstImgUUID, str(e)))
CopyImageError: low level Image copy failed: ('src image=f99d83ec-3a52-4e68-ab2c-67e7863c1288, dst image=f99d83ec-3a52-4e68-ab2c-67e7863c1288: msg=Action was stopped: ()',)

We have several examples of this flow in the same log:

$ egrep 'stopTask|ActionStopped|CopyImageError' vdsm.log.1
Thread-317::INFO::2015-10-08 07:36:19,150::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='2b75ff2e-723f-43d6-9d37-039a67b79f35', spUUID=None, options=None)
Thread-317::DEBUG::2015-10-08 07:36:19,150::taskManager::155::Storage.TaskManager::(stopTask) Entry. taskID: 2b75ff2e-723f-43d6-9d37-039a67b79f35
Thread-317::DEBUG::2015-10-08 07:36:19,151::taskManager::158::Storage.TaskManager::(stopTask) Return.
Thread-317::INFO::2015-10-08 07:36:19,151::logUtils::51::dispatcher::(wrapper) Run and protect: stopTask, Return response: True
    raise ActionStopped()
ActionStopped: Action was stopped: ()
CopyImageError: low level Image copy failed: ('src image=f99d83ec-3a52-4e68-ab2c-67e7863c1288, dst image=f99d83ec-3a52-4e68-ab2c-67e7863c1288: msg=Action was stopped: ()',)
Thread-328::INFO::2015-10-08 07:39:43,158::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='37a93f9c-9271-4592-9133-8272b2252e75', spUUID=None, options=None)
Thread-328::DEBUG::2015-10-08 07:39:43,158::taskManager::155::Storage.TaskManager::(stopTask) Entry. taskID: 37a93f9c-9271-4592-9133-8272b2252e75
Thread-328::DEBUG::2015-10-08 07:39:43,158::taskManager::158::Storage.TaskManager::(stopTask) Return.
Thread-328::INFO::2015-10-08 07:39:43,158::logUtils::51::dispatcher::(wrapper) Run and protect: stopTask, Return response: True
    raise ActionStopped()
ActionStopped: Action was stopped: ()
CopyImageError: low level Image copy failed: ('src image=f99d83ec-3a52-4e68-ab2c-67e7863c1288, dst image=f99d83ec-3a52-4e68-ab2c-67e7863c1288: msg=Action was stopped: ()',)
Thread-39::INFO::2015-10-08 08:39:10,647::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='fbface18-5c65-42c5-806a-5f1daa3208ee', spUUID=None, options=None)
Thread-39::DEBUG::2015-10-08 08:39:10,647::taskManager::155::Storage.TaskManager::(stopTask) Entry. taskID: fbface18-5c65-42c5-806a-5f1daa3208ee
Thread-39::DEBUG::2015-10-08 08:39:10,648::taskManager::158::Storage.TaskManager::(stopTask) Return.
Thread-39::INFO::2015-10-08 08:39:10,648::logUtils::51::dispatcher::(wrapper) Run and protect: stopTask, Return response: True
    raise ActionStopped()
ActionStopped: Action was stopped: ()
CopyImageError: low level Image copy failed: ('src image=a9584585-57dc-4d9f-ac01-aaba5d690d1c, dst image=a9584585-57dc-4d9f-ac01-aaba5d690d1c: msg=Action was stopped: ()',)
Thread-39::INFO::2015-10-08 08:40:03,137::logUtils::48::dispatcher::(wrapper) Run and protect: stopTask(taskID='696e52f6-e4fd-41f5-9cb7-cc5e87dd961e', spUUID=None, options=None)
Thread-39::DEBUG::2015-10-08 08:40:03,137::taskManager::155::Storage.TaskManager::(stopTask) Entry. taskID: 696e52f6-e4fd-41f5-9cb7-cc5e87dd961e
Thread-39::DEBUG::2015-10-08 08:40:03,137::taskManager::158::Storage.TaskManager::(stopTask) Return.
Thread-39::INFO::2015-10-08 08:40:03,137::logUtils::51::dispatcher::(wrapper) Run and protect: stopTask, Return response: True
    raise ActionStopped()
ActionStopped: Action was stopped: ()
CopyImageError: low level Image copy failed: ('src image=a9584585-57dc-4d9f-ac01-aaba5d690d1c, dst image=a9584585-57dc-4d9f-ac01-aaba5d690d1c: msg=Action was stopped: ()',)
[nsoffer@thin 1270003 (master)]$ 

Everything on the vdsm side is expected - when you ask to stop a task, vdsm will stop it.

Looking in engine log:

$ grep 'SPMAsyncTask::StopTask: Attempting to stop task' engine.log
2015-10-08 14:36:19,805 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-44) [76a3396a] SPMAsyncTask::StopTask: Attempting to stop task '2b75ff2e-723f-43d6-9d37-039a67b79f35' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters').
2015-10-08 14:39:42,471 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-28) [7b5de388] SPMAsyncTask::StopTask: Attempting to stop task '37a93f9c-9271-4592-9133-8272b2252e75' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters').
2015-10-08 15:39:11,192 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-13) [5d845592] SPMAsyncTask::StopTask: Attempting to stop task 'fbface18-5c65-42c5-806a-5f1daa3208ee' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters').
2015-10-08 15:40:04,728 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-37) [66c84f5f] SPMAsyncTask::StopTask: Attempting to stop task '696e52f6-e4fd-41f5-9cb7-cc5e87dd961e' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters').

So it was engine who ask to stop the task.

Looking in the first command flow in the engine:

2015-10-08 14:36:19,397 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (org.ovirt.thread.pool-7-thread-7) [76a3396a] Adding task '2b75ff2e-723f-43d6-9d37-039a67b79f35
' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet..
2015-10-08 14:36:19,606 ERROR [org.ovirt.engine.core.bll.ImportVmTemplateCommand] (org.ovirt.thread.pool-7-thread-7) [76a3396a] Command 'org.ovirt.engine.core.bll.ImportVmTempl
ateCommand' failed: null
2015-10-08 14:36:19,606 ERROR [org.ovirt.engine.core.bll.ImportVmTemplateCommand] (org.ovirt.thread.pool-7-thread-7) [76a3396a] Exception: java.lang.NumberFormatException: null
        at java.lang.Long.parseLong(Long.java:552) [rt.jar:1.8.0_51]
        at org.ovirt.engine.core.utils.MacAddressRangeUtils.macToLong(MacAddressRangeUtils.java:122) [utils.jar:]
        at org.ovirt.engine.core.bll.network.macpoolmanager.MacPoolManagerRanges.isMacInUse(MacPoolManagerRanges.java:142) [bll.jar:]
        at org.ovirt.engine.core.bll.utils.VmDeviceUtils.canPlugInterfaceInDc(VmDeviceUtils.java:684) [bll.jar:]
        at org.ovirt.engine.core.bll.utils.VmDeviceUtils.canPlugInterface(VmDeviceUtils.java:672) [bll.jar:]
        at org.ovirt.engine.core.bll.utils.VmDeviceUtils.addImportedInterfaces(VmDeviceUtils.java:1660) [bll.jar:]
        at org.ovirt.engine.core.bll.utils.VmDeviceUtils.addImportedDevices(VmDeviceUtils.java:1619) [bll.jar:]
        at org.ovirt.engine.core.bll.ImportVmTemplateCommand.executeCommand(ImportVmTemplateCommand.java:327) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1211) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1355) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1979) [bll.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:174) [utils.jar:]
        at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:116) [utils.jar:]
        at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1392) [bll.jar:]
        at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:374) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner.executeValidatedCommand(MultipleActionsRunner.java:202) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner.runCommands(MultipleActionsRunner.java:170) [bll.jar:]
        at org.ovirt.engine.core.bll.MultipleActionsRunner$2.run(MultipleActionsRunner.java:179) [bll.jar:]
        at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92) [utils.jar:]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_51]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_51]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_51]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_51]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_51]

Somebody was not careful with his nulls.

So engine cancel the task.

2015-10-08 14:36:19,805 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-7-thread-44) [76a3396a] SPMAsyncTask::StopTask: Attempting to stop task '2b75ff2e-723f-43d6-9d37-039a67b79f35' (Parent Command 'ImportVmTemplate', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters').


Maor, can you take a look at this?
Comment 13 Tal Nisan 2015-10-26 21:38:16 UTC 
Michal, this exception in MacAddressRangeUtils is similar to the one we've seen in an import bug a few weeks ago, I think it might be more virt related, can someone from you team take a look?
Comment 14 Carlos Mestre González 2015-10-26 22:19:23 UTC 
Created attachment 1086612 [details]
engine.log x86
Comment 15 Carlos Mestre González 2015-10-26 22:22:10 UTC 
Created attachment 1086614 [details]
vdsm.log x86
Comment 16 Michal Skrivanek 2015-10-29 14:15:32 UTC 
I successfully reproduced the problem on a completely clean and freshly deployed system, just create a VM, export to local storage export domain and import it back
Comment 17 Michal Skrivanek 2015-10-29 15:08:04 UTC 
AFAICT the issue is with mac assignment when importing (or template creation) - reassigning to network

Worth noting in Import VM dialog the MAC field is empty. The original VM does have a MAC.
Comment 18 Martin Mucha 2015-10-29 15:19:07 UTC 
I tried it once again during meeting with danken and we had some weird issues:
We created VM with 1GB disk, created template and issued it's export. While Danken confirmed, that vdsm was done sufficiently fast with exporting template to export domain, it took over 8 minutes to engine to report it's done. Before engine presented template as exported in "export domain -> Template import" it said in events: "Oct 29, 2015 4:11:43 PM Failed to export Template test to exportDomain" and few minutes after that successfully exported template miraculously summoned. During waiting for this template in export domain, whole app was resilient to refresh, and refreshed only after export was done. After logout and log back in, it takes again minutes to see content in "export domain -> Template import".

Not sure if it's related to this bug, or if it's even another bug. Having successfully someting in export domain, I'll try to verify if there's a problem with mac pool asap.
Comment 19 Michael Burman 2015-11-04 12:14:43 UTC 
Verified on - 3.6.0.3-0.1.el6
Note You need to log in before you can comment on or make changes to this bug.