Attachment 941372 Details for Bug 1145582 – part of vdsm.log

part of vdsm.log

vdsm_import.log (text/plain), 149.35 KB, created by zhoujunqin on 2014-09-26 04:12:56 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: zhoujunqin

Created: 2014-09-26 04:12:56 UTC

Size: 149.35 KB

patch

obsolete

># tailf  vdsm.log
>Thread-36352::DEBUG::2014-09-26 04:04:25,179::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.6.8:_var_v2v__export/e4883354-fa70-4314-bcc0-6ee12c39e3a2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-36352::DEBUG::2014-09-26 04:04:25,194::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n355 bytes (355 B) copied, 0.000521856 s, 680 kB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:26,926::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:27,028::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0405264 s, 25.3 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:29,043::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:29,132::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0327002 s, 31.3 MB/s\n'; <rc> = 0
>Thread-22::DEBUG::2014-09-26 04:04:29,570::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:04:29,584::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000330011 s, 1.6 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:31,146::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:31,244::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0399068 s, 25.7 MB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:04:32,700::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21512::DEBUG::2014-09-26 04:04:32,701::task::595::TaskManager.Task::(_updateState) Task=`d5330896-1902-4454-a430-a0b559464ee6`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:32,701::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21512::INFO::2014-09-26 04:04:32,702::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:32,702::task::1185::TaskManager.Task::(prepare) Task=`d5330896-1902-4454-a430-a0b559464ee6`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:32,702::task::595::TaskManager.Task::(_updateState) Task=`d5330896-1902-4454-a430-a0b559464ee6`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:32,702::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:32,702::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:32,703::task::990::TaskManager.Task::(_decref) Task=`d5330896-1902-4454-a430-a0b559464ee6`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:32,761::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21513::DEBUG::2014-09-26 04:04:32,762::task::595::TaskManager.Task::(_updateState) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:32,762::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:32,763::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`6cda5962-c36a-47d6-8596-3f3a2761f8aa`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2573' at 'getStoragePoolInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:32,763::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000002c4' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:32,763::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:32,763::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`6cda5962-c36a-47d6-8596-3f3a2761f8aa`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:32,764::task::827::TaskManager.Task::(resourceAcquired) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::_resourcesAcquired: Storage.00000002-0002-0002-0002-0000000002c4 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:32,764::task::990::TaskManager.Task::(_decref) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:32,791::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:32,791::task::1185::TaskManager.Task::(prepare) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::finished: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:32,791::task::595::TaskManager.Task::(_updateState) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:32,792::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.00000002-0002-0002-0002-0000000002c4': < ResourceRef 'Storage.00000002-0002-0002-0002-0000000002c4', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:32,792::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:32,792::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000002c4'
>Thread-21513::DEBUG::2014-09-26 04:04:32,793::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000002c4' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:32,793::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:32,793::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000002c4', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:32,793::task::990::TaskManager.Task::(_decref) Task=`86d2eb60-d45e-42b4-bf0f-1cb744690834`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:33,258::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:33,355::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0399806 s, 25.6 MB/s\n'; <rc> = 0
>Thread-36352::DEBUG::2014-09-26 04:04:35,218::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.6.8:_var_v2v__export/e4883354-fa70-4314-bcc0-6ee12c39e3a2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-36352::DEBUG::2014-09-26 04:04:35,233::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n355 bytes (355 B) copied, 0.000550604 s, 645 kB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:04:35,304::task::595::TaskManager.Task::(_updateState) Task=`a5a9afe5-efa5-4c37-833c-fba2b77d7aaf`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:35,304::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-21512::INFO::2014-09-26 04:04:35,304::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000550604', 'lastCheck': '0.1', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000330011', 'lastCheck': '5.7', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:04:35,305::task::1185::TaskManager.Task::(prepare) Task=`a5a9afe5-efa5-4c37-833c-fba2b77d7aaf`::finished: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000550604', 'lastCheck': '0.1', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000330011', 'lastCheck': '5.7', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:04:35,305::task::595::TaskManager.Task::(_updateState) Task=`a5a9afe5-efa5-4c37-833c-fba2b77d7aaf`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:35,305::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:35,305::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:35,305::task::990::TaskManager.Task::(_decref) Task=`a5a9afe5-efa5-4c37-833c-fba2b77d7aaf`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:35,370::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:35,469::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0438541 s, 23.4 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:37,482::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:37,571::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0324951 s, 31.5 MB/s\n'; <rc> = 0
>Thread-21513::DEBUG::2014-09-26 04:04:39,333::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21513::DEBUG::2014-09-26 04:04:39,333::task::595::TaskManager.Task::(_updateState) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:39,333::logUtils::44::dispatcher::(wrapper) Run and protect: getVmsInfo(spUUID='00000002-0002-0002-0002-0000000002c4', sdUUID='e4883354-fa70-4314-bcc0-6ee12c39e3a2', vmList=[], options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:39,334::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`482b63d8-bd7e-419c-9a99-b107897625d4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1424' at 'getVmsInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:39,334::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:39,335::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:39,335::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`482b63d8-bd7e-419c-9a99-b107897625d4`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:39,335::task::827::TaskManager.Task::(resourceAcquired) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::_resourcesAcquired: Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:39,335::task::990::TaskManager.Task::(_decref) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:39,338::sd::595::Storage.StorageDomain::(getVMsList) vmList=['db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844', '24d00314-d7b9-4a0f-9ba2-c39c75434e51', 'ba899c55-fb83-44b7-bdd3-b8a71ee25be1', 'c56d9296-c1cc-4fe4-a66e-7775cddb974c']
>Thread-21513::INFO::2014-09-26 04:04:39,338::sd::612::Storage.StorageDomain::(getVMsInfo) vmList=['db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844', '24d00314-d7b9-4a0f-9ba2-c39c75434e51', 'ba899c55-fb83-44b7-bdd3-b8a71ee25be1', 'c56d9296-c1cc-4fe4-a66e-7775cddb974c']
>Thread-21513::INFO::2014-09-26 04:04:39,347::logUtils::47::dispatcher::(wrapper) Run and protect: getVmsInfo, Return response: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template>\n      
>Thread-21513::DEBUG::2014-09-26 04:04:39,347::task::1185::TaskManager.Task::(prepare) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::finished: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Tem
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::task::595::TaskManager.Task::(_updateState) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>/rasd:StoragePoolId>\n        <rasd:CreationDate>2014/09/25 06:03:20</rasd:CreationDate>\n        <rasd:LastModified>2014/09/25 06:03:20</rasd:LastModified>\n        <rasd:last_modified_date>2014/09/25 06:03:20</rasd:last_modified_date>\n      </Item>\n      <Item>\n        <rasd:InstanceId>3</rasd:InstanceId>\n        <rasd:Caption>Ethernet adapter on rhevm</rasd:Caption>\n        <rasd:ResourceType>10</rasd:ResourceType>\n        <rasd:ResourceSubType>3</rasd:ResourceSubType>\n        <rasd:Connection>rhevm</rasd:Connection>\n        <rasd:Name>eth0</rasd:Name>\n        <rasd:MACAddress>52:54:00:6b:53:76</rasd:MACAddress>\n      </Item>\n    </Section>\n  </Content>\n</ovf:Envelope>\n', 'c56d9296-c1cc-4fe4-a66e-7775cddb974c': u'<ovf:Envelope xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1/" ovf:version="0.9">\n\n    <References><File ovf:href="3fa463b2-1469-4784-b857-21e7b79cc20a/c273e1ad-6f96-4fc5-a74b-1836165e9f27" ovf:id="c273e1ad-6f96-4fc5-a74b-1836165e9f27" ovf:size="8388608000" ovf:description="imported by virt-v2v"/></References>\n\n    <Section xsi:type="ovf:NetworkSection_Type">\n        <Info>List of networks</Info>\n    <Network ovf:name="rhevm"/></Section>\n\n    <Section xsi:type="ovf:DiskSection_Type">\n        <Info>List of Virtual Disks</Info>\n    <Disk ovf:diskId="c273e1ad-6f96-4fc5-a74b-1836165e9f27" ovf:size="8" ovf:actual_size="4" ovf:fileRef="3fa463b2-1469-4784-b857-21e7b79cc20a/c273e1ad-6f96-4fc5-a74b-1836165e9f27" ovf:parentRef="" ovf:vm_snapshot_id="0fd3ac32-12b7-448b-8e37-9a118f2b5bec" ovf:volume-format="COW" ovf:volume-type="Sparse" ovf:format="http://en.wikipedia.org/wiki/Byte" ovf:disk-interface="VirtIO" ovf:disk-type="System" ovf:boot="True"/></Section>\n\n    <Content ovf:id="out" xsi:type="ovf:VirtualSystem_Type">\n        <Name>demo-tzheng</Name>\n        <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n        <TemplateName>Blank</TemplateName>\n        <Description>Imported with virt-v2v</Description>\n        <Domain/>\n        <CreationDate>2014/09/25 19:35:57</CreationDate>\n        <IsInitilized>True</IsInitilized>\n        <IsAutoSuspend>False</IsAutoSuspend>\n        <TimeZone/>\n        <IsStateless>False</IsStateless>\n        <Origin>0</Origin>\n        <VmType>1</VmType>\n        <DefaultDisplayType>0</DefaultDisplayType>\n\n        <Section ovf:id="c56d9296-c1cc-4fe4-a66e-7775cddb974c" ovf:required="false" xsi:type="ovf:OperatingSystemSection_Type">\n          <Info>Guest Operating System</Info>\n          <Description>OtherLinux</Description>\n        </Section>\n\n        <Section xsi:type="ovf:VirtualHardwareSection_Type">\n            <Info>1 CPU, 1024 Memory</Info>\n            <Item>\n                <rasd:Caption>1 virtual cpu</rasd:Caption>\n                <rasd:Description>Number of virtual CPU</rasd:Description>\n                <rasd:InstanceId>1</rasd:InstanceId>\n                <rasd:ResourceType>3</rasd:ResourceType>\n                <rasd:num_of_sockets>1</rasd:num_of_sockets>\n                <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n            </Item>\n            <Item>\n                <rasd:Caption>1024 MB of memory</rasd:Caption>\n                <rasd:Description>Memory Size</rasd:Description>\n                <rasd:InstanceId>2</rasd:InstanceId>\n                <rasd:ResourceType>4</rasd:ResourceType>\n                <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n                <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n            </Item>\n            <Item>\n                <rasd:Caption>USB Controller</rasd:Caption>\n                <rasd:InstanceId>4</rasd:InstanceId>\n                <rasd:ResourceType>23</rasd:ResourceType>\n                <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n            </Item>\n            <Item>\n                <rasd:Caption>Graphical C
>Thread-21513::DEBUG::2014-09-26 04:04:39,347::task::1185::TaskManager.Task::(prepare) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::finished: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Tem
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::task::595::TaskManager.Task::(_updateState) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:39,348::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:39,349::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:39,350::task::990::TaskManager.Task::(_decref) Task=`e649e64a-0da1-4c2d-a269-0bc8cf53359e`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:39,586::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:04:39,679::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:04:39,705::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000318842 s, 1.6 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:39,784::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.141338 s, 7.2 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2014-09-26 04:04:41,281::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 92.
>Thread-38679::DEBUG::2014-09-26 04:04:41,411::task::595::TaskManager.Task::(_updateState) Task=`f176245e-8f62-4ad4-9d2c-81e2d1fc64c2`::moving from state init -> state preparing
>Thread-38679::INFO::2014-09-26 04:04:41,411::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='946b78c7-b21e-4d88-b4ee-fee464cc4ce9', spUUID='00000002-0002-0002-0002-0000000002c4', imgUUID='e844160d-b559-4858-a03b-566de70c5ae2', volUUID='3b73f780-03a2-4609-9135-bde0e892edf5', options=None)
>Thread-38679::INFO::2014-09-26 04:04:41,414::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3360743424', 'apparentsize': '10737418240'}
>Thread-38679::DEBUG::2014-09-26 04:04:41,414::task::1185::TaskManager.Task::(prepare) Task=`f176245e-8f62-4ad4-9d2c-81e2d1fc64c2`::finished: {'truesize': '3360743424', 'apparentsize': '10737418240'}
>Thread-38679::DEBUG::2014-09-26 04:04:41,414::task::595::TaskManager.Task::(_updateState) Task=`f176245e-8f62-4ad4-9d2c-81e2d1fc64c2`::moving from state preparing -> state finished
>Thread-38679::DEBUG::2014-09-26 04:04:41,414::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-38679::DEBUG::2014-09-26 04:04:41,414::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-38679::DEBUG::2014-09-26 04:04:41,415::task::990::TaskManager.Task::(_decref) Task=`f176245e-8f62-4ad4-9d2c-81e2d1fc64c2`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:41,800::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:41,899::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0427794 s, 23.9 MB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:04:42,928::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [4257171f]
>Thread-21512::DEBUG::2014-09-26 04:04:42,929::task::595::TaskManager.Task::(_updateState) Task=`f7218762-8275-43f7-a614-0a1704f6c9bf`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:42,929::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21512::INFO::2014-09-26 04:04:42,930::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:42,930::task::1185::TaskManager.Task::(prepare) Task=`f7218762-8275-43f7-a614-0a1704f6c9bf`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:42,930::task::595::TaskManager.Task::(_updateState) Task=`f7218762-8275-43f7-a614-0a1704f6c9bf`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:42,930::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:42,930::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:42,930::task::990::TaskManager.Task::(_decref) Task=`f7218762-8275-43f7-a614-0a1704f6c9bf`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:42,989::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [4257171f]
>Thread-21513::DEBUG::2014-09-26 04:04:42,989::task::595::TaskManager.Task::(_updateState) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:42,989::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:42,990::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`e7748b42-8cf6-4cbd-8b4d-d9ad498b75d6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2573' at 'getStoragePoolInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:42,990::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000002c4' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:42,990::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:42,990::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`e7748b42-8cf6-4cbd-8b4d-d9ad498b75d6`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:42,990::task::827::TaskManager.Task::(resourceAcquired) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::_resourcesAcquired: Storage.00000002-0002-0002-0002-0000000002c4 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:42,991::task::990::TaskManager.Task::(_decref) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:43,012::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:43,012::task::1185::TaskManager.Task::(prepare) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::finished: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:43,012::task::595::TaskManager.Task::(_updateState) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:43,012::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.00000002-0002-0002-0002-0000000002c4': < ResourceRef 'Storage.00000002-0002-0002-0002-0000000002c4', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000002c4'
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000002c4' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000002c4', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:43,013::task::990::TaskManager.Task::(_decref) Task=`767e2258-efab-4dd7-a8c0-c0330d0d4e53`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:43,926::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:44,016::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.032956 s, 31.1 MB/s\n'; <rc> = 0
>Thread-36352::DEBUG::2014-09-26 04:04:45,264::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.6.8:_var_v2v__export/e4883354-fa70-4314-bcc0-6ee12c39e3a2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-36352::DEBUG::2014-09-26 04:04:45,278::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n355 bytes (355 B) copied, 0.000592958 s, 599 kB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:46,030::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:46,127::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0400258 s, 25.6 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:48,142::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:48,240::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0404883 s, 25.3 MB/s\n'; <rc> = 0
>Thread-21513::DEBUG::2014-09-26 04:04:49,103::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [7a7b1177]
>Thread-21513::DEBUG::2014-09-26 04:04:49,103::task::595::TaskManager.Task::(_updateState) Task=`1f18b1ff-b267-4184-b342-697716021542`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:49,103::logUtils::44::dispatcher::(wrapper) Run and protect: getVmsInfo(spUUID='00000002-0002-0002-0002-0000000002c4', sdUUID='e4883354-fa70-4314-bcc0-6ee12c39e3a2', vmList=[], options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:49,104::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`b8846d40-10fb-49b5-b7dc-47ad6fe0b3ad`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1424' at 'getVmsInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:49,104::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:49,104::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:49,104::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`b8846d40-10fb-49b5-b7dc-47ad6fe0b3ad`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:49,105::task::827::TaskManager.Task::(resourceAcquired) Task=`1f18b1ff-b267-4184-b342-697716021542`::_resourcesAcquired: Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:49,105::task::990::TaskManager.Task::(_decref) Task=`1f18b1ff-b267-4184-b342-697716021542`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:49,106::sd::595::Storage.StorageDomain::(getVMsList) vmList=['db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844', '24d00314-d7b9-4a0f-9ba2-c39c75434e51', 'ba899c55-fb83-44b7-bdd3-b8a71ee25be1', 'c56d9296-c1cc-4fe4-a66e-7775cddb974c']
>Thread-21513::INFO::2014-09-26 04:04:49,107::sd::612::Storage.StorageDomain::(getVMsInfo) vmList=['db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844', '24d00314-d7b9-4a0f-9ba2-c39c75434e51', 'ba899c55-fb83-44b7-bdd3-b8a71ee25be1', 'c56d9296-c1cc-4fe4-a66e-7775cddb974c']
>Thread-21513::INFO::2014-09-26 04:04:49,109::logUtils::47::dispatcher::(wrapper) Run and protect: getVmsInfo, Return response: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template>\n      
>Thread-21513::DEBUG::2014-09-26 04:04:49,109::task::1185::TaskManager.Task::(prepare) Task=`1f18b1ff-b267-4184-b342-697716021542`::finished: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Tem
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::task::595::TaskManager.Task::(_updateState) Task=`1f18b1ff-b267-4184-b342-697716021542`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>rasd:AllocationUnits>\n                <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n            </Item>\n            <Item>\n                <rasd:Caption>USB Controller</rasd:Caption>\n                <rasd:InstanceId>4</rasd:InstanceId>\n                <rasd:ResourceType>23</rasd:ResourceType>\n                <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n            </Item>\n            <Item>\n                <rasd:Caption>Graphical Controller</rasd:Caption>\n                <rasd:InstanceId>5</rasd:InstanceId>\n                <rasd:ResourceType>20</rasd:ResourceType>\n                <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n            </Item>\n        <Item><rasd:Caption>Drive 1</rasd:Caption><rasd:InstanceId>c273e1ad-6f96-4fc5-a74b-1836165e9f27</rasd:InstanceId><rasd:ResourceType>17</rasd:ResourceType><rasd:HostResource>3fa463b2-1469-4784-b857-21e7b79cc20a/c273e1ad-6f96-4fc5-a74b-1836165e9f27</rasd:HostResource><rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent><rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template><rasd:ApplicationList/><rasd:StorageId>e4883354-fa70-4314-bcc0-6ee12c39e3a2</rasd:StorageId><rasd:StoragePoolId>00000000-0000-0000-0000-000000000000</rasd:StoragePoolId><rasd:CreationDate>2014/09/25 19:14:56</rasd:CreationDate><rasd:LastModified>2014/09/25 19:14:56</rasd:LastModified><rasd:last_modified_date>2014/09/25 19:14:56</rasd:last_modified_date></Item><Item><rasd:Caption>Ethernet adapter on rhevm</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>10</rasd:ResourceType><rasd:ResourceSubType>3</rasd:ResourceSubType><rasd:Connection>rhevm</rasd:Connection><rasd:Name>eth0</rasd:Name><rasd:MACAddress>52:54:00:ab:6a:36</rasd:MACAddress></Item></Section>\n    </Content>\n</ovf:Envelope>\n', 'ba899c55-fb83-44b7-bdd3-b8a71ee25be1': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'e844160d-b559-4858-a03b-566de70c5ae2/3b73f780-03a2-4609-9135-bde0e892edf5\' ovf:id=\'3b73f780-03a2-4609-9135-bde0e892edf5\' ovf:size=\'10737418240\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'10\' ovf:diskId=\'3b73f780-03a2-4609-9135-bde0e892edf5\' ovf:size=\'10\' ovf:fileRef=\'e844160d-b559-4858-a03b-566de70c5ae2/3b73f780-03a2-4609-9135-bde0e892edf5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'b2c682ab-0fa4-4ddb-90fc-d24f49495052\' ovf:volume-format=\'RAW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel6.6-tzheng</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 11:02:30</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'ba899c55-fb83-44b7-bdd3-b8a71ee25be1\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL6x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>3 CPU, 2048 Memory</I
>Thread-21513::DEBUG::2014-09-26 04:04:49,109::task::1185::TaskManager.Task::(prepare) Task=`1f18b1ff-b267-4184-b342-697716021542`::finished: {'vmlist': {'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844': u'<?xml version=\'1.0\' encoding=\'utf-8\'?>\n<ovf:Envelope xmlns:rasd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData\' xmlns:vssd=\'http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData\' xmlns:xsi=\'http://www.w3.org/2001/XMLSchema-instance\' xmlns:ovf=\'http://schemas.dmtf.org/ovf/envelope/1/\' ovf:version=\'0.9\'>\n  <References>\n    <File ovf:href=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:id=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8589934592\' ovf:description=\'Exported by virt-v2v 1.27.54\'/>\n  </References>\n  <Section xsi:type=\'ovf:NetworkSection_Type\'>\n    <Info>List of networks</Info>\n    \n    <Network ovf:name=\'rhevm\'/>\n  </Section>\n  <Section xsi:type=\'ovf:DiskSection_Type\'>\n    <Info>List of Virtual Disks</Info>\n    <Disk ovf:actual_size=\'4\' ovf:diskId=\'f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:size=\'8\' ovf:fileRef=\'5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\' ovf:parentRef=\'\' ovf:vm_snapshot_id=\'93bfcaa9-8680-4639-8d93-94913097c64f\' ovf:volume-format=\'COW\' ovf:volume-type=\'Sparse\' ovf:format=\'http://en.wikipedia.org/wiki/Byte\' ovf:disk-interface=\'VirtIO\' ovf:disk-type=\'System\' ovf:boot=\'True\'/>\n  </Section>\n  <Content ovf:id=\'out\' xsi:type=\'ovf:VirtualSystem_Type\'>\n    <Name>rhel7new-today2</Name>\n    <TemplateId>00000000-0000-0000-0000-000000000000</TemplateId>\n    <TemplateName>Blank</TemplateName>\n    <Description>Exported by virt-v2v 1.27.54</Description>\n    <Domain/>\n    <CreationDate>2014/09/25 06:03:20</CreationDate>\n    <IsInitilized>True</IsInitilized>\n    <IsAutoSuspend>False</IsAutoSuspend>\n    <TimeZone/>\n    <IsStateless>False</IsStateless>\n    <Origin>0</Origin>\n    <VmType>1</VmType>\n    <DefaultDisplayType>1</DefaultDisplayType>\n    <Section ovf:id=\'db2c5a2f-d6ac-4b56-ab4d-cac8f29a4844\' ovf:required=\'false\' xsi:type=\'ovf:OperatingSystemSection_Type\'>\n      <Info>Guest Operating System</Info>\n      <Description>RHEL7x64</Description>\n    </Section>\n    <Section xsi:type=\'ovf:VirtualHardwareSection_Type\'>\n      <Info>1 CPU, 1024 Memory</Info>\n      <Item>\n        <rasd:Caption>1 virtual cpu</rasd:Caption>\n        <rasd:Description>Number of virtual CPU</rasd:Description>\n        <rasd:InstanceId>1</rasd:InstanceId>\n        <rasd:ResourceType>3</rasd:ResourceType>\n        <rasd:num_of_sockets>1</rasd:num_of_sockets>\n        <rasd:cpu_per_socket>1</rasd:cpu_per_socket>\n      </Item>\n      <Item>\n        <rasd:Caption>1024 MB of memory</rasd:Caption>\n        <rasd:Description>Memory Size</rasd:Description>\n        <rasd:InstanceId>2</rasd:InstanceId>\n        <rasd:ResourceType>4</rasd:ResourceType>\n        <rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits>\n        <rasd:VirtualQuantity>1024</rasd:VirtualQuantity>\n      </Item>\n      <Item>\n        <rasd:Caption>USB Controller</rasd:Caption>\n        <rasd:InstanceId>4</rasd:InstanceId>\n        <rasd:ResourceType>23</rasd:ResourceType>\n        <rasd:UsbPolicy>Disabled</rasd:UsbPolicy>\n      </Item>\n      <Item>\n        <rasd:Caption>Graphical Controller</rasd:Caption>\n        <rasd:InstanceId>5</rasd:InstanceId>\n        <rasd:ResourceType>20</rasd:ResourceType>\n        <rasd:VirtualQuantity>1</rasd:VirtualQuantity>\n        <rasd:Device>qxl</rasd:Device>\n      </Item>\n      <Item>\n        <rasd:InstanceId>f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:InstanceId>\n        <rasd:ResourceType>17</rasd:ResourceType>\n        <rasd:HostResource>5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5</rasd:HostResource>\n        <rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent>\n        <rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Tem
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::task::595::TaskManager.Task::(_updateState) Task=`1f18b1ff-b267-4184-b342-697716021542`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::task::990::TaskManager.Task::(_decref) Task=`1f18b1ff-b267-4184-b342-697716021542`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:49,110::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:49,111::task::990::TaskManager.Task::(_decref) Task=`1f18b1ff-b267-4184-b342-697716021542`::ref 0 aborting False
>VM Channels Listener::DEBUG::2014-09-26 04:04:49,290::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 76.
>Thread-21513::DEBUG::2014-09-26 04:04:49,493::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [7a7b1177]
>Thread-21513::DEBUG::2014-09-26 04:04:49,493::task::595::TaskManager.Task::(_updateState) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:49,493::logUtils::44::dispatcher::(wrapper) Run and protect: getImagesList(sdUUID='946b78c7-b21e-4d88-b4ee-fee464cc4ce9', options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:49,494::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`418f031f-3a9c-483d-b628-af3aa038e29a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3339' at 'getImagesList'
>Thread-21513::DEBUG::2014-09-26 04:04:49,494::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:49,494::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:49,494::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`418f031f-3a9c-483d-b628-af3aa038e29a`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:49,494::task::827::TaskManager.Task::(resourceAcquired) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::_resourcesAcquired: Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:49,495::task::990::TaskManager.Task::(_decref) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:49,499::logUtils::47::dispatcher::(wrapper) Run and protect: getImagesList, Return response: {'imageslist': ['8e3a6396-060f-4ecc-9201-84c5b035a076', 'b47408a1-79e2-48b3-9d24-a777c815ca0f', 'e844160d-b559-4858-a03b-566de70c5ae2', '3fa463b2-1469-4784-b857-21e7b79cc20a', '2fa21597-c8fb-4278-b020-339d1ed98e06', 'ae2709dd-acec-4342-8c6b-baf3252dd9a3', '809a0238-fed4-4254-8cfe-9c31062bfcbe', 'a7710d12-d546-4d1c-a493-9462ef600ed9']}
>Thread-21513::DEBUG::2014-09-26 04:04:49,499::task::1185::TaskManager.Task::(prepare) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::finished: {'imageslist': ['8e3a6396-060f-4ecc-9201-84c5b035a076', 'b47408a1-79e2-48b3-9d24-a777c815ca0f', 'e844160d-b559-4858-a03b-566de70c5ae2', '3fa463b2-1469-4784-b857-21e7b79cc20a', '2fa21597-c8fb-4278-b020-339d1ed98e06', 'ae2709dd-acec-4342-8c6b-baf3252dd9a3', '809a0238-fed4-4254-8cfe-9c31062bfcbe', 'a7710d12-d546-4d1c-a493-9462ef600ed9']}
>Thread-21513::DEBUG::2014-09-26 04:04:49,499::task::595::TaskManager.Task::(_updateState) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:49,499::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9': < ResourceRef 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:49,499::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:49,499::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9'
>Thread-21513::DEBUG::2014-09-26 04:04:49,500::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:49,500::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:49,500::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:49,500::task::990::TaskManager.Task::(_decref) Task=`dc46dce2-4f08-42b3-ac0c-4b566119e5d2`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:49,549::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [7a7b1177]
>Thread-21513::DEBUG::2014-09-26 04:04:49,550::task::595::TaskManager.Task::(_updateState) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:49,550::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='e4883354-fa70-4314-bcc0-6ee12c39e3a2', spUUID='00000002-0002-0002-0002-0000000002c4', imgUUID='5649d3a7-4025-45e6-99f9-d9682b82ee0f', volUUID='f636aa62-3568-41f5-8b84-0bb69cd408a5', options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:49,550::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`743143a3-d667-4e86-946a-0f98dfab88b9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3090' at 'getVolumeInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:49,550::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:49,550::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:49,551::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`743143a3-d667-4e86-946a-0f98dfab88b9`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:49,551::task::827::TaskManager.Task::(resourceAcquired) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::_resourcesAcquired: Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:49,551::task::990::TaskManager.Task::(_decref) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::ref 1 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:49,553::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::INFO::2014-09-26 04:04:49,555::volume::879::Storage.Volume::(getInfo) Info request: sdUUID=e4883354-fa70-4314-bcc0-6ee12c39e3a2 imgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f volUUID = f636aa62-3568-41f5-8b84-0bb69cd408a5 
>Thread-21513::INFO::2014-09-26 04:04:49,568::volume::909::Storage.Volume::(getInfo) e4883354-fa70-4314-bcc0-6ee12c39e3a2/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 info is {'status': 'OK', 'domain': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2', 'voltype': 'LEAF', 'description': 'Exported by virt-v2v 1.27.54', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'ctime': '1411625000', 'disktype': '1', 'legality': 'LEGAL', 'mtime': '1411625000', 'apparentsize': '4180475904', 'children': [], 'pool': '', 'capacity': '8589934592', 'uuid': 'f636aa62-3568-41f5-8b84-0bb69cd408a5', 'truesize': '4180353024', 'type': 'SPARSE'}
>Thread-21513::INFO::2014-09-26 04:04:49,568::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2', 'voltype': 'LEAF', 'description': 'Exported by virt-v2v 1.27.54', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'ctime': '1411625000', 'disktype': '1', 'legality': 'LEGAL', 'mtime': '1411625000', 'apparentsize': '4180475904', 'children': [], 'pool': '', 'capacity': '8589934592', 'uuid': 'f636aa62-3568-41f5-8b84-0bb69cd408a5', 'truesize': '4180353024', 'type': 'SPARSE'}}
>Thread-21513::DEBUG::2014-09-26 04:04:49,568::task::1185::TaskManager.Task::(prepare) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::finished: {'info': {'status': 'OK', 'domain': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2', 'voltype': 'LEAF', 'description': 'Exported by virt-v2v 1.27.54', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'ctime': '1411625000', 'disktype': '1', 'legality': 'LEGAL', 'mtime': '1411625000', 'apparentsize': '4180475904', 'children': [], 'pool': '', 'capacity': '8589934592', 'uuid': 'f636aa62-3568-41f5-8b84-0bb69cd408a5', 'truesize': '4180353024', 'type': 'SPARSE'}}
>Thread-21513::DEBUG::2014-09-26 04:04:49,568::task::595::TaskManager.Task::(_updateState) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:49,568::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:49,569::task::990::TaskManager.Task::(_decref) Task=`4d2737cd-f4af-4a5b-b080-cab7f51a0561`::ref 0 aborting False
>Thread-22::DEBUG::2014-09-26 04:04:49,739::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:04:49,753::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000317455 s, 1.6 MB/s\n'; <rc> = 0
>Thread-21513::DEBUG::2014-09-26 04:04:49,862::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [19afe406]
>Thread-21513::DEBUG::2014-09-26 04:04:49,863::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:49,863::logUtils::44::dispatcher::(wrapper) Run and protect: copyImage(sdUUID='e4883354-fa70-4314-bcc0-6ee12c39e3a2', spUUID='00000002-0002-0002-0002-0000000002c4', vmUUID='', srcImgUUID='5649d3a7-4025-45e6-99f9-d9682b82ee0f', srcVolUUID='f636aa62-3568-41f5-8b84-0bb69cd408a5', dstImgUUID='5649d3a7-4025-45e6-99f9-d9682b82ee0f', dstVolUUID='f636aa62-3568-41f5-8b84-0bb69cd408a5', description='', dstSdUUID='946b78c7-b21e-4d88-b4ee-fee464cc4ce9', volType=8, volFormat=5, preallocate=2, postZero='false', force='true')
>Thread-21513::DEBUG::2014-09-26 04:04:49,865::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::INFO::2014-09-26 04:04:49,870::image::285::Storage.Image::(isLegal) image 5649d3a7-4025-45e6-99f9-d9682b82ee0f in domain e4883354-fa70-4314-bcc0-6ee12c39e3a2 has vollist ['f636aa62-3568-41f5-8b84-0bb69cd408a5']
>Thread-21513::DEBUG::2014-09-26 04:04:49,870::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::DEBUG::2014-09-26 04:04:49,879::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::DEBUG::2014-09-26 04:04:49,884::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::DEBUG::2014-09-26 04:04:49,888::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>Thread-21513::INFO::2014-09-26 04:04:49,895::image::215::Storage.Image::(getChain) sdUUID=e4883354-fa70-4314-bcc0-6ee12c39e3a2 imgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f chain=[<storage.fileVolume.FileVolume object at 0x7f5b14085750>] 
>Thread-21513::DEBUG::2014-09-26 04:04:49,899::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`f49ea2d7-7b00-426e-891c-fb655671c1f1`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1793' at 'copyImage'
>Thread-21513::DEBUG::2014-09-26 04:04:49,899::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:49,901::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:49,901::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`f49ea2d7-7b00-426e-891c-fb655671c1f1`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:49,902::task::827::TaskManager.Task::(resourceAcquired) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_resourcesAcquired: Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:49,902::task::990::TaskManager.Task::(_decref) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::ref 1 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:49,903::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`dae19f55-5adf-4adf-b1a2-dee547eff7fa`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1793' at 'copyImage'
>Thread-21513::DEBUG::2014-09-26 04:04:49,903::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:49,903::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:49,903::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2`ReqID=`dae19f55-5adf-4adf-b1a2-dee547eff7fa`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:49,904::task::827::TaskManager.Task::(resourceAcquired) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_resourcesAcquired: Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:49,904::task::990::TaskManager.Task::(_decref) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::ref 1 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:49,905::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>Thread-21513::DEBUG::2014-09-26 04:04:49,914::taskManager::68::TaskManager::(scheduleJob) scheduled job copyImage_5649d3a7-4025-45e6-99f9-d9682b82ee0f for task dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 
>Thread-21513::INFO::2014-09-26 04:04:49,914::logUtils::47::dispatcher::(wrapper) Run and protect: copyImage, Return response: None
>Thread-21513::DEBUG::2014-09-26 04:04:49,914::task::1180::TaskManager.Task::(prepare) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Prepare: 1 jobs exist, move to acquiring
>Thread-21513::DEBUG::2014-09-26 04:04:49,914::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state preparing -> state acquiring
>Thread-21513::DEBUG::2014-09-26 04:04:49,915::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>Thread-21513::DEBUG::2014-09-26 04:04:49,924::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state acquiring -> state queued
>Thread-21513::DEBUG::2014-09-26 04:04:49,925::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>Thread-21513::DEBUG::2014-09-26 04:04:49,936::taskManager::50::TaskManager::(_queueTask) queuing task: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605
>5e43d940-f075-4938-8a2c-e5d8a5ada7b5::DEBUG::2014-09-26 04:04:49,938::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-21513::DEBUG::2014-09-26 04:04:49,937::taskManager::56::TaskManager::(_queueTask) task queued: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,939::threadPool::200::Misc.ThreadPool.WorkerThread::(_processNextTask) Task: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 running: <bound method Task.commit of <storage.task.Task instance at 0x7f5b040b2d40>> with: None
>Thread-21513::DEBUG::2014-09-26 04:04:49,941::task::1182::TaskManager.Task::(prepare) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::returning
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,942::task::1194::TaskManager.Task::(commit) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::committing task: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605
>Thread-21513::DEBUG::2014-09-26 04:04:49,945::task::990::TaskManager.Task::(_decref) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::ref 0 aborting False
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,946::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state queued -> state running
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,956::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,970::task::905::TaskManager.Task::(_runJobs) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Task.run: running job 0: copyImage_5649d3a7-4025-45e6-99f9-d9682b82ee0f: <bound method StoragePool.copyImage of <storage.sp.StoragePool object at 0x7f5b140c6990>> (args: ('e4883354-fa70-4314-bcc0-6ee12c39e3a2', '', '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'f636aa62-3568-41f5-8b84-0bb69cd408a5', '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'f636aa62-3568-41f5-8b84-0bb69cd408a5', '', '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 8, 5, 2, False, True) kwargs: {})
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,970::task::331::TaskManager.Task::(run) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Job.run: running copyImage_5649d3a7-4025-45e6-99f9-d9682b82ee0f: <bound method StoragePool.copyImage of <storage.sp.StoragePool object at 0x7f5b140c6990>> (args: ('e4883354-fa70-4314-bcc0-6ee12c39e3a2', '', '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'f636aa62-3568-41f5-8b84-0bb69cd408a5', '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'f636aa62-3568-41f5-8b84-0bb69cd408a5', '', '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 8, 5, 2, False, True) kwargs: {}) callback None
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,970::resourceManager::198::ResourceManager.Request::(__init__) ResName=`e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`c89082c7-17de-4f12-ab6f-555472754555`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1495' at 'copyImage'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,971::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' for lock type 'shared'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,973::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,977::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,982::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:49,989::image::215::Storage.Image::(getChain) sdUUID=e4883354-fa70-4314-bcc0-6ee12c39e3a2 imgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f chain=[<storage.fileVolume.FileVolume object at 0x7f5b140c3ad0>] 
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,993::resourceManager::198::ResourceManager.Request::(__init__) ResName=`e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5`ReqID=`1fe57f50-2430-4a8d-8c70-2bfe758558b1`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '172' at '__getResourceCandidatesList'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,993::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5' for lock type 'shared'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,993::resourceManager::601::ResourceManager::(registerResource) Resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5' is free. Now locking as 'shared' (1 active user)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,993::resourceManager::238::ResourceManager.Request::(grant) ResName=`e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5`ReqID=`1fe57f50-2430-4a8d-8c70-2bfe758558b1`::Granted request
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,994::resourceManager::601::ResourceManager::(registerResource) Resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free. Now locking as 'shared' (1 active user)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,994::resourceManager::238::ResourceManager.Request::(grant) ResName=`e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`c89082c7-17de-4f12-ab6f-555472754555`::Granted request
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,994::resourceManager::198::ResourceManager.Request::(__init__) ResName=`946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`ceb33021-917d-4d0e-bd99-cd7902e93dff`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1497' at 'copyImage'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,995::resourceManager::542::ResourceManager::(registerResource) Trying to register resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' for lock type 'exclusive'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,995::resourceFactories::125::Storage.ResourcesFactories::(__getResourceCandidatesList) Image 5649d3a7-4025-45e6-99f9-d9682b82ee0f does not exist in domain 946b78c7-b21e-4d88-b4ee-fee464cc4ce9
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,996::resourceManager::601::ResourceManager::(registerResource) Resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free. Now locking as 'exclusive' (1 active user)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,996::resourceManager::238::ResourceManager.Request::(grant) ResName=`946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`ceb33021-917d-4d0e-bd99-cd7902e93dff`::Granted request
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:49,996::image::647::Storage.Image::(copyCollapsed) sdUUID=e4883354-fa70-4314-bcc0-6ee12c39e3a2 vmUUID= srcImgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f srcVolUUID=f636aa62-3568-41f5-8b84-0bb69cd408a5 dstImgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f dstVolUUID=f636aa62-3568-41f5-8b84-0bb69cd408a5 dstSdUUID=946b78c7-b21e-4d88-b4ee-fee464cc4ce9 volType=8 volFormat=RAW preallocate=SPARSE force=True postZero=False
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:49,997::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,023::image::697::Storage.Image::(copyCollapsed) copy source e4883354-fa70-4314-bcc0-6ee12c39e3a2:5649d3a7-4025-45e6-99f9-d9682b82ee0f:f636aa62-3568-41f5-8b84-0bb69cd408a5 vol size 16777216 destination 946b78c7-b21e-4d88-b4ee-fee464cc4ce9:5649d3a7-4025-45e6-99f9-d9682b82ee0f:f636aa62-3568-41f5-8b84-0bb69cd408a5 apparentsize 8164992
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,024::image::285::Storage.Image::(isLegal) image 5649d3a7-4025-45e6-99f9-d9682b82ee0f in domain 946b78c7-b21e-4d88-b4ee-fee464cc4ce9 has vollist []
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,024::image::709::Storage.Image::(copyCollapsed) delete image 5649d3a7-4025-45e6-99f9-d9682b82ee0f on domain 946b78c7-b21e-4d88-b4ee-fee464cc4ce9 before overwriting
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::WARNING::2014-09-26 04:04:50,028::image::82::Storage.Image::(_deleteImage) No volumes found for image 5649d3a7-4025-45e6-99f9-d9682b82ee0f. {'28a96d8b-fecc-48e0-8c24-fc864175ea59': ImgsPar(imgs=('2fa21597-c8fb-4278-b020-339d1ed98e06',), parent=None), 'a6308a81-ce91-4272-8e0f-ccb12f3db8a0': ImgsPar(imgs=('809a0238-fed4-4254-8cfe-9c31062bfcbe',), parent=None), '159b6f5f-8cbb-4f2f-ac51-0d199d9663c7': ImgsPar(imgs=('ae2709dd-acec-4342-8c6b-baf3252dd9a3',), parent=None), '3b73f780-03a2-4609-9135-bde0e892edf5': ImgsPar(imgs=('e844160d-b559-4858-a03b-566de70c5ae2',), parent=None), '184584f4-d1d2-4571-8394-945bf8ac4643': ImgsPar(imgs=('a7710d12-d546-4d1c-a493-9462ef600ed9',), parent=None), '892c3ba6-bba7-4fc8-b58b-342e49ffcc93': ImgsPar(imgs=('8e3a6396-060f-4ecc-9201-84c5b035a076',), parent=None), 'c273e1ad-6f96-4fc5-a74b-1836165e9f27': ImgsPar(imgs=('3fa463b2-1469-4784-b857-21e7b79cc20a',), parent=None), 'd0978ddf-bacd-4a23-bd5a-11fc7e529c62': ImgsPar(imgs=('b47408a1-79e2-48b3-9d24-a777c815ca0f',), parent=None)}
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,028::image::123::Storage.Image::(create) Create placeholder /rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f for image's volumes
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,029::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,041::volume::443::Storage.Volume::(create) Creating volume f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,042::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,056::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,073::fileVolume::144::Storage.Volume::(_create) Request to create RAW volume /rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 with size = 20480 sectors
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,076::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,096::fileVolume::395::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=f636aa62-3568-41f5-8b84-0bb69cd408a5 sdUUID=946b78c7-b21e-4d88-b4ee-fee464cc4ce9, metaId=('/rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5',)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,112::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,129::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,135::volume::789::Storage.Volume::(prepare) Volume: preparing volume e4883354-fa70-4314-bcc0-6ee12c39e3a2/f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,145::volume::789::Storage.Volume::(prepare) Volume: preparing volume 946b78c7-b21e-4d88-b4ee-fee464cc4ce9/f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,159::volume::1094::Storage.Volume::(qemuConvert) (qemuConvert): COPY /rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 (qcow2) to /rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 (raw) START
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,160::utils::683::Storage.Misc.excCmd::(watchCmd) '/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/qemu-img convert -t none -f qcow2 /rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 -O raw /rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5' (cwd None)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,173::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,204::utils::697::Storage.Misc.excCmd::(watchCmd) FAILED: <err> = ["'image' uses a qcow2 feature which is not supported by this qemu version: QCOW version 3", "Could not open '/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5': Operation not supported", "Could not open '/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5'"]; <rc> = 1
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,205::volume::1111::Storage.Volume::(qemuConvert) (qemuConvert): COPY /rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 to /rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5 DONE
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::ERROR::2014-09-26 04:04:50,205::image::772::Storage.Image::(copyCollapsed) Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/image.py", line 760, in copyCollapsed
>CopyImageError: low level Image copy failed: ('General Storage Exception: (\'rc: 1, err: ["\\\'image\\\' uses a qcow2 feature which is not supported by this qemu version: QCOW version 3", "Could not open \\\'/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\\\': Operation not supported", "Could not open \\\'/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\\\'"]\',)',)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,206::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,206::resourceManager::635::ResourceManager::(releaseResource) Released resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' (0 active users)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,206::resourceManager::641::ResourceManager::(releaseResource) Resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free, finding out if anyone is waiting for it.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,206::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource '946b78c7-b21e-4d88-b4ee-fee464cc4ce9_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f', Clearing records.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,206::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,207::resourceManager::635::ResourceManager::(releaseResource) Released resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' (0 active users)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,207::resourceManager::641::ResourceManager::(releaseResource) Resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free, finding out if anyone is waiting for it.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,207::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,207::resourceManager::635::ResourceManager::(releaseResource) Released resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5' (0 active users)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,207::resourceManager::641::ResourceManager::(releaseResource) Resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5' is free, finding out if anyone is waiting for it.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,208::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_volumeNS.f636aa62-3568-41f5-8b84-0bb69cd408a5', Clearing records.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,208::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'e4883354-fa70-4314-bcc0-6ee12c39e3a2_imageNS.5649d3a7-4025-45e6-99f9-d9682b82ee0f', Clearing records.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::ERROR::2014-09-26 04:04:50,208::task::866::TaskManager.Task::(_setError) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 873, in _run
>  File "/usr/share/vdsm/storage/task.py", line 334, in run
>  File "/usr/share/vdsm/storage/securable.py", line 75, in wrapper
>  File "/usr/share/vdsm/storage/sp.py", line 1502, in copyImage
>  File "/usr/share/vdsm/storage/image.py", line 760, in copyCollapsed
>CopyImageError: low level Image copy failed: ('General Storage Exception: (\'rc: 1, err: ["\\\'image\\\' uses a qcow2 feature which is not supported by this qemu version: QCOW version 3", "Could not open \\\'/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\\\': Operation not supported", "Could not open \\\'/rhev/data-center/00000002-0002-0002-0002-0000000002c4/e4883354-fa70-4314-bcc0-6ee12c39e3a2/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f/f636aa62-3568-41f5-8b84-0bb69cd408a5\\\'"]\',)',)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,209::task::885::TaskManager.Task::(_run) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Task._run: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 () {} failed - stopping task
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,209::task::1211::TaskManager.Task::(stop) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::stopping in state running (force False)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,209::task::990::TaskManager.Task::(_decref) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::ref 1 aborting True
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,209::task::916::TaskManager.Task::(_runJobs) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::aborting: Task is aborted: 'low level Image copy failed' - code 261
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,209::task::990::TaskManager.Task::(_decref) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::ref 0 aborting True
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,210::task::925::TaskManager.Task::(_doAbort) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Task._doAbort: force False
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,210::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,210::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state running -> state aborting
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,210::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,227::task::550::TaskManager.Task::(__state_aborting) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_aborting: recover policy auto
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,228::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state aborting -> state racquiring
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,228::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,245::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state racquiring -> state recovering
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,246::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>Dummy-39::DEBUG::2014-09-26 04:04:50,256::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,291::task::798::TaskManager.Task::(_recover) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_recover
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,293::task::805::TaskManager.Task::(_recover) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::running recovery Kill-15129: Volume->killProcRollback(15129,1411704290.17)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,295::volume::163::Storage.Volume::(killProcRollback) pid=15129 ctime=1411704290.17
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,297::volume::167::Storage.Volume::(killProcRollback) pid=15129 ctime=1411704290.17 ([Errno 3] Could not find process with pid 15129)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,298::task::805::TaskManager.Task::(_recover) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::running recovery Create volume rollback: FileVolume->createVolumeRollback(/rhev/data-center/00000002-0002-0002-0002-0000000002c4,946b78c7-b21e-4d88-b4ee-fee464cc4ce9,5649d3a7-4025-45e6-99f9-d9682b82ee0f,f636aa62-3568-41f5-8b84-0bb69cd408a5,/rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,301::volume::363::Storage.Volume::(createVolumeRollback) createVolumeRollback: repoPath=/rhev/data-center/00000002-0002-0002-0002-0000000002c4 sdUUID=946b78c7-b21e-4d88-b4ee-fee464cc4ce9 imgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f volUUID=f636aa62-3568-41f5-8b84-0bb69cd408a5 imageDir=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,307::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,318::fileVolume::166::Storage.Volume::(delete) Request to delete volume f636aa62-3568-41f5-8b84-0bb69cd408a5
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,319::volume::646::Storage.Volume::(setLegality) sdUUID=946b78c7-b21e-4d88-b4ee-fee464cc4ce9 imgUUID=5649d3a7-4025-45e6-99f9-d9682b82ee0f volUUID = f636aa62-3568-41f5-8b84-0bb69cd408a5 legality = ILLEGAL 
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,353::task::805::TaskManager.Task::(_recover) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::running recovery create image rollback: 5649d3a7-4025-45e6-99f9-d9682b82ee0f: Image->createImageRollback(/rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::INFO::2014-09-26 04:04:50,355::image::102::Storage.Image::(createImageRollback) createImageRollback: imageDir=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/images/5649d3a7-4025-45e6-99f9-d9682b82ee0f
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,357::task::805::TaskManager.Task::(_recover) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::running recovery None
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,359::task::786::TaskManager.Task::(_recoverDone) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::Recover Done: state recovering
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,361::task::595::TaskManager.Task::(_updateState) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::moving from state recovering -> state recovered
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,364::task::752::TaskManager.Task::(_save) Task=`dc8e8ef8-4ba3-4e69-b186-d0a96b4df605`::_save: orig /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605 temp /rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/master/tasks/dc8e8ef8-4ba3-4e69-b186-d0a96b4df605.temp
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,395::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9': < ResourceRef 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', isValid: 'True' obj: 'None'>, 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2': < ResourceRef 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', isValid: 'True' obj: 'None'>}
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,397::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,401::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,405::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' (0 active users)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,407::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free, finding out if anyone is waiting for it.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,408::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', Clearing records.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,411::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2'
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,413::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' (0 active users)
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,414::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2' is free, finding out if anyone is waiting for it.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,415::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.e4883354-fa70-4314-bcc0-6ee12c39e3a2', Clearing records.
>dc8e8ef8-4ba3-4e69-b186-d0a96b4df605::DEBUG::2014-09-26 04:04:50,418::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Dummy-39::DEBUG::2014-09-26 04:04:50,458::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.11937 s, 8.6 MB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:04:51,011::task::595::TaskManager.Task::(_updateState) Task=`ba35f1fc-6c15-413f-86f7-d6703614817b`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:51,011::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-21512::INFO::2014-09-26 04:04:51,011::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000592958', 'lastCheck': '5.7', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000317455', 'lastCheck': '1.3', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:04:51,012::task::1185::TaskManager.Task::(prepare) Task=`ba35f1fc-6c15-413f-86f7-d6703614817b`::finished: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000592958', 'lastCheck': '5.7', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000317455', 'lastCheck': '1.3', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:04:51,012::task::595::TaskManager.Task::(_updateState) Task=`ba35f1fc-6c15-413f-86f7-d6703614817b`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:51,012::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:51,012::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:51,013::task::990::TaskManager.Task::(_decref) Task=`ba35f1fc-6c15-413f-86f7-d6703614817b`::ref 0 aborting False
>Thread-21512::DEBUG::2014-09-26 04:04:52,121::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21512::DEBUG::2014-09-26 04:04:52,121::task::595::TaskManager.Task::(_updateState) Task=`3eca7a2c-f830-4306-9866-97ee98b926f5`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:52,121::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-21512::DEBUG::2014-09-26 04:04:52,121::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
>Thread-21512::DEBUG::2014-09-26 04:04:52,121::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605
>Thread-21512::DEBUG::2014-09-26 04:04:52,122::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 261, 'message': 'low level Image copy failed', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': 'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605'}
>Thread-21512::DEBUG::2014-09-26 04:04:52,122::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605': {'code': 261, 'message': 'low level Image copy failed', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': 'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605'}}
>Thread-21512::INFO::2014-09-26 04:04:52,122::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605': {'code': 261, 'message': 'low level Image copy failed', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': 'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605'}}}
>Thread-21512::DEBUG::2014-09-26 04:04:52,122::task::1185::TaskManager.Task::(prepare) Task=`3eca7a2c-f830-4306-9866-97ee98b926f5`::finished: {'allTasksStatus': {'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605': {'code': 261, 'message': 'low level Image copy failed', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': 'dc8e8ef8-4ba3-4e69-b186-d0a96b4df605'}}}
>Thread-21512::DEBUG::2014-09-26 04:04:52,122::task::595::TaskManager.Task::(_updateState) Task=`3eca7a2c-f830-4306-9866-97ee98b926f5`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:52,122::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:52,123::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:52,123::task::990::TaskManager.Task::(_decref) Task=`3eca7a2c-f830-4306-9866-97ee98b926f5`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:52,356::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [77724b38]
>Thread-21513::DEBUG::2014-09-26 04:04:52,356::task::595::TaskManager.Task::(_updateState) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:52,356::logUtils::44::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='946b78c7-b21e-4d88-b4ee-fee464cc4ce9', spUUID='00000002-0002-0002-0002-0000000002c4', imgUUID='5649d3a7-4025-45e6-99f9-d9682b82ee0f', postZero='false', force='false')
>Thread-21513::DEBUG::2014-09-26 04:04:52,357::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`bb674a45-aa3f-43b6-9dcd-a34182083fa7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1507' at 'deleteImage'
>Thread-21513::DEBUG::2014-09-26 04:04:52,357::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f' for lock type 'exclusive'
>Thread-21513::DEBUG::2014-09-26 04:04:52,357::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free. Now locking as 'exclusive' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:52,357::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f`ReqID=`bb674a45-aa3f-43b6-9dcd-a34182083fa7`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:52,357::task::827::TaskManager.Task::(resourceAcquired) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::_resourcesAcquired: Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f (exclusive)
>Thread-21513::DEBUG::2014-09-26 04:04:52,358::task::990::TaskManager.Task::(_decref) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::ref 1 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:52,358::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`2e967ad4-d5ca-4964-8c37-60a3b5161f06`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1508' at 'deleteImage'
>Thread-21513::DEBUG::2014-09-26 04:04:52,358::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:52,358::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:52,358::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9`ReqID=`2e967ad4-d5ca-4964-8c37-60a3b5161f06`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:52,359::task::827::TaskManager.Task::(resourceAcquired) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::_resourcesAcquired: Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:52,359::task::990::TaskManager.Task::(_decref) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::ref 1 aborting False
>Thread-21513::ERROR::2014-09-26 04:04:52,362::hsm::1513::Storage.HSM::(deleteImage) Empty or not found image 5649d3a7-4025-45e6-99f9-d9682b82ee0f in SD 946b78c7-b21e-4d88-b4ee-fee464cc4ce9. {'28a96d8b-fecc-48e0-8c24-fc864175ea59': ImgsPar(imgs=('2fa21597-c8fb-4278-b020-339d1ed98e06',), parent=None), 'a6308a81-ce91-4272-8e0f-ccb12f3db8a0': ImgsPar(imgs=('809a0238-fed4-4254-8cfe-9c31062bfcbe',), parent=None), '159b6f5f-8cbb-4f2f-ac51-0d199d9663c7': ImgsPar(imgs=('ae2709dd-acec-4342-8c6b-baf3252dd9a3',), parent=None), '3b73f780-03a2-4609-9135-bde0e892edf5': ImgsPar(imgs=('e844160d-b559-4858-a03b-566de70c5ae2',), parent=None), '184584f4-d1d2-4571-8394-945bf8ac4643': ImgsPar(imgs=('a7710d12-d546-4d1c-a493-9462ef600ed9',), parent=None), '892c3ba6-bba7-4fc8-b58b-342e49ffcc93': ImgsPar(imgs=('8e3a6396-060f-4ecc-9201-84c5b035a076',), parent=None), 'c273e1ad-6f96-4fc5-a74b-1836165e9f27': ImgsPar(imgs=('3fa463b2-1469-4784-b857-21e7b79cc20a',), parent=None), 'd0978ddf-bacd-4a23-bd5a-11fc7e529c62': ImgsPar(imgs=('b47408a1-79e2-48b3-9d24-a777c815ca0f',), parent=None)}
>Thread-21513::ERROR::2014-09-26 04:04:52,362::task::866::TaskManager.Task::(_setError) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 873, in _run
>  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
>  File "/usr/share/vdsm/storage/hsm.py", line 1514, in deleteImage
>ImageDoesNotExistInSD: Image does not exist in domain: 'image=5649d3a7-4025-45e6-99f9-d9682b82ee0f, domain=946b78c7-b21e-4d88-b4ee-fee464cc4ce9'
>Thread-21513::DEBUG::2014-09-26 04:04:52,363::task::885::TaskManager.Task::(_run) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::Task._run: 606d75c2-4b9c-45d2-b245-0c42b80d022a ('946b78c7-b21e-4d88-b4ee-fee464cc4ce9', '00000002-0002-0002-0002-0000000002c4', '5649d3a7-4025-45e6-99f9-d9682b82ee0f', 'false', 'false') {} failed - stopping task
>Thread-21513::DEBUG::2014-09-26 04:04:52,363::task::1211::TaskManager.Task::(stop) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::stopping in state preparing (force False)
>Thread-21513::DEBUG::2014-09-26 04:04:52,363::task::990::TaskManager.Task::(_decref) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::ref 1 aborting True
>Thread-21513::INFO::2014-09-26 04:04:52,363::task::1168::TaskManager.Task::(prepare) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::aborting: Task is aborted: 'Image does not exist in domain' - code 268
>Thread-21513::DEBUG::2014-09-26 04:04:52,363::task::1173::TaskManager.Task::(prepare) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::Prepare: aborted: Image does not exist in domain
>Thread-21513::DEBUG::2014-09-26 04:04:52,363::task::990::TaskManager.Task::(_decref) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::ref 0 aborting True
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::task::925::TaskManager.Task::(_doAbort) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::Task._doAbort: force False
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::task::595::TaskManager.Task::(_updateState) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::moving from state preparing -> state aborting
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::task::550::TaskManager.Task::(__state_aborting) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::_aborting: recover policy none
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::task::595::TaskManager.Task::(_updateState) Task=`606d75c2-4b9c-45d2-b245-0c42b80d022a`::moving from state aborting -> state failed
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9': < ResourceRef 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', isValid: 'True' obj: 'None'>, 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f': < ResourceRef 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:52,364::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9'
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.946b78c7-b21e-4d88-b4ee-fee464cc4ce9', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f'
>Thread-21513::DEBUG::2014-09-26 04:04:52,365::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:52,366::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:52,366::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5649d3a7-4025-45e6-99f9-d9682b82ee0f', Clearing records.
>Thread-21513::ERROR::2014-09-26 04:04:52,366::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Image does not exist in domain: 'image=5649d3a7-4025-45e6-99f9-d9682b82ee0f, domain=946b78c7-b21e-4d88-b4ee-fee464cc4ce9'", 'code': 268}}
>Dummy-39::DEBUG::2014-09-26 04:04:52,472::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:52,562::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0327776 s, 31.2 MB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:04:52,573::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21512::DEBUG::2014-09-26 04:04:52,574::task::595::TaskManager.Task::(_updateState) Task=`f79c88c5-0e7b-47eb-a470-3bc5c5b8a6cf`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:52,575::logUtils::44::dispatcher::(wrapper) Run and protect: clearTask(taskID='dc8e8ef8-4ba3-4e69-b186-d0a96b4df605', spUUID=None, options=None)
>Thread-21512::DEBUG::2014-09-26 04:04:52,576::taskManager::161::TaskManager::(clearTask) Entry. taskID: dc8e8ef8-4ba3-4e69-b186-d0a96b4df605
>Thread-21512::DEBUG::2014-09-26 04:04:52,579::taskManager::166::TaskManager::(clearTask) Return.
>Thread-21512::INFO::2014-09-26 04:04:52,580::logUtils::47::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-21512::DEBUG::2014-09-26 04:04:52,580::task::1185::TaskManager.Task::(prepare) Task=`f79c88c5-0e7b-47eb-a470-3bc5c5b8a6cf`::finished: None
>Thread-21512::DEBUG::2014-09-26 04:04:52,581::task::595::TaskManager.Task::(_updateState) Task=`f79c88c5-0e7b-47eb-a470-3bc5c5b8a6cf`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:52,582::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:52,582::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:52,583::task::990::TaskManager.Task::(_decref) Task=`f79c88c5-0e7b-47eb-a470-3bc5c5b8a6cf`::ref 0 aborting False
>Thread-21512::DEBUG::2014-09-26 04:04:53,148::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [3042b692]
>Thread-21512::DEBUG::2014-09-26 04:04:53,149::task::595::TaskManager.Task::(_updateState) Task=`3d4df29e-79b5-4a4b-9612-5cdf68ecbdf5`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:04:53,149::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21512::INFO::2014-09-26 04:04:53,149::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:53,150::task::1185::TaskManager.Task::(prepare) Task=`3d4df29e-79b5-4a4b-9612-5cdf68ecbdf5`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:04:53,150::task::595::TaskManager.Task::(_updateState) Task=`3d4df29e-79b5-4a4b-9612-5cdf68ecbdf5`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:04:53,150::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:04:53,150::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:04:53,150::task::990::TaskManager.Task::(_decref) Task=`3d4df29e-79b5-4a4b-9612-5cdf68ecbdf5`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:04:53,210::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38] flowID [3042b692]
>Thread-21513::DEBUG::2014-09-26 04:04:53,210::task::595::TaskManager.Task::(_updateState) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:04:53,211::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21513::DEBUG::2014-09-26 04:04:53,211::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`abd26d83-8602-426e-acc5-d90c4988e66e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2573' at 'getStoragePoolInfo'
>Thread-21513::DEBUG::2014-09-26 04:04:53,211::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000002c4' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:04:53,212::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:04:53,212::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`abd26d83-8602-426e-acc5-d90c4988e66e`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:04:53,212::task::827::TaskManager.Task::(resourceAcquired) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::_resourcesAcquired: Storage.00000002-0002-0002-0002-0000000002c4 (shared)
>Thread-21513::DEBUG::2014-09-26 04:04:53,213::task::990::TaskManager.Task::(_decref) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:04:53,240::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:53,241::task::1185::TaskManager.Task::(prepare) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::finished: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:04:53,241::task::595::TaskManager.Task::(_updateState) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:04:53,241::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.00000002-0002-0002-0002-0000000002c4': < ResourceRef 'Storage.00000002-0002-0002-0002-0000000002c4', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:04:53,241::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:04:53,242::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000002c4'
>Thread-21513::DEBUG::2014-09-26 04:04:53,242::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000002c4' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:04:53,242::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:04:53,242::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000002c4', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:04:53,243::task::990::TaskManager.Task::(_decref) Task=`23ebf2f7-7c25-4974-a7d1-8c66a73e0ecc`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:04:54,588::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:54,683::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0367792 s, 27.8 MB/s\n'; <rc> = 0
>Thread-36352::DEBUG::2014-09-26 04:04:55,310::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.6.8:_var_v2v__export/e4883354-fa70-4314-bcc0-6ee12c39e3a2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-36352::DEBUG::2014-09-26 04:04:55,325::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n355 bytes (355 B) copied, 0.000561807 s, 632 kB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:56,698::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:56,796::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0402534 s, 25.4 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:04:58,811::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:04:58,901::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0328887 s, 31.1 MB/s\n'; <rc> = 0
>Thread-22::DEBUG::2014-09-26 04:04:59,785::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:04:59,799::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000310941 s, 1.6 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:05:00,916::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:05:01,015::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.033086 s, 30.9 MB/s\n'; <rc> = 0
>Dummy-39::DEBUG::2014-09-26 04:05:03,035::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:05:03,139::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.042209 s, 24.3 MB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:05:03,372::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21512::DEBUG::2014-09-26 04:05:03,373::task::595::TaskManager.Task::(_updateState) Task=`33e8bc05-4d6b-4403-abe7-dd1b17171377`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:05:03,373::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21512::INFO::2014-09-26 04:05:03,374::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:05:03,374::task::1185::TaskManager.Task::(prepare) Task=`33e8bc05-4d6b-4403-abe7-dd1b17171377`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-21512::DEBUG::2014-09-26 04:05:03,374::task::595::TaskManager.Task::(_updateState) Task=`33e8bc05-4d6b-4403-abe7-dd1b17171377`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:05:03,375::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:05:03,375::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:05:03,375::task::990::TaskManager.Task::(_decref) Task=`33e8bc05-4d6b-4403-abe7-dd1b17171377`::ref 0 aborting False
>Thread-21513::DEBUG::2014-09-26 04:05:03,435::BindingXMLRPC::251::vds::(wrapper) client [10.66.72.38]
>Thread-21513::DEBUG::2014-09-26 04:05:03,435::task::595::TaskManager.Task::(_updateState) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::moving from state init -> state preparing
>Thread-21513::INFO::2014-09-26 04:05:03,435::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-0000000002c4', options=None)
>Thread-21513::DEBUG::2014-09-26 04:05:03,436::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`938a0e84-6cab-4248-bd72-4d891679b199`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2573' at 'getStoragePoolInfo'
>Thread-21513::DEBUG::2014-09-26 04:05:03,436::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.00000002-0002-0002-0002-0000000002c4' for lock type 'shared'
>Thread-21513::DEBUG::2014-09-26 04:05:03,436::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free. Now locking as 'shared' (1 active user)
>Thread-21513::DEBUG::2014-09-26 04:05:03,437::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.00000002-0002-0002-0002-0000000002c4`ReqID=`938a0e84-6cab-4248-bd72-4d891679b199`::Granted request
>Thread-21513::DEBUG::2014-09-26 04:05:03,437::task::827::TaskManager.Task::(resourceAcquired) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::_resourcesAcquired: Storage.00000002-0002-0002-0002-0000000002c4 (shared)
>Thread-21513::DEBUG::2014-09-26 04:05:03,437::task::990::TaskManager.Task::(_decref) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::ref 1 aborting False
>Thread-21513::INFO::2014-09-26 04:05:03,468::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:05:03,469::task::1185::TaskManager.Task::(prepare) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::finished: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'e4883354-fa70-4314-bcc0-6ee12c39e3a2:Active,946b78c7-b21e-4d88-b4ee-fee464cc4ce9:Active', 'master_uuid': '946b78c7-b21e-4d88-b4ee-fee464cc4ce9', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'status': 'Active', 'diskfree': '270877589504', 'isoprefix': '', 'alerts': [], 'disktotal': '309502935040', 'version': 0}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'status': 'Active', 'diskfree': '502663020544', 'isoprefix': '', 'alerts': [], 'disktotal': '773094113280', 'version': 3}}}
>Thread-21513::DEBUG::2014-09-26 04:05:03,469::task::595::TaskManager.Task::(_updateState) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::moving from state preparing -> state finished
>Thread-21513::DEBUG::2014-09-26 04:05:03,469::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.00000002-0002-0002-0002-0000000002c4': < ResourceRef 'Storage.00000002-0002-0002-0002-0000000002c4', isValid: 'True' obj: 'None'>}
>Thread-21513::DEBUG::2014-09-26 04:05:03,469::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21513::DEBUG::2014-09-26 04:05:03,470::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.00000002-0002-0002-0002-0000000002c4'
>Thread-21513::DEBUG::2014-09-26 04:05:03,470::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.00000002-0002-0002-0002-0000000002c4' (0 active users)
>Thread-21513::DEBUG::2014-09-26 04:05:03,470::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.00000002-0002-0002-0002-0000000002c4' is free, finding out if anyone is waiting for it.
>Thread-21513::DEBUG::2014-09-26 04:05:03,470::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.00000002-0002-0002-0002-0000000002c4', Clearing records.
>Thread-21513::DEBUG::2014-09-26 04:05:03,471::task::990::TaskManager.Task::(_decref) Task=`78a841e5-2b7c-431f-9b9c-dbda09e9d987`::ref 0 aborting False
>Thread-39890::WARNING::2014-09-26 04:05:05,022::fileSD::673::scanDomains::(collectMetaFiles) Metadata collection for domain path /rhev/data-center/mnt/10.66.4.226:_NFS timedout
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll
>Timeout
>Dummy-39::DEBUG::2014-09-26 04:05:05,154::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:05:05,243::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.032557 s, 31.5 MB/s\n'; <rc> = 0
>Thread-36352::DEBUG::2014-09-26 04:05:05,356::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.6.8:_var_v2v__export/e4883354-fa70-4314-bcc0-6ee12c39e3a2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-36352::DEBUG::2014-09-26 04:05:05,370::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n355 bytes (355 B) copied, 0.000504511 s, 704 kB/s\n'; <rc> = 0
>Thread-21512::DEBUG::2014-09-26 04:05:06,628::task::595::TaskManager.Task::(_updateState) Task=`f3d1e3ad-1bef-4233-9a39-6fe54c833d2f`::moving from state init -> state preparing
>Thread-21512::INFO::2014-09-26 04:05:06,629::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-21512::INFO::2014-09-26 04:05:06,629::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000504511', 'lastCheck': '1.3', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000310941', 'lastCheck': '6.8', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:05:06,629::task::1185::TaskManager.Task::(prepare) Task=`f3d1e3ad-1bef-4233-9a39-6fe54c833d2f`::finished: {'e4883354-fa70-4314-bcc0-6ee12c39e3a2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000504511', 'lastCheck': '1.3', 'valid': True}, '946b78c7-b21e-4d88-b4ee-fee464cc4ce9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000310941', 'lastCheck': '6.8', 'valid': True}}
>Thread-21512::DEBUG::2014-09-26 04:05:06,630::task::595::TaskManager.Task::(_updateState) Task=`f3d1e3ad-1bef-4233-9a39-6fe54c833d2f`::moving from state preparing -> state finished
>Thread-21512::DEBUG::2014-09-26 04:05:06,630::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21512::DEBUG::2014-09-26 04:05:06,630::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21512::DEBUG::2014-09-26 04:05:06,630::task::990::TaskManager.Task::(_decref) Task=`f3d1e3ad-1bef-4233-9a39-6fe54c833d2f`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:05:07,258::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:05:07,355::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0401287 s, 25.5 MB/s\n'; <rc> = 0
>Thread-34838::DEBUG::2014-09-26 04:05:07,488::task::595::TaskManager.Task::(_updateState) Task=`4e91d701-e4bb-41ca-8675-f9d0e19c18bc`::moving from state init -> state preparing
>Thread-34838::INFO::2014-09-26 04:05:07,488::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='946b78c7-b21e-4d88-b4ee-fee464cc4ce9', spUUID='00000002-0002-0002-0002-0000000002c4', imgUUID='ae2709dd-acec-4342-8c6b-baf3252dd9a3', volUUID='159b6f5f-8cbb-4f2f-ac51-0d199d9663c7', options=None)
>Thread-34838::INFO::2014-09-26 04:05:07,491::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3449110528', 'apparentsize': '8589934592'}
>Thread-34838::DEBUG::2014-09-26 04:05:07,491::task::1185::TaskManager.Task::(prepare) Task=`4e91d701-e4bb-41ca-8675-f9d0e19c18bc`::finished: {'truesize': '3449110528', 'apparentsize': '8589934592'}
>Thread-34838::DEBUG::2014-09-26 04:05:07,491::task::595::TaskManager.Task::(_updateState) Task=`4e91d701-e4bb-41ca-8675-f9d0e19c18bc`::moving from state preparing -> state finished
>Thread-34838::DEBUG::2014-09-26 04:05:07,491::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-34838::DEBUG::2014-09-26 04:05:07,491::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-34838::DEBUG::2014-09-26 04:05:07,491::task::990::TaskManager.Task::(_decref) Task=`4e91d701-e4bb-41ca-8675-f9d0e19c18bc`::ref 0 aborting False
>Dummy-39::DEBUG::2014-09-26 04:05:09,369::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/00000002-0002-0002-0002-0000000002c4/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-39::DEBUG::2014-09-26 04:05:09,459::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0331299 s, 30.9 MB/s\n'; <rc> = 0
>Thread-22::DEBUG::2014-09-26 04:05:09,830::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.66.90.115:_vol_v2v__auto_nfs__data/946b78c7-b21e-4d88-b4ee-fee464cc4ce9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-22::DEBUG::2014-09-26 04:05:09,844::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.00032156 s, 1.6 MB/s\n'; <rc> = 0
>^C
>
>

Actions: View

Attachments on bug 1145582: 940368 | 940369 | 940644 | 940985 | 940986 | 940987 | 941372