Thread-329::DEBUG::2013-02-11 19:51:34,006::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-329::DEBUG::2013-02-11 19:51:34,007::task::568::TaskManager.Task::(_updateState) Task=`5ff2773d-21ee-422f-a4df-4bc20cacac67`::moving from state init -> state preparing
Thread-329::INFO::2013-02-11 19:51:34,007::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
Thread-329::DEBUG::2013-02-11 19:51:34,008::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
Thread-329::DEBUG::2013-02-11 19:51:34,008::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 7f2adac1-8eff-4381-8420-5c450d60959a
Thread-329::DEBUG::2013-02-11 19:51:34,008::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '7f2adac1-8eff-4381-8420-5c450d60959a'}
Thread-329::DEBUG::2013-02-11 19:51:34,008::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {'7f2adac1-8eff-4381-8420-5c450d60959a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '7f2adac1-8eff-4381-8420-5c450d60959a'}}
Thread-329::INFO::2013-02-11 19:51:34,008::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'7f2adac1-8eff-4381-8420-5c450d60959a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '7f2adac1-8eff-4381-8420-5c450d60959a'}}}
Thread-329::DEBUG::2013-02-11 19:51:34,009::task::1151::TaskManager.Task::(prepare) Task=`5ff2773d-21ee-422f-a4df-4bc20cacac67`::finished: {'allTasksStatus': {'7f2adac1-8eff-4381-8420-5c450d60959a': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '7f2adac1-8eff-4381-8420-5c450d60959a'}}}
Thread-329::DEBUG::2013-02-11 19:51:34,009::task::568::TaskManager.Task::(_updateState) Task=`5ff2773d-21ee-422f-a4df-4bc20cacac67`::moving from state preparing -> state finished
Thread-329::DEBUG::2013-02-11 19:51:34,009::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-329::DEBUG::2013-02-11 19:51:34,009::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-329::DEBUG::2013-02-11 19:51:34,010::task::957::TaskManager.Task::(_decref) Task=`5ff2773d-21ee-422f-a4df-4bc20cacac67`::ref 0 aborting False
Thread-330::DEBUG::2013-02-11 19:51:34,099::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-330::DEBUG::2013-02-11 19:51:34,100::task::568::TaskManager.Task::(_updateState) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::moving from state init -> state preparing
Thread-330::INFO::2013-02-11 19:51:34,100::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', imgUUID='509eb58c-2541-47b3-bdeb-3665011ce69f', volUUID='9ee3829a-d45b-4927-937c-5f7092138fd5', options=None)
Thread-330::DEBUG::2013-02-11 19:51:34,101::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e`ReqID=`f32ce9e6-8b61-4e60-a815-96ed7f24f931`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-330::DEBUG::2013-02-11 19:51:34,101::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e' for lock type 'shared'
Thread-330::DEBUG::2013-02-11 19:51:34,101::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e' is free. Now locking as 'shared' (1 active user)
Thread-330::DEBUG::2013-02-11 19:51:34,102::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e`ReqID=`f32ce9e6-8b61-4e60-a815-96ed7f24f931`::Granted request
Thread-330::DEBUG::2013-02-11 19:51:34,102::task::794::TaskManager.Task::(resourceAcquired) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::_resourcesAcquired: Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e (shared)
Thread-330::DEBUG::2013-02-11 19:51:34,102::task::957::TaskManager.Task::(_decref) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::ref 1 aborting False
Thread-330::DEBUG::2013-02-11 19:51:34,103::fileVolume::561::Storage.Volume::(validateVolumePath) validate path for 9ee3829a-d45b-4927-937c-5f7092138fd5
Thread-330::INFO::2013-02-11 19:51:34,105::volume::795::Storage.Volume::(getInfo) Info request: sdUUID=fc810722-3af0-4ca5-9a6e-1b4c40e76c1e imgUUID=509eb58c-2541-47b3-bdeb-3665011ce69f volUUID = 9ee3829a-d45b-4927-937c-5f7092138fd5 
Thread-330::DEBUG::2013-02-11 19:51:34,117::fileVolume::561::Storage.Volume::(validateVolumePath) validate path for 9ee3829a-d45b-4927-937c-5f7092138fd5
Thread-330::DEBUG::2013-02-11 19:51:34,121::fileVolume::561::Storage.Volume::(validateVolumePath) validate path for 9ee3829a-d45b-4927-937c-5f7092138fd5
Thread-330::INFO::2013-02-11 19:51:34,124::volume::824::Storage.Volume::(getInfo) fc810722-3af0-4ca5-9a6e-1b4c40e76c1e/509eb58c-2541-47b3-bdeb-3665011ce69f/9ee3829a-d45b-4927-937c-5f7092138fd5 info is {'status': 'OK', 'domain': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'voltype': 'LEAF', 'description': '', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '509eb58c-2541-47b3-bdeb-3665011ce69f', 'ctime': '1360583487', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '1360583487', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '9ee3829a-d45b-4927-937c-5f7092138fd5', 'truesize': '0', 'type': 'SPARSE'}
Thread-330::INFO::2013-02-11 19:51:34,124::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'voltype': 'LEAF', 'description': '', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '509eb58c-2541-47b3-bdeb-3665011ce69f', 'ctime': '1360583487', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '1360583487', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '9ee3829a-d45b-4927-937c-5f7092138fd5', 'truesize': '0', 'type': 'SPARSE'}}
Thread-330::DEBUG::2013-02-11 19:51:34,125::task::1151::TaskManager.Task::(prepare) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::finished: {'info': {'status': 'OK', 'domain': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'voltype': 'LEAF', 'description': '', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'RAW', 'image': '509eb58c-2541-47b3-bdeb-3665011ce69f', 'ctime': '1360583487', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '1360583487', 'apparentsize': '10737418240', 'children': [], 'pool': '', 'capacity': '10737418240', 'uuid': '9ee3829a-d45b-4927-937c-5f7092138fd5', 'truesize': '0', 'type': 'SPARSE'}}
Thread-330::DEBUG::2013-02-11 19:51:34,125::task::568::TaskManager.Task::(_updateState) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::moving from state preparing -> state finished
Thread-330::DEBUG::2013-02-11 19:51:34,125::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': < ResourceRef 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', isValid: 'True' obj: 'None'>}
Thread-330::DEBUG::2013-02-11 19:51:34,125::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-330::DEBUG::2013-02-11 19:51:34,125::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e'
Thread-330::DEBUG::2013-02-11 19:51:34,126::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e' (0 active users)
Thread-330::DEBUG::2013-02-11 19:51:34,126::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e' is free, finding out if anyone is waiting for it.
Thread-330::DEBUG::2013-02-11 19:51:34,126::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', Clearing records.
Thread-330::DEBUG::2013-02-11 19:51:34,126::task::957::TaskManager.Task::(_decref) Task=`338da6a5-402b-40ed-9a4c-184d267d5ee0`::ref 0 aborting False
Thread-331::DEBUG::2013-02-11 19:51:34,248::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-331::DEBUG::2013-02-11 19:51:34,248::task::568::TaskManager.Task::(_updateState) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::moving from state init -> state preparing
Thread-331::INFO::2013-02-11 19:51:34,249::logUtils::37::dispatcher::(wrapper) Run and protect: updateVM(spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', vmList=[{'imglist': '509eb58c-2541-47b3-bdeb-3665011ce69f', 'ovf': '<?xml version=\'1.0\' encoding=\'UTF-8\'?><ovf:Envelope xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1/" 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" ovf:version="3.2.0.0"><References><File ovf:href="509eb58c-2541-47b3-bdeb-3665011ce69f/9ee3829a-d45b-4927-937c-5f7092138fd5" ovf:id="9ee3829a-d45b-4927-937c-5f7092138fd5" ovf:size="10737418240" ovf:description="Active VM"/><Nic ovf:id="5171d908-f88e-4147-ba73-0923f3e6da16"/></References><Section xsi:type="ovf:NetworkSection_Type"><Info>List of networks</Info><Network ovf:name="Network 1"/></Section><Section xsi:type="ovf:DiskSection_Type"><Info>List of Virtual Disks</Info><Disk ovf:diskId="9ee3829a-d45b-4927-937c-5f7092138fd5" ovf:size="10" ovf:actual_size="0" ovf:vm_snapshot_id="81915e1b-b8fd-432c-ab8d-3104d212fec5" ovf:parentRef="" ovf:fileRef="509eb58c-2541-47b3-bdeb-3665011ce69f/9ee3829a-d45b-4927-937c-5f7092138fd5" ovf:format="http://www.vmware.com/specifications/vmdk.html#sparse" ovf:volume-format="RAW" ovf:volume-type="Sparse" ovf:disk-interface="VirtIO" ovf:boot="true" ovf:disk-alias="Centos_Disk1" ovf:disk-description="Centos_Disk1" ovf:wipe-after-delete="false"/></Section><Content ovf:id="out" xsi:type="ovf:VirtualSystem_Type"><Name>Centos</Name><TemplateId>00000000-0000-0000-0000-000000000000</TemplateId><TemplateName>Blank</TemplateName><Description>Centos</Description><Domain></Domain><CreationDate>2013/02/11 11:51:04</CreationDate><ExportDate>2013/02/11 11:51:34</ExportDate><IsInitilized>false</IsInitilized><IsAutoSuspend>false</IsAutoSuspend><TimeZone>Asia/Singapore</TimeZone><IsStateless>false</IsStateless><Origin>3</Origin><default_boot_sequence>1</default_boot_sequence><quota_id>00000000-0000-0000-0000-000000000000</quota_id><VmType>1</VmType><DefaultDisplayType>0</DefaultDisplayType><MinAllocatedMem>1024</MinAllocatedMem><Section ovf:id="1230befe-85e5-4ac5-a60f-ed0b0adb54b8" ovf:required="false" xsi:type="ovf:OperatingSystemSection_Type"><Info>Guest Operating System</Info><Description>OtherLinux</Description></Section><Section xsi:type="ovf:VirtualHardwareSection_Type"><Info>1 CPU, 1024 Memeory</Info><System><vssd:VirtualSystemType>ENGINE 3.2.0.0</vssd:VirtualSystemType></System><Item><rasd:Caption>1 virtual cpu</rasd:Caption><rasd:Description>Number of virtual CPU</rasd:Description><rasd:InstanceId>1</rasd:InstanceId><rasd:ResourceType>3</rasd:ResourceType><rasd:num_of_sockets>1</rasd:num_of_sockets><rasd:cpu_per_socket>1</rasd:cpu_per_socket></Item><Item><rasd:Caption>1024 MB of memory</rasd:Caption><rasd:Description>Memory Size</rasd:Description><rasd:InstanceId>2</rasd:InstanceId><rasd:ResourceType>4</rasd:ResourceType><rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits><rasd:VirtualQuantity>1024</rasd:VirtualQuantity></Item><Item><rasd:Caption>Centos_Disk1</rasd:Caption><rasd:InstanceId>9ee3829a-d45b-4927-937c-5f7092138fd5</rasd:InstanceId><rasd:ResourceType>17</rasd:ResourceType><rasd:HostResource>509eb58c-2541-47b3-bdeb-3665011ce69f/9ee3829a-d45b-4927-937c-5f7092138fd5</rasd:HostResource><rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent><rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template><rasd:ApplicationList></rasd:ApplicationList><rasd:StorageId>fc810722-3af0-4ca5-9a6e-1b4c40e76c1e</rasd:StorageId><rasd:StoragePoolId>fce396f2-72cb-11e2-acc2-000c29a7b590</rasd:StoragePoolId><rasd:CreationDate>2013/02/11 11:51:27</rasd:CreationDate><rasd:LastModified>2013/02/11 11:51:27</rasd:LastModified><rasd:last_modified_date>2013/02/11 11:51:34</rasd:last_modified_date></Item><Item><rasd:Caption>Ethernet adapter on ovirtmgmt</rasd:Caption><rasd:InstanceId>5171d908-f88e-4147-ba73-0923f3e6da16</rasd:InstanceId><rasd:ResourceType>10</rasd:ResourceType><rasd:ResourceSubType>3</rasd:ResourceSubType><rasd:Connection>ovirtmgmt</rasd:Connection><rasd:Name>nic1</rasd:Name><rasd:MACAddress>00:1a:4a:a8:47:ed</rasd:MACAddress><rasd:speed>1000</rasd:speed></Item><Item><rasd:Caption>USB Controller</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>23</rasd:ResourceType><rasd:UsbPolicy>DISABLED</rasd:UsbPolicy></Item></Section></Content></ovf:Envelope>\n', 'vm': '1230befe-85e5-4ac5-a60f-ed0b0adb54b8'}], sdUUID=None, options=None)
Thread-331::DEBUG::2013-02-11 19:51:34,249::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`8727ae0a-12c5-43f6-be30-16f1315108be`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-331::DEBUG::2013-02-11 19:51:34,250::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' for lock type 'shared'
Thread-331::DEBUG::2013-02-11 19:51:34,250::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free. Now locking as 'shared' (1 active user)
Thread-331::DEBUG::2013-02-11 19:51:34,250::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`8727ae0a-12c5-43f6-be30-16f1315108be`::Granted request
Thread-331::DEBUG::2013-02-11 19:51:34,251::task::794::TaskManager.Task::(resourceAcquired) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::_resourcesAcquired: Storage.fce396f2-72cb-11e2-acc2-000c29a7b590 (shared)
Thread-331::DEBUG::2013-02-11 19:51:34,251::task::957::TaskManager.Task::(_decref) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::ref 1 aborting False
Thread-331::INFO::2013-02-11 19:51:34,251::sp::1258::Storage.StoragePool::(updateVM) spUUID=fce396f2-72cb-11e2-acc2-000c29a7b590 sdUUID=fc810722-3af0-4ca5-9a6e-1b4c40e76c1e
Thread-331::INFO::2013-02-11 19:51:34,252::sp::1269::Storage.StoragePool::(updateVM) vmUUID=1230befe-85e5-4ac5-a60f-ed0b0adb54b8 imgList=['509eb58c-2541-47b3-bdeb-3665011ce69f']
Thread-331::INFO::2013-02-11 19:51:34,257::logUtils::39::dispatcher::(wrapper) Run and protect: updateVM, Return response: None
Thread-331::DEBUG::2013-02-11 19:51:34,257::task::1151::TaskManager.Task::(prepare) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::finished: None
Thread-331::DEBUG::2013-02-11 19:51:34,257::task::568::TaskManager.Task::(_updateState) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::moving from state preparing -> state finished
Thread-331::DEBUG::2013-02-11 19:51:34,258::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590': < ResourceRef 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', isValid: 'True' obj: 'None'>}
Thread-331::DEBUG::2013-02-11 19:51:34,258::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-331::DEBUG::2013-02-11 19:51:34,258::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590'
Thread-331::DEBUG::2013-02-11 19:51:34,258::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' (0 active users)
Thread-331::DEBUG::2013-02-11 19:51:34,259::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free, finding out if anyone is waiting for it.
Thread-331::DEBUG::2013-02-11 19:51:34,259::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', Clearing records.
Thread-331::DEBUG::2013-02-11 19:51:34,259::task::957::TaskManager.Task::(_decref) Task=`e3668693-41a6-42f5-9741-ba916af9c1fe`::ref 0 aborting False
Thread-332::DEBUG::2013-02-11 19:51:34,324::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-332::DEBUG::2013-02-11 19:51:34,324::task::568::TaskManager.Task::(_updateState) Task=`598aaa98-22fc-4e39-af3a-e8fa33543212`::moving from state init -> state preparing
Thread-332::INFO::2013-02-11 19:51:34,325::logUtils::37::dispatcher::(wrapper) Run and protect: clearTask(taskID='7f2adac1-8eff-4381-8420-5c450d60959a', spUUID=None, options=None)
Thread-332::DEBUG::2013-02-11 19:51:34,325::taskManager::161::TaskManager::(clearTask) Entry. taskID: 7f2adac1-8eff-4381-8420-5c450d60959a
Thread-332::DEBUG::2013-02-11 19:51:34,330::taskManager::166::TaskManager::(clearTask) Return.
Thread-332::INFO::2013-02-11 19:51:34,331::logUtils::39::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
Thread-332::DEBUG::2013-02-11 19:51:34,331::task::1151::TaskManager.Task::(prepare) Task=`598aaa98-22fc-4e39-af3a-e8fa33543212`::finished: None
Thread-332::DEBUG::2013-02-11 19:51:34,331::task::568::TaskManager.Task::(_updateState) Task=`598aaa98-22fc-4e39-af3a-e8fa33543212`::moving from state preparing -> state finished
Thread-332::DEBUG::2013-02-11 19:51:34,331::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-332::DEBUG::2013-02-11 19:51:34,332::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-332::DEBUG::2013-02-11 19:51:34,332::task::957::TaskManager.Task::(_decref) Task=`598aaa98-22fc-4e39-af3a-e8fa33543212`::ref 0 aborting False
Thread-335::DEBUG::2013-02-11 19:51:38,041::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-335::DEBUG::2013-02-11 19:51:38,042::task::568::TaskManager.Task::(_updateState) Task=`804bb953-5a86-477e-90cf-9c6b4e60c926`::moving from state init -> state preparing
Thread-335::INFO::2013-02-11 19:51:38,042::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', options=None)
Thread-335::INFO::2013-02-11 19:51:38,043::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 6}}
Thread-335::DEBUG::2013-02-11 19:51:38,043::task::1151::TaskManager.Task::(prepare) Task=`804bb953-5a86-477e-90cf-9c6b4e60c926`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 6}}
Thread-335::DEBUG::2013-02-11 19:51:38,043::task::568::TaskManager.Task::(_updateState) Task=`804bb953-5a86-477e-90cf-9c6b4e60c926`::moving from state preparing -> state finished
Thread-335::DEBUG::2013-02-11 19:51:38,043::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-335::DEBUG::2013-02-11 19:51:38,044::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-335::DEBUG::2013-02-11 19:51:38,044::task::957::TaskManager.Task::(_decref) Task=`804bb953-5a86-477e-90cf-9c6b4e60c926`::ref 0 aborting False
Thread-336::DEBUG::2013-02-11 19:51:38,089::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-336::DEBUG::2013-02-11 19:51:38,089::task::568::TaskManager.Task::(_updateState) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::moving from state init -> state preparing
Thread-336::INFO::2013-02-11 19:51:38,090::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', options=None)
Thread-336::DEBUG::2013-02-11 19:51:38,090::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`2af84ed4-eba8-4297-b843-65e60f0b02eb`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-336::DEBUG::2013-02-11 19:51:38,090::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' for lock type 'shared'
Thread-336::DEBUG::2013-02-11 19:51:38,091::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free. Now locking as 'shared' (1 active user)
Thread-336::DEBUG::2013-02-11 19:51:38,091::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`2af84ed4-eba8-4297-b843-65e60f0b02eb`::Granted request
Thread-336::DEBUG::2013-02-11 19:51:38,091::task::794::TaskManager.Task::(resourceAcquired) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::_resourcesAcquired: Storage.fce396f2-72cb-11e2-acc2-000c29a7b590 (shared)
Thread-336::DEBUG::2013-02-11 19:51:38,092::task::957::TaskManager.Task::(_decref) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::ref 1 aborting False
Thread-336::INFO::2013-02-11 19:51:38,094::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'name': 'Default', 'version': '3', 'domains': '86a53043-bb7c-4098-a3b8-e5d70286bf5f:Active,fc810722-3af0-4ca5-9a6e-1b4c40e76c1e:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/fce396f2-72cb-11e2-acc2-000c29a7b590/86a53043-bb7c-4098-a3b8-e5d70286bf5f/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 6}, 'dominfo': {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}}}
Thread-336::DEBUG::2013-02-11 19:51:38,095::task::1151::TaskManager.Task::(prepare) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::finished: {'info': {'spm_id': 1, 'master_uuid': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'name': 'Default', 'version': '3', 'domains': '86a53043-bb7c-4098-a3b8-e5d70286bf5f:Active,fc810722-3af0-4ca5-9a6e-1b4c40e76c1e:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/fce396f2-72cb-11e2-acc2-000c29a7b590/86a53043-bb7c-4098-a3b8-e5d70286bf5f/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 6}, 'dominfo': {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}}}
Thread-336::DEBUG::2013-02-11 19:51:38,095::task::568::TaskManager.Task::(_updateState) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::moving from state preparing -> state finished
Thread-336::DEBUG::2013-02-11 19:51:38,095::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590': < ResourceRef 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', isValid: 'True' obj: 'None'>}
Thread-336::DEBUG::2013-02-11 19:51:38,095::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-336::DEBUG::2013-02-11 19:51:38,096::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590'
Thread-336::DEBUG::2013-02-11 19:51:38,096::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' (0 active users)
Thread-336::DEBUG::2013-02-11 19:51:38,096::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free, finding out if anyone is waiting for it.
Thread-336::DEBUG::2013-02-11 19:51:38,096::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', Clearing records.
Thread-336::DEBUG::2013-02-11 19:51:38,097::task::957::TaskManager.Task::(_decref) Task=`387e8889-1d3f-405b-9534-53e8298d17fc`::ref 0 aborting False
Thread-337::DEBUG::2013-02-11 19:51:38,461::task::568::TaskManager.Task::(_updateState) Task=`b5aef9eb-f481-4618-8e0a-86f319150004`::moving from state init -> state preparing
Thread-337::INFO::2013-02-11 19:51:38,461::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-337::INFO::2013-02-11 19:51:38,462::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'delay': '0.00217008590698', 'lastCheck': '9.7', 'code': 0, 'valid': True}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'delay': '0.00195503234863', 'lastCheck': '9.7', 'code': 0, 'valid': True}}
Thread-337::DEBUG::2013-02-11 19:51:38,462::task::1151::TaskManager.Task::(prepare) Task=`b5aef9eb-f481-4618-8e0a-86f319150004`::finished: {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'delay': '0.00217008590698', 'lastCheck': '9.7', 'code': 0, 'valid': True}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'delay': '0.00195503234863', 'lastCheck': '9.7', 'code': 0, 'valid': True}}
Thread-337::DEBUG::2013-02-11 19:51:38,462::task::568::TaskManager.Task::(_updateState) Task=`b5aef9eb-f481-4618-8e0a-86f319150004`::moving from state preparing -> state finished
Thread-337::DEBUG::2013-02-11 19:51:38,462::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-337::DEBUG::2013-02-11 19:51:38,463::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-337::DEBUG::2013-02-11 19:51:38,463::task::957::TaskManager.Task::(_decref) Task=`b5aef9eb-f481-4618-8e0a-86f319150004`::ref 0 aborting False
Thread-343::DEBUG::2013-02-11 19:51:48,128::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-343::DEBUG::2013-02-11 19:51:48,129::task::568::TaskManager.Task::(_updateState) Task=`a6751a4b-b37f-4fd7-8bc7-807c1f5cd072`::moving from state init -> state preparing
Thread-343::INFO::2013-02-11 19:51:48,130::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', options=None)
Thread-343::INFO::2013-02-11 19:51:48,130::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 6}}
Thread-343::DEBUG::2013-02-11 19:51:48,131::task::1151::TaskManager.Task::(prepare) Task=`a6751a4b-b37f-4fd7-8bc7-807c1f5cd072`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 6}}
Thread-343::DEBUG::2013-02-11 19:51:48,131::task::568::TaskManager.Task::(_updateState) Task=`a6751a4b-b37f-4fd7-8bc7-807c1f5cd072`::moving from state preparing -> state finished
Thread-343::DEBUG::2013-02-11 19:51:48,131::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-343::DEBUG::2013-02-11 19:51:48,132::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-343::DEBUG::2013-02-11 19:51:48,132::task::957::TaskManager.Task::(_decref) Task=`a6751a4b-b37f-4fd7-8bc7-807c1f5cd072`::ref 0 aborting False
Thread-344::DEBUG::2013-02-11 19:51:48,179::BindingXMLRPC::161::vds::(wrapper) [192.168.71.71]
Thread-344::DEBUG::2013-02-11 19:51:48,180::task::568::TaskManager.Task::(_updateState) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::moving from state init -> state preparing
Thread-344::INFO::2013-02-11 19:51:48,180::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='fce396f2-72cb-11e2-acc2-000c29a7b590', options=None)
Thread-344::DEBUG::2013-02-11 19:51:48,181::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`546919d9-1c61-4a45-ace1-d16f49eeaaf4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-344::DEBUG::2013-02-11 19:51:48,181::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' for lock type 'shared'
Thread-344::DEBUG::2013-02-11 19:51:48,181::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free. Now locking as 'shared' (1 active user)
Thread-344::DEBUG::2013-02-11 19:51:48,181::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.fce396f2-72cb-11e2-acc2-000c29a7b590`ReqID=`546919d9-1c61-4a45-ace1-d16f49eeaaf4`::Granted request
Thread-344::DEBUG::2013-02-11 19:51:48,182::task::794::TaskManager.Task::(resourceAcquired) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::_resourcesAcquired: Storage.fce396f2-72cb-11e2-acc2-000c29a7b590 (shared)
Thread-344::DEBUG::2013-02-11 19:51:48,182::task::957::TaskManager.Task::(_decref) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::ref 1 aborting False
Thread-344::INFO::2013-02-11 19:51:48,185::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'name': 'Default', 'version': '3', 'domains': '86a53043-bb7c-4098-a3b8-e5d70286bf5f:Active,fc810722-3af0-4ca5-9a6e-1b4c40e76c1e:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/fce396f2-72cb-11e2-acc2-000c29a7b590/86a53043-bb7c-4098-a3b8-e5d70286bf5f/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 6}, 'dominfo': {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}}}
Thread-344::DEBUG::2013-02-11 19:51:48,185::task::1151::TaskManager.Task::(prepare) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::finished: {'info': {'spm_id': 1, 'master_uuid': 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e', 'name': 'Default', 'version': '3', 'domains': '86a53043-bb7c-4098-a3b8-e5d70286bf5f:Active,fc810722-3af0-4ca5-9a6e-1b4c40e76c1e:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/fce396f2-72cb-11e2-acc2-000c29a7b590/86a53043-bb7c-4098-a3b8-e5d70286bf5f/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 6}, 'dominfo': {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'status': 'Active', 'diskfree': '13046382592', 'alerts': [], 'disktotal': '27091009536'}}}
Thread-344::DEBUG::2013-02-11 19:51:48,185::task::568::TaskManager.Task::(_updateState) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::moving from state preparing -> state finished
Thread-344::DEBUG::2013-02-11 19:51:48,185::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590': < ResourceRef 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', isValid: 'True' obj: 'None'>}
Thread-344::DEBUG::2013-02-11 19:51:48,185::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-344::DEBUG::2013-02-11 19:51:48,186::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590'
Thread-344::DEBUG::2013-02-11 19:51:48,186::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' (0 active users)
Thread-344::DEBUG::2013-02-11 19:51:48,186::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590' is free, finding out if anyone is waiting for it.
Thread-344::DEBUG::2013-02-11 19:51:48,186::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.fce396f2-72cb-11e2-acc2-000c29a7b590', Clearing records.
Thread-344::DEBUG::2013-02-11 19:51:48,187::task::957::TaskManager.Task::(_decref) Task=`c6577777-e6c2-4adf-83b5-f65e685e4263`::ref 0 aborting False
Thread-345::DEBUG::2013-02-11 19:51:48,729::task::568::TaskManager.Task::(_updateState) Task=`9eb30529-6d29-4329-b003-66cef22347e4`::moving from state init -> state preparing
Thread-345::INFO::2013-02-11 19:51:48,730::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-345::INFO::2013-02-11 19:51:48,731::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'delay': '0.0029718875885', 'lastCheck': '10.0', 'code': 0, 'valid': True}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'delay': '0.00237989425659', 'lastCheck': '10.0', 'code': 0, 'valid': True}}
Thread-345::DEBUG::2013-02-11 19:51:48,731::task::1151::TaskManager.Task::(prepare) Task=`9eb30529-6d29-4329-b003-66cef22347e4`::finished: {'86a53043-bb7c-4098-a3b8-e5d70286bf5f': {'delay': '0.0029718875885', 'lastCheck': '10.0', 'code': 0, 'valid': True}, 'fc810722-3af0-4ca5-9a6e-1b4c40e76c1e': {'delay': '0.00237989425659', 'lastCheck': '10.0', 'code': 0, 'valid': True}}
Thread-345::DEBUG::2013-02-11 19:51:48,731::task::568::TaskManager.Task::(_updateState) Task=`9eb30529-6d29-4329-b003-66cef22347e4`::moving from state preparing -> state finished
Thread-345::DEBUG::2013-02-11 19:51:48,732::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-345::DEBUG::2013-02-11 19:51:48,732::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-345::DEBUG::2013-02-11 19:51:48,732::task::957::TaskManager.Task::(_decref) Task=`9eb30529-6d29-4329-b003-66cef22347e4`::ref 0 aborting False