Attachment 598502 Details for Bug 840538 – Relevant vdsm log from node

Relevant vdsm log from node

vdsm.log (text/x-log), 137.17 KB, created by Miłosz Kosobucki on 2012-07-16 17:15:30 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Miłosz Kosobucki

Created: 2012-07-16 17:15:30 UTC

Size: 137.17 KB

patch

obsolete

>Thread-11042::DEBUG::2012-07-16 16:48:40,255::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11042::DEBUG::2012-07-16 16:48:40,255::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11042::DEBUG::2012-07-16 16:48:40,255::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11042::DEBUG::2012-07-16 16:48:40,256::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11042::DEBUG::2012-07-16 16:48:40,256::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11042::DEBUG::2012-07-16 16:48:40,256::task::978::TaskManager.Task::(_decref) Task=`c8303c7b-6c8b-4e64-9336-133d17431611`::ref 0 aborting False
>Thread-11043::DEBUG::2012-07-16 16:48:41,466::task::588::TaskManager.Task::(_updateState) Task=`e3bffc6b-ed82-4458-8bdd-a43b664a65f9`::moving from state init -> state preparing
>Thread-11043::INFO::2012-07-16 16:48:41,466::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11043::INFO::2012-07-16 16:48:41,467::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00167894363403', 'lastCheck': 1342457311.547375, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00129699707031', 'lastCheck': 1342457316.643736, 'code': 0, 'valid': True}}
>Thread-11043::DEBUG::2012-07-16 16:48:41,467::task::1172::TaskManager.Task::(prepare) Task=`e3bffc6b-ed82-4458-8bdd-a43b664a65f9`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00167894363403', 'lastCheck': 1342457311.547375, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00129699707031', 'lastCheck': 1342457316.643736, 'code': 0, 'valid': True}}
>Thread-11043::DEBUG::2012-07-16 16:48:41,467::task::588::TaskManager.Task::(_updateState) Task=`e3bffc6b-ed82-4458-8bdd-a43b664a65f9`::moving from state preparing -> state finished
>Thread-11043::DEBUG::2012-07-16 16:48:41,467::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11043::DEBUG::2012-07-16 16:48:41,467::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11043::DEBUG::2012-07-16 16:48:41,468::task::978::TaskManager.Task::(_decref) Task=`e3bffc6b-ed82-4458-8bdd-a43b664a65f9`::ref 0 aborting False
>Thread-11046::DEBUG::2012-07-16 16:48:44,972::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmCreate with ({'custom': {'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149ba': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=b5a7562b-2642-45b8-b6cf-405b1f8149ba,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149badevice_5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149badevice_5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1device_5d6baf6c-7858-47e5-b2ff-f821256d53c2': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=5d6baf6c-7858-47e5-b2ff-f821256d53c2,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=28635929-7c3d-43ad-949e-b4627b1725b8,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'tabletEnable': 'true', 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '717bb03c-55c5-4f9b-baca-3a489bd6db36', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'ubuntu-12.04-server-amd64.iso'}, 'readonly': 'true', 'deviceId': 'c1d3655c-10a4-4593-aed3-316ef7412748', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111/ubuntu-12.04-server-amd64.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'poolID': '3966bab3-5801-4345-a808-a802ba96e380', 'volumeID': 'ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651', 'specParams': {}, 'readonly': 'false', 'domainID': 'a407d973-2213-49da-bf84-1b08afb41236', 'optional': 'false', 'deviceId': 'cb7a38f2-de94-4973-9ca8-9fffade64651', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:fe:4e:01', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '29749e5a-9883-4478-9c00-1745e3d11989', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '28635929-7c3d-43ad-949e-b4627b1725b8', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'dc7dc145-fca7-42bc-b33c-ddd73737b624'}], 'smp': '1', 'vmType': 'kvm', 'timeOffset': '-2', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'SandyBridge', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'ubuntu1', 'display': 'vnc', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [5580be96]
>Thread-11046::INFO::2012-07-16 16:48:44,972::API::592::vds::(_getNetworkIp) network None: using 0
>Thread-11046::INFO::2012-07-16 16:48:44,973::clientIF::311::vds::(createVm) vmContainerLock acquired by vm 2c9311b8-0939-4f68-b801-bd20bfada988
>Thread-11047::DEBUG::2012-07-16 16:48:44,974::vm::564::vm.Vm::(_startUnderlyingVm) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Start
>Thread-11046::DEBUG::2012-07-16 16:48:44,974::clientIF::325::vds::(createVm) Total desktops after creation of 2c9311b8-0939-4f68-b801-bd20bfada988 is 1
>Thread-11047::DEBUG::2012-07-16 16:48:44,975::vm::568::vm.Vm::(_startUnderlyingVm) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::_ongoingCreations acquired
>Thread-11046::DEBUG::2012-07-16 16:48:44,975::BindingXMLRPC::879::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'tabletEnable': 'true', 'pid': '0', 'timeOffset': '-2', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'SandyBridge', 'custom': {'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149ba': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=b5a7562b-2642-45b8-b6cf-405b1f8149ba,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149badevice_5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8device_b5a7562b-2642-45b8-b6cf-405b1f8149badevice_5a23704f-b9e2-4a97-90ec-f09bbbf4ffa1device_5d6baf6c-7858-47e5-b2ff-f821256d53c2': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=5d6baf6c-7858-47e5-b2ff-f821256d53c2,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_28635929-7c3d-43ad-949e-b4627b1725b8': 'VmId=2c9311b8-0939-4f68-b801-bd20bfada988,DeviceId=28635929-7c3d-43ad-949e-b4627b1725b8,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '717bb03c-55c5-4f9b-baca-3a489bd6db36', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': 'ubuntu-12.04-server-amd64.iso'}, 'readonly': 'true', 'deviceId': 'c1d3655c-10a4-4593-aed3-316ef7412748', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111/ubuntu-12.04-server-amd64.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'poolID': '3966bab3-5801-4345-a808-a802ba96e380', 'volumeID': 'ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651', 'specParams': {}, 'readonly': 'false', 'domainID': 'a407d973-2213-49da-bf84-1b08afb41236', 'optional': 'false', 'deviceId': 'cb7a38f2-de94-4973-9ca8-9fffade64651', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:fe:4e:01', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': '29749e5a-9883-4478-9c00-1745e3d11989', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '28635929-7c3d-43ad-949e-b4627b1725b8', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'dc7dc145-fca7-42bc-b33c-ddd73737b624'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 512, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1', 'vmName': 'ubuntu1', 'display': 'vnc', 'nice': '0'}}
>Thread-11047::INFO::2012-07-16 16:48:44,975::libvirtvm::1290::vm.Vm::(_run) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::VM wrapper has started
>Thread-11047::DEBUG::2012-07-16 16:48:44,978::task::588::TaskManager.Task::(_updateState) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::moving from state init -> state preparing
>Thread-11047::INFO::2012-07-16 16:48:44,978::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a407d973-2213-49da-bf84-1b08afb41236', spUUID='3966bab3-5801-4345-a808-a802ba96e380', imgUUID='cb7a38f2-de94-4973-9ca8-9fffade64651', volUUID='ccf28d2e-5a71-463c-b9eb-79c5602d630c', options=None)
>Thread-11047::DEBUG::2012-07-16 16:48:44,979::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`01b96092-d106-4418-8000-5724f1e99bdc`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11047::DEBUG::2012-07-16 16:48:44,979::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' for lock type 'shared'
>Thread-11047::DEBUG::2012-07-16 16:48:44,979::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free. Now locking as 'shared' (1 active user)
>Thread-11047::DEBUG::2012-07-16 16:48:44,979::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`01b96092-d106-4418-8000-5724f1e99bdc`::Granted request
>Thread-11047::DEBUG::2012-07-16 16:48:44,980::task::817::TaskManager.Task::(resourceAcquired) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::_resourcesAcquired: Storage.a407d973-2213-49da-bf84-1b08afb41236 (shared)
>Thread-11047::DEBUG::2012-07-16 16:48:44,980::task::978::TaskManager.Task::(_decref) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::ref 1 aborting False
>Thread-11047::DEBUG::2012-07-16 16:48:44,981::fileVolume::579::Storage.Volume::(validateVolumePath) validate path for ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11047::DEBUG::2012-07-16 16:48:44,984::fileVolume::579::Storage.Volume::(validateVolumePath) validate path for ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11047::INFO::2012-07-16 16:48:44,986::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1147043840', 'apparentsize': '10737418240'}
>Thread-11047::DEBUG::2012-07-16 16:48:44,986::task::1172::TaskManager.Task::(prepare) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::finished: {'truesize': '1147043840', 'apparentsize': '10737418240'}
>Thread-11047::DEBUG::2012-07-16 16:48:44,986::task::588::TaskManager.Task::(_updateState) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::moving from state preparing -> state finished
>Thread-11047::DEBUG::2012-07-16 16:48:44,986::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a407d973-2213-49da-bf84-1b08afb41236': < ResourceRef 'Storage.a407d973-2213-49da-bf84-1b08afb41236', isValid: 'True' obj: 'None'>}
>Thread-11047::DEBUG::2012-07-16 16:48:44,987::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11047::DEBUG::2012-07-16 16:48:44,987::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236'
>Thread-11047::DEBUG::2012-07-16 16:48:44,987::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' (0 active users)
>Thread-11047::DEBUG::2012-07-16 16:48:44,987::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free, finding out if anyone is waiting for it.
>Thread-11047::DEBUG::2012-07-16 16:48:44,987::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236', Clearing records.
>Thread-11047::DEBUG::2012-07-16 16:48:44,988::task::978::TaskManager.Task::(_decref) Task=`11232d73-1c2d-406a-87e8-a481805d6a42`::ref 0 aborting False
>Thread-11047::INFO::2012-07-16 16:48:44,988::clientIF::293::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111/ubuntu-12.04-server-amd64.iso
>Thread-11047::DEBUG::2012-07-16 16:48:44,988::task::588::TaskManager.Task::(_updateState) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::moving from state init -> state preparing
>Thread-11047::INFO::2012-07-16 16:48:44,989::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='a407d973-2213-49da-bf84-1b08afb41236', spUUID='3966bab3-5801-4345-a808-a802ba96e380', imgUUID='cb7a38f2-de94-4973-9ca8-9fffade64651', volUUID='ccf28d2e-5a71-463c-b9eb-79c5602d630c')
>Thread-11047::DEBUG::2012-07-16 16:48:44,989::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`b80a71b1-cac7-4bf9-8f04-3bb3fab311a9`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11047::DEBUG::2012-07-16 16:48:44,989::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' for lock type 'shared'
>Thread-11047::DEBUG::2012-07-16 16:48:44,989::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free. Now locking as 'shared' (1 active user)
>Thread-11047::DEBUG::2012-07-16 16:48:44,989::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`b80a71b1-cac7-4bf9-8f04-3bb3fab311a9`::Granted request
>Thread-11047::DEBUG::2012-07-16 16:48:44,990::task::817::TaskManager.Task::(resourceAcquired) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::_resourcesAcquired: Storage.a407d973-2213-49da-bf84-1b08afb41236 (shared)
>Thread-11047::DEBUG::2012-07-16 16:48:44,990::task::978::TaskManager.Task::(_decref) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::ref 1 aborting False
>Thread-11047::DEBUG::2012-07-16 16:48:44,991::fileVolume::579::Storage.Volume::(validateVolumePath) validate path for ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11047::INFO::2012-07-16 16:48:45,011::image::357::Storage.Image::(getChain) sdUUID=a407d973-2213-49da-bf84-1b08afb41236 imgUUID=cb7a38f2-de94-4973-9ca8-9fffade64651 chain=[<storage.fileVolume.FileVolume instance at 0x7f238c1f4d88>] 
>Thread-11047::INFO::2012-07-16 16:48:45,013::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'chain': [{'shared': False, 'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'domainID': 'a407d973-2213-49da-bf84-1b08afb41236', 'volumeID': 'ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}]}
>Thread-11047::DEBUG::2012-07-16 16:48:45,013::task::1172::TaskManager.Task::(prepare) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::finished: {'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'chain': [{'shared': False, 'path': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'domainID': 'a407d973-2213-49da-bf84-1b08afb41236', 'volumeID': 'ccf28d2e-5a71-463c-b9eb-79c5602d630c', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}]}
>Thread-11047::DEBUG::2012-07-16 16:48:45,013::task::588::TaskManager.Task::(_updateState) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::moving from state preparing -> state finished
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a407d973-2213-49da-bf84-1b08afb41236': < ResourceRef 'Storage.a407d973-2213-49da-bf84-1b08afb41236', isValid: 'True' obj: 'None'>}
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236'
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' (0 active users)
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free, finding out if anyone is waiting for it.
>Thread-11047::DEBUG::2012-07-16 16:48:45,014::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236', Clearing records.
>Thread-11047::DEBUG::2012-07-16 16:48:45,015::task::978::TaskManager.Task::(_decref) Task=`5d51d089-da27-4a6a-9ba9-ba39daaa1963`::ref 0 aborting False
>Thread-11047::INFO::2012-07-16 16:48:45,015::clientIF::293::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11047::DEBUG::2012-07-16 16:48:45,023::libvirtvm::1343::vm.Vm::(_run) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>ubuntu1</name>
>	<uuid>2c9311b8-0939-4f68-b801-bd20bfada988</uuid>
>	<memory>524288</memory>
>	<currentMemory>524288</currentMemory>
>	<vcpu>1</vcpu>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/ubuntu1.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<input bus="usb" type="tablet"/>
>		<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" type="vnc"/>
>		<console type="pty">
>			<target port="0" type="virtio"/>
>		</console>
>		<controller type="usb">
>			<address  domain="0x0000"  function="0x2"  slot="0x01"  type="pci" bus="0x00"/>
>		</controller>
>		<video>
>			<address  domain="0x0000"  function="0x0"  slot="0x02"  type="pci" bus="0x00"/>
>			<model heads="1" type="qxl" vram="65536"/>
>		</video>
>		<interface type="bridge">
>			<address  domain="0x0000"  function="0x0"  slot="0x03"  type="pci" bus="0x00"/>
>			<mac address="00:1a:4a:fe:4e:01"/>
>			<model type="virtio"/>
>			<source bridge="ovirtmgmt"/>
>		</interface>
>		<memballoon model="virtio"/>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address  bus="1"  controller="0"  target="0"  type="drive" unit="0"/>
>			<source file="/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111/ubuntu-12.04-server-amd64.iso" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial></serial>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<address  domain="0x0000"  function="0x0"  slot="0x05"  type="pci" bus="0x00"/>
>			<source file="/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/a407d973-2213-49da-bf84-1b08afb41236/images/cb7a38f2-de94-4973-9ca8-9fffade64651/ccf28d2e-5a71-463c-b9eb-79c5602d630c"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>cb7a38f2-de94-4973-9ca8-9fffade64651</serial>
>			<boot order="1"/>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="pc-0.14">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">Red Hat</entry>
>			<entry name="product">RHEV Hypervisor</entry>
>			<entry name="version">17-1</entry>
>			<entry name="serial">C4447E23-F09F-E011-B533-00101859A779_00:1e:67:1a:44:13</entry>
>			<entry name="uuid">2c9311b8-0939-4f68-b801-bd20bfada988</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="-2" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>SandyBridge</model>
>		<topology cores="1" sockets="1" threads="1"/>
>	</cpu>
></domain>
>
>libvirtEventLoop::DEBUG::2012-07-16 16:48:45,629::libvirtvm::2414::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::event Started detail 0 opaque None
>Thread-11047::DEBUG::2012-07-16 16:48:45,678::utils::329::vm.Vm::(start) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Start statistics collection
>Thread-11050::DEBUG::2012-07-16 16:48:45,678::utils::358::vm.Vm::(run) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Stats thread started
>Thread-11050::DEBUG::2012-07-16 16:48:45,679::task::588::TaskManager.Task::(_updateState) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::moving from state init -> state preparing
>Thread-11050::INFO::2012-07-16 16:48:45,679::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a407d973-2213-49da-bf84-1b08afb41236', spUUID='3966bab3-5801-4345-a808-a802ba96e380', imgUUID='cb7a38f2-de94-4973-9ca8-9fffade64651', volUUID='ccf28d2e-5a71-463c-b9eb-79c5602d630c', options=None)
>Thread-11050::DEBUG::2012-07-16 16:48:45,680::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`6115a3a6-e15c-4d08-b267-f1f583079be6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11050::DEBUG::2012-07-16 16:48:45,680::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' for lock type 'shared'
>Thread-11050::DEBUG::2012-07-16 16:48:45,680::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free. Now locking as 'shared' (1 active user)
>Thread-11047::DEBUG::2012-07-16 16:48:45,680::vmChannels::144::vds::(register) Add fileno 51 to listener's channels.
>Thread-11050::DEBUG::2012-07-16 16:48:45,680::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.a407d973-2213-49da-bf84-1b08afb41236`ReqID=`6115a3a6-e15c-4d08-b267-f1f583079be6`::Granted request
>Thread-11050::DEBUG::2012-07-16 16:48:45,680::task::817::TaskManager.Task::(resourceAcquired) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::_resourcesAcquired: Storage.a407d973-2213-49da-bf84-1b08afb41236 (shared)
>Thread-11050::DEBUG::2012-07-16 16:48:45,681::task::978::TaskManager.Task::(_decref) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::ref 1 aborting False
>Thread-11050::DEBUG::2012-07-16 16:48:45,681::fileVolume::579::Storage.Volume::(validateVolumePath) validate path for ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11047::WARNING::2012-07-16 16:48:45,682::libvirtvm::1552::vm.Vm::(_readPauseCode) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::_readPauseCode unsupported by libvirt vm
>Thread-11050::DEBUG::2012-07-16 16:48:45,684::fileVolume::579::Storage.Volume::(validateVolumePath) validate path for ccf28d2e-5a71-463c-b9eb-79c5602d630c
>Thread-11050::INFO::2012-07-16 16:48:45,685::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1147043840', 'apparentsize': '10737418240'}
>Thread-11050::DEBUG::2012-07-16 16:48:45,685::task::1172::TaskManager.Task::(prepare) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::finished: {'truesize': '1147043840', 'apparentsize': '10737418240'}
>Thread-11050::DEBUG::2012-07-16 16:48:45,685::task::588::TaskManager.Task::(_updateState) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::moving from state preparing -> state finished
>Thread-11050::DEBUG::2012-07-16 16:48:45,685::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a407d973-2213-49da-bf84-1b08afb41236': < ResourceRef 'Storage.a407d973-2213-49da-bf84-1b08afb41236', isValid: 'True' obj: 'None'>}
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236'
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' (0 active users)
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236' is free, finding out if anyone is waiting for it.
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a407d973-2213-49da-bf84-1b08afb41236', Clearing records.
>Thread-11050::DEBUG::2012-07-16 16:48:45,686::task::978::TaskManager.Task::(_decref) Task=`fb887ec8-a372-4d6c-b81d-a8395e33f088`::ref 0 aborting False
>Thread-11047::DEBUG::2012-07-16 16:48:45,687::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /usr/sbin/service ksmtuned retune' (cwd None)
>Thread-11047::DEBUG::2012-07-16 16:48:45,708::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'Unknown operation retune\n'; <rc> = 1
>Thread-11047::DEBUG::2012-07-16 16:48:45,708::vm::580::vm.Vm::(_startUnderlyingVm) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::_ongoingCreations released
>VM Channels Listener::DEBUG::2012-07-16 16:48:46,527::vmChannels::71::vds::(_do_add_channels) fileno 51 was added to unconnected channels.
>VM Channels Listener::DEBUG::2012-07-16 16:48:46,527::vmChannels::103::vds::(_handle_unconnected) Trying to connect fileno 51.
>VM Channels Listener::DEBUG::2012-07-16 16:48:46,527::guestIF::86::vm.Vm::(_connect) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Attempting connection to /var/lib/libvirt/qemu/channels/ubuntu1.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2012-07-16 16:48:46,528::guestIF::88::vm.Vm::(_connect) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Connected to /var/lib/libvirt/qemu/channels/ubuntu1.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2012-07-16 16:48:46,528::vmChannels::106::vds::(_handle_unconnected) Connect fileno 51 was succeed.
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::220::vm.Vm::(_getNetworkStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Network stats not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11052::DEBUG::2012-07-16 16:48:47,572::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:fe:4e:01', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '1.89', 'cpuIdle': '100.00', 'elapsedTime': '2', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11055::DEBUG::2012-07-16 16:48:49,730::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11055::DEBUG::2012-07-16 16:48:49,730::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,731::libvirtvm::220::vm.Vm::(_getNetworkStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Network stats not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,731::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,731::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,731::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,731::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11055::DEBUG::2012-07-16 16:48:49,732::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:fe:4e:01', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.03', 'cpuIdle': '100.00', 'elapsedTime': '4', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11056::DEBUG::2012-07-16 16:48:50,282::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11056::DEBUG::2012-07-16 16:48:50,283::task::588::TaskManager.Task::(_updateState) Task=`1fc5a555-b3c0-4eca-b557-51fda82fa6c0`::moving from state init -> state preparing
>Thread-11056::INFO::2012-07-16 16:48:50,283::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11056::INFO::2012-07-16 16:48:50,284::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11056::DEBUG::2012-07-16 16:48:50,284::task::1172::TaskManager.Task::(prepare) Task=`1fc5a555-b3c0-4eca-b557-51fda82fa6c0`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11056::DEBUG::2012-07-16 16:48:50,284::task::588::TaskManager.Task::(_updateState) Task=`1fc5a555-b3c0-4eca-b557-51fda82fa6c0`::moving from state preparing -> state finished
>Thread-11056::DEBUG::2012-07-16 16:48:50,284::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11056::DEBUG::2012-07-16 16:48:50,284::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11056::DEBUG::2012-07-16 16:48:50,285::task::978::TaskManager.Task::(_decref) Task=`1fc5a555-b3c0-4eca-b557-51fda82fa6c0`::ref 0 aborting False
>Thread-11057::DEBUG::2012-07-16 16:48:50,302::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11057::DEBUG::2012-07-16 16:48:50,302::task::588::TaskManager.Task::(_updateState) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::moving from state init -> state preparing
>Thread-11057::INFO::2012-07-16 16:48:50,303::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11057::DEBUG::2012-07-16 16:48:50,303::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`220f1666-77bf-4b86-8c48-5e14eee65ee6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11057::DEBUG::2012-07-16 16:48:50,303::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11057::DEBUG::2012-07-16 16:48:50,303::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11057::DEBUG::2012-07-16 16:48:50,304::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`220f1666-77bf-4b86-8c48-5e14eee65ee6`::Granted request
>Thread-11057::DEBUG::2012-07-16 16:48:50,304::task::817::TaskManager.Task::(resourceAcquired) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11057::DEBUG::2012-07-16 16:48:50,304::task::978::TaskManager.Task::(_decref) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::ref 1 aborting False
>Thread-11057::INFO::2012-07-16 16:48:50,305::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210689024', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11057::DEBUG::2012-07-16 16:48:50,305::task::1172::TaskManager.Task::(prepare) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210689024', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11057::DEBUG::2012-07-16 16:48:50,305::task::588::TaskManager.Task::(_updateState) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::moving from state preparing -> state finished
>Thread-11057::DEBUG::2012-07-16 16:48:50,306::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11057::DEBUG::2012-07-16 16:48:50,306::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11057::DEBUG::2012-07-16 16:48:50,306::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11057::DEBUG::2012-07-16 16:48:50,306::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11057::DEBUG::2012-07-16 16:48:50,306::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11057::DEBUG::2012-07-16 16:48:50,307::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11057::DEBUG::2012-07-16 16:48:50,307::task::978::TaskManager.Task::(_decref) Task=`48af3127-ae18-41ec-8ad1-f645a958cb20`::ref 0 aborting False
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::task::588::TaskManager.Task::(_updateState) Task=`bb4d1fd4-cd0c-4b45-940d-59b97fbb5886`::moving from state init -> state preparing
>Thread-11058::INFO::2012-07-16 16:48:51,760::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11058::INFO::2012-07-16 16:48:51,760::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00166296958923', 'lastCheck': 1342457331.742215, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.000738143920898', 'lastCheck': 1342457326.646378, 'code': 0, 'valid': True}}
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::task::1172::TaskManager.Task::(prepare) Task=`bb4d1fd4-cd0c-4b45-940d-59b97fbb5886`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00166296958923', 'lastCheck': 1342457331.742215, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.000738143920898', 'lastCheck': 1342457326.646378, 'code': 0, 'valid': True}}
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::task::588::TaskManager.Task::(_updateState) Task=`bb4d1fd4-cd0c-4b45-940d-59b97fbb5886`::moving from state preparing -> state finished
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11058::DEBUG::2012-07-16 16:48:51,760::task::978::TaskManager.Task::(_decref) Task=`bb4d1fd4-cd0c-4b45-940d-59b97fbb5886`::ref 0 aborting False
>Thread-11059::DEBUG::2012-07-16 16:48:51,779::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11059::DEBUG::2012-07-16 16:48:51,780::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11059::DEBUG::2012-07-16 16:48:51,780::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11059::DEBUG::2012-07-16 16:48:51,780::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11059::DEBUG::2012-07-16 16:48:51,780::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,831::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11061::DEBUG::2012-07-16 16:48:53,831::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,831::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,832::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,832::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,832::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11061::DEBUG::2012-07-16 16:48:53,832::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.13', 'cpuIdle': '100.00', 'elapsedTime': '8', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11062::DEBUG::2012-07-16 16:48:55,462::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmSetTicket with ('2c9311b8-0939-4f68-b801-bd20bfada988', 'RZ0Y5RNPooE2', '120', 'disconnect', {'userName': 'admin@internal', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [4f9fc094]
>Thread-11062::DEBUG::2012-07-16 16:48:55,477::BindingXMLRPC::879::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-11064::DEBUG::2012-07-16 16:48:55,875::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11064::DEBUG::2012-07-16 16:48:55,875::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11064::DEBUG::2012-07-16 16:48:55,876::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11064::DEBUG::2012-07-16 16:48:55,876::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11064::DEBUG::2012-07-16 16:48:55,876::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11064::DEBUG::2012-07-16 16:48:55,876::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11064::DEBUG::2012-07-16 16:48:55,877::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.17', 'cpuIdle': '100.00', 'elapsedTime': '10', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11066::DEBUG::2012-07-16 16:48:57,919::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11066::DEBUG::2012-07-16 16:48:57,919::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11066::DEBUG::2012-07-16 16:48:57,920::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11066::DEBUG::2012-07-16 16:48:57,920::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11066::DEBUG::2012-07-16 16:48:57,920::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11066::DEBUG::2012-07-16 16:48:57,920::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11066::DEBUG::2012-07-16 16:48:57,921::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.22', 'cpuIdle': '100.00', 'elapsedTime': '12', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11068::DEBUG::2012-07-16 16:48:59,962::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11068::DEBUG::2012-07-16 16:48:59,962::libvirtvm::189::vm.Vm::(_getCpuStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::CPU stats not available
>Thread-11068::DEBUG::2012-07-16 16:48:59,963::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11068::DEBUG::2012-07-16 16:48:59,963::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11068::DEBUG::2012-07-16 16:48:59,963::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11068::DEBUG::2012-07-16 16:48:59,963::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11068::DEBUG::2012-07-16 16:48:59,964::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.26', 'cpuIdle': '100.00', 'elapsedTime': '14', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11069::DEBUG::2012-07-16 16:49:00,335::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11069::DEBUG::2012-07-16 16:49:00,335::task::588::TaskManager.Task::(_updateState) Task=`f064aae8-e425-43cb-9a0e-51f3041f73c3`::moving from state init -> state preparing
>Thread-11069::INFO::2012-07-16 16:49:00,336::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11069::INFO::2012-07-16 16:49:00,336::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11069::DEBUG::2012-07-16 16:49:00,336::task::1172::TaskManager.Task::(prepare) Task=`f064aae8-e425-43cb-9a0e-51f3041f73c3`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11069::DEBUG::2012-07-16 16:49:00,336::task::588::TaskManager.Task::(_updateState) Task=`f064aae8-e425-43cb-9a0e-51f3041f73c3`::moving from state preparing -> state finished
>Thread-11069::DEBUG::2012-07-16 16:49:00,336::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11069::DEBUG::2012-07-16 16:49:00,336::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11069::DEBUG::2012-07-16 16:49:00,337::task::978::TaskManager.Task::(_decref) Task=`f064aae8-e425-43cb-9a0e-51f3041f73c3`::ref 0 aborting False
>Thread-11070::DEBUG::2012-07-16 16:49:00,354::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11070::DEBUG::2012-07-16 16:49:00,354::task::588::TaskManager.Task::(_updateState) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::moving from state init -> state preparing
>Thread-11070::INFO::2012-07-16 16:49:00,354::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11070::DEBUG::2012-07-16 16:49:00,355::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`a179b4ed-a827-4957-bd10-2491dd8041ca`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11070::DEBUG::2012-07-16 16:49:00,355::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11070::DEBUG::2012-07-16 16:49:00,355::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11070::DEBUG::2012-07-16 16:49:00,356::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`a179b4ed-a827-4957-bd10-2491dd8041ca`::Granted request
>Thread-11070::DEBUG::2012-07-16 16:49:00,356::task::817::TaskManager.Task::(resourceAcquired) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11070::DEBUG::2012-07-16 16:49:00,356::task::978::TaskManager.Task::(_decref) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::ref 1 aborting False
>Thread-11070::INFO::2012-07-16 16:49:00,357::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210689024', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11070::DEBUG::2012-07-16 16:49:00,357::task::1172::TaskManager.Task::(prepare) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210689024', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11070::DEBUG::2012-07-16 16:49:00,357::task::588::TaskManager.Task::(_updateState) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::moving from state preparing -> state finished
>Thread-11070::DEBUG::2012-07-16 16:49:00,357::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11070::DEBUG::2012-07-16 16:49:00,358::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11070::DEBUG::2012-07-16 16:49:00,358::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11070::DEBUG::2012-07-16 16:49:00,358::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11070::DEBUG::2012-07-16 16:49:00,358::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11070::DEBUG::2012-07-16 16:49:00,358::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11070::DEBUG::2012-07-16 16:49:00,359::task::978::TaskManager.Task::(_decref) Task=`8214d834-8ad7-4415-9da5-6900e994dc22`::ref 0 aborting False
>Thread-11071::DEBUG::2012-07-16 16:49:01,990::task::588::TaskManager.Task::(_updateState) Task=`64994f7f-4d52-4746-bb94-876bd14ec6a5`::moving from state init -> state preparing
>Thread-11071::INFO::2012-07-16 16:49:01,990::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11071::INFO::2012-07-16 16:49:01,991::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00167107582092', 'lastCheck': 1342457341.845654, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00138401985168', 'lastCheck': 1342457336.651192, 'code': 0, 'valid': True}}
>Thread-11071::DEBUG::2012-07-16 16:49:01,991::task::1172::TaskManager.Task::(prepare) Task=`64994f7f-4d52-4746-bb94-876bd14ec6a5`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00167107582092', 'lastCheck': 1342457341.845654, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00138401985168', 'lastCheck': 1342457336.651192, 'code': 0, 'valid': True}}
>Thread-11071::DEBUG::2012-07-16 16:49:01,991::task::588::TaskManager.Task::(_updateState) Task=`64994f7f-4d52-4746-bb94-876bd14ec6a5`::moving from state preparing -> state finished
>Thread-11071::DEBUG::2012-07-16 16:49:01,991::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11071::DEBUG::2012-07-16 16:49:01,991::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11071::DEBUG::2012-07-16 16:49:01,992::task::978::TaskManager.Task::(_decref) Task=`64994f7f-4d52-4746-bb94-876bd14ec6a5`::ref 0 aborting False
>Thread-11072::DEBUG::2012-07-16 16:49:02,012::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11072::DEBUG::2012-07-16 16:49:02,012::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11072::DEBUG::2012-07-16 16:49:02,013::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11072::DEBUG::2012-07-16 16:49:02,013::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11074::DEBUG::2012-07-16 16:49:04,070::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11074::DEBUG::2012-07-16 16:49:04,071::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11074::DEBUG::2012-07-16 16:49:04,071::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11074::DEBUG::2012-07-16 16:49:04,071::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11074::DEBUG::2012-07-16 16:49:04,071::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11074::DEBUG::2012-07-16 16:49:04,072::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '33.30', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.36', 'cpuIdle': '66.70', 'elapsedTime': '19', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11076::DEBUG::2012-07-16 16:49:06,114::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11076::DEBUG::2012-07-16 16:49:06,115::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11076::DEBUG::2012-07-16 16:49:06,115::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11076::DEBUG::2012-07-16 16:49:06,115::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11076::DEBUG::2012-07-16 16:49:06,115::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11076::DEBUG::2012-07-16 16:49:06,115::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '33.30', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.41', 'cpuIdle': '66.70', 'elapsedTime': '21', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11078::DEBUG::2012-07-16 16:49:08,157::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11078::DEBUG::2012-07-16 16:49:08,157::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11078::DEBUG::2012-07-16 16:49:08,157::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11078::DEBUG::2012-07-16 16:49:08,158::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11078::DEBUG::2012-07-16 16:49:08,158::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11078::DEBUG::2012-07-16 16:49:08,158::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '33.30', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.45', 'cpuIdle': '66.70', 'elapsedTime': '23', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11080::DEBUG::2012-07-16 16:49:10,200::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11080::DEBUG::2012-07-16 16:49:10,201::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11080::DEBUG::2012-07-16 16:49:10,201::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11080::DEBUG::2012-07-16 16:49:10,201::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11080::DEBUG::2012-07-16 16:49:10,201::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11080::DEBUG::2012-07-16 16:49:10,202::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '33.30', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.49', 'cpuIdle': '66.70', 'elapsedTime': '25', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11081::DEBUG::2012-07-16 16:49:10,385::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11081::DEBUG::2012-07-16 16:49:10,386::task::588::TaskManager.Task::(_updateState) Task=`dedcd312-a13a-4248-9fa0-6b0dd4adab25`::moving from state init -> state preparing
>Thread-11081::INFO::2012-07-16 16:49:10,386::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11081::INFO::2012-07-16 16:49:10,386::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11081::DEBUG::2012-07-16 16:49:10,387::task::1172::TaskManager.Task::(prepare) Task=`dedcd312-a13a-4248-9fa0-6b0dd4adab25`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11081::DEBUG::2012-07-16 16:49:10,387::task::588::TaskManager.Task::(_updateState) Task=`dedcd312-a13a-4248-9fa0-6b0dd4adab25`::moving from state preparing -> state finished
>Thread-11081::DEBUG::2012-07-16 16:49:10,387::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11081::DEBUG::2012-07-16 16:49:10,387::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11081::DEBUG::2012-07-16 16:49:10,387::task::978::TaskManager.Task::(_decref) Task=`dedcd312-a13a-4248-9fa0-6b0dd4adab25`::ref 0 aborting False
>Thread-11082::DEBUG::2012-07-16 16:49:10,405::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11082::DEBUG::2012-07-16 16:49:10,406::task::588::TaskManager.Task::(_updateState) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::moving from state init -> state preparing
>Thread-11082::INFO::2012-07-16 16:49:10,406::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11082::DEBUG::2012-07-16 16:49:10,406::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`d9c1d24b-88ec-4b85-baa5-1dfe6ef229a3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11082::DEBUG::2012-07-16 16:49:10,406::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11082::DEBUG::2012-07-16 16:49:10,407::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11082::DEBUG::2012-07-16 16:49:10,407::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`d9c1d24b-88ec-4b85-baa5-1dfe6ef229a3`::Granted request
>Thread-11082::DEBUG::2012-07-16 16:49:10,407::task::817::TaskManager.Task::(resourceAcquired) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11082::DEBUG::2012-07-16 16:49:10,407::task::978::TaskManager.Task::(_decref) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::ref 1 aborting False
>Thread-11082::INFO::2012-07-16 16:49:10,408::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11082::DEBUG::2012-07-16 16:49:10,408::task::1172::TaskManager.Task::(prepare) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11082::DEBUG::2012-07-16 16:49:10,409::task::588::TaskManager.Task::(_updateState) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::moving from state preparing -> state finished
>Thread-11082::DEBUG::2012-07-16 16:49:10,409::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11082::DEBUG::2012-07-16 16:49:10,409::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11082::DEBUG::2012-07-16 16:49:10,409::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11082::DEBUG::2012-07-16 16:49:10,409::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11082::DEBUG::2012-07-16 16:49:10,410::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11082::DEBUG::2012-07-16 16:49:10,410::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11082::DEBUG::2012-07-16 16:49:10,410::task::978::TaskManager.Task::(_decref) Task=`37bdaf2e-6e1c-409e-9d47-8b9cc984603f`::ref 0 aborting False
>Thread-11083::DEBUG::2012-07-16 16:49:12,229::task::588::TaskManager.Task::(_updateState) Task=`10d74245-13f2-4965-b940-639d6ffc2c0d`::moving from state init -> state preparing
>Thread-11083::INFO::2012-07-16 16:49:12,229::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11083::INFO::2012-07-16 16:49:12,229::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00157499313354', 'lastCheck': 1342457351.940469, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.0013210773468', 'lastCheck': 1342457346.655753, 'code': 0, 'valid': True}}
>Thread-11083::DEBUG::2012-07-16 16:49:12,229::task::1172::TaskManager.Task::(prepare) Task=`10d74245-13f2-4965-b940-639d6ffc2c0d`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00157499313354', 'lastCheck': 1342457351.940469, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.0013210773468', 'lastCheck': 1342457346.655753, 'code': 0, 'valid': True}}
>Thread-11083::DEBUG::2012-07-16 16:49:12,230::task::588::TaskManager.Task::(_updateState) Task=`10d74245-13f2-4965-b940-639d6ffc2c0d`::moving from state preparing -> state finished
>Thread-11083::DEBUG::2012-07-16 16:49:12,230::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11083::DEBUG::2012-07-16 16:49:12,230::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11083::DEBUG::2012-07-16 16:49:12,230::task::978::TaskManager.Task::(_decref) Task=`10d74245-13f2-4965-b940-639d6ffc2c0d`::ref 0 aborting False
>Thread-11084::DEBUG::2012-07-16 16:49:12,251::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11084::DEBUG::2012-07-16 16:49:12,251::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11084::DEBUG::2012-07-16 16:49:12,251::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11084::DEBUG::2012-07-16 16:49:12,251::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11086::DEBUG::2012-07-16 16:49:14,325::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11086::DEBUG::2012-07-16 16:49:14,325::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11086::DEBUG::2012-07-16 16:49:14,325::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11086::DEBUG::2012-07-16 16:49:14,326::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11086::DEBUG::2012-07-16 16:49:14,326::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11086::DEBUG::2012-07-16 16:49:14,326::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '33.30', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.61', 'cpuIdle': '66.70', 'elapsedTime': '29', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11088::DEBUG::2012-07-16 16:49:16,368::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11088::DEBUG::2012-07-16 16:49:16,369::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11088::DEBUG::2012-07-16 16:49:16,369::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11088::DEBUG::2012-07-16 16:49:16,369::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11088::DEBUG::2012-07-16 16:49:16,369::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11088::DEBUG::2012-07-16 16:49:16,370::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.66', 'cpuIdle': '93.34', 'elapsedTime': '31', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>VM Channels Listener::DEBUG::2012-07-16 16:49:16,559::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 51.
>Thread-11090::DEBUG::2012-07-16 16:49:18,411::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11090::DEBUG::2012-07-16 16:49:18,411::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11090::DEBUG::2012-07-16 16:49:18,411::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11090::DEBUG::2012-07-16 16:49:18,412::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11090::DEBUG::2012-07-16 16:49:18,412::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11090::DEBUG::2012-07-16 16:49:18,412::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.69', 'cpuIdle': '93.34', 'elapsedTime': '33', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11092::DEBUG::2012-07-16 16:49:20,451::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11092::DEBUG::2012-07-16 16:49:20,452::task::588::TaskManager.Task::(_updateState) Task=`1d53c3d4-3cf2-43a1-9510-1c3a17dfdd73`::moving from state init -> state preparing
>Thread-11092::INFO::2012-07-16 16:49:20,452::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11092::INFO::2012-07-16 16:49:20,453::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11092::DEBUG::2012-07-16 16:49:20,453::task::1172::TaskManager.Task::(prepare) Task=`1d53c3d4-3cf2-43a1-9510-1c3a17dfdd73`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11092::DEBUG::2012-07-16 16:49:20,454::task::588::TaskManager.Task::(_updateState) Task=`1d53c3d4-3cf2-43a1-9510-1c3a17dfdd73`::moving from state preparing -> state finished
>Thread-11092::DEBUG::2012-07-16 16:49:20,454::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11092::DEBUG::2012-07-16 16:49:20,454::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11092::DEBUG::2012-07-16 16:49:20,454::task::978::TaskManager.Task::(_decref) Task=`1d53c3d4-3cf2-43a1-9510-1c3a17dfdd73`::ref 0 aborting False
>Thread-11093::DEBUG::2012-07-16 16:49:20,481::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11094::DEBUG::2012-07-16 16:49:20,482::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11093::DEBUG::2012-07-16 16:49:20,482::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11094::DEBUG::2012-07-16 16:49:20,482::task::588::TaskManager.Task::(_updateState) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::moving from state init -> state preparing
>Thread-11093::DEBUG::2012-07-16 16:49:20,483::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11094::INFO::2012-07-16 16:49:20,483::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11093::DEBUG::2012-07-16 16:49:20,483::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11094::DEBUG::2012-07-16 16:49:20,484::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`550f399e-d9e0-46c9-85e0-bd7eb573bb03`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11093::DEBUG::2012-07-16 16:49:20,484::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11094::DEBUG::2012-07-16 16:49:20,484::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11093::DEBUG::2012-07-16 16:49:20,485::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.77', 'cpuIdle': '93.34', 'elapsedTime': '35', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11094::DEBUG::2012-07-16 16:49:20,486::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11094::DEBUG::2012-07-16 16:49:20,487::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`550f399e-d9e0-46c9-85e0-bd7eb573bb03`::Granted request
>Thread-11094::DEBUG::2012-07-16 16:49:20,487::task::817::TaskManager.Task::(resourceAcquired) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11094::DEBUG::2012-07-16 16:49:20,487::task::978::TaskManager.Task::(_decref) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::ref 1 aborting False
>Thread-11094::INFO::2012-07-16 16:49:20,488::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11094::DEBUG::2012-07-16 16:49:20,488::task::1172::TaskManager.Task::(prepare) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11094::DEBUG::2012-07-16 16:49:20,489::task::588::TaskManager.Task::(_updateState) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::moving from state preparing -> state finished
>Thread-11094::DEBUG::2012-07-16 16:49:20,489::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11094::DEBUG::2012-07-16 16:49:20,489::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11094::DEBUG::2012-07-16 16:49:20,489::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11094::DEBUG::2012-07-16 16:49:20,489::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11094::DEBUG::2012-07-16 16:49:20,490::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11094::DEBUG::2012-07-16 16:49:20,490::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11094::DEBUG::2012-07-16 16:49:20,490::task::978::TaskManager.Task::(_decref) Task=`7bbc490b-c6c1-4c77-a3aa-c87dbd3eecda`::ref 0 aborting False
>libvirtEventLoop::DEBUG::2012-07-16 16:49:21,724::libvirtconnection::58::vm.Vm::(__eventCallback) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::graphics event phase 0 localAddr {'node': '0.0.0.0', 'service': '5900', 'family': 0} remoteAddr {'node': '10.82.0.12', 'service': '36434', 'family': 0}authScheme vnc subject []
>Thread-11095::DEBUG::2012-07-16 16:49:22,524::task::588::TaskManager.Task::(_updateState) Task=`d9293823-e2bf-4d6b-b61a-e10f03f092c1`::moving from state init -> state preparing
>Thread-11095::INFO::2012-07-16 16:49:22,525::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11095::INFO::2012-07-16 16:49:22,525::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00209903717041', 'lastCheck': 1342457362.036626, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00130414962769', 'lastCheck': 1342457356.660148, 'code': 0, 'valid': True}}
>Thread-11095::DEBUG::2012-07-16 16:49:22,525::task::1172::TaskManager.Task::(prepare) Task=`d9293823-e2bf-4d6b-b61a-e10f03f092c1`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00209903717041', 'lastCheck': 1342457362.036626, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00130414962769', 'lastCheck': 1342457356.660148, 'code': 0, 'valid': True}}
>Thread-11095::DEBUG::2012-07-16 16:49:22,525::task::588::TaskManager.Task::(_updateState) Task=`d9293823-e2bf-4d6b-b61a-e10f03f092c1`::moving from state preparing -> state finished
>Thread-11095::DEBUG::2012-07-16 16:49:22,526::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11095::DEBUG::2012-07-16 16:49:22,526::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11095::DEBUG::2012-07-16 16:49:22,526::task::978::TaskManager.Task::(_decref) Task=`d9293823-e2bf-4d6b-b61a-e10f03f092c1`::ref 0 aborting False
>Thread-11096::DEBUG::2012-07-16 16:49:22,547::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11096::DEBUG::2012-07-16 16:49:22,547::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11096::DEBUG::2012-07-16 16:49:22,547::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11096::DEBUG::2012-07-16 16:49:22,547::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11098::DEBUG::2012-07-16 16:49:24,597::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11098::DEBUG::2012-07-16 16:49:24,598::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11098::DEBUG::2012-07-16 16:49:24,598::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11098::DEBUG::2012-07-16 16:49:24,598::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11098::DEBUG::2012-07-16 16:49:24,598::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11098::DEBUG::2012-07-16 16:49:24,599::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.88', 'cpuIdle': '93.34', 'elapsedTime': '39', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11100::DEBUG::2012-07-16 16:49:26,642::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11100::DEBUG::2012-07-16 16:49:26,642::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11100::DEBUG::2012-07-16 16:49:26,642::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11100::DEBUG::2012-07-16 16:49:26,643::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11100::DEBUG::2012-07-16 16:49:26,643::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11100::DEBUG::2012-07-16 16:49:26,643::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.92', 'cpuIdle': '93.34', 'elapsedTime': '41', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>libvirtEventLoop::DEBUG::2012-07-16 16:49:27,176::libvirtconnection::58::vm.Vm::(__eventCallback) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::graphics event phase 1 localAddr {'node': '0.0.0.0', 'service': '5900', 'family': 0} remoteAddr {'node': '10.82.0.12', 'service': '36434', 'family': 0}authScheme vnc subject []
>Thread-11102::DEBUG::2012-07-16 16:49:28,686::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11102::DEBUG::2012-07-16 16:49:28,687::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11102::DEBUG::2012-07-16 16:49:28,687::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11102::DEBUG::2012-07-16 16:49:28,687::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11102::DEBUG::2012-07-16 16:49:28,687::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11102::DEBUG::2012-07-16 16:49:28,687::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '6.66', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.97', 'cpuIdle': '93.34', 'elapsedTime': '43', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11103::DEBUG::2012-07-16 16:49:30,518::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11103::DEBUG::2012-07-16 16:49:30,519::task::588::TaskManager.Task::(_updateState) Task=`fad7d9fd-c0eb-4a43-9d47-039a6a5fbf6f`::moving from state init -> state preparing
>Thread-11103::INFO::2012-07-16 16:49:30,519::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11103::INFO::2012-07-16 16:49:30,519::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11103::DEBUG::2012-07-16 16:49:30,519::task::1172::TaskManager.Task::(prepare) Task=`fad7d9fd-c0eb-4a43-9d47-039a6a5fbf6f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11103::DEBUG::2012-07-16 16:49:30,519::task::588::TaskManager.Task::(_updateState) Task=`fad7d9fd-c0eb-4a43-9d47-039a6a5fbf6f`::moving from state preparing -> state finished
>Thread-11103::DEBUG::2012-07-16 16:49:30,520::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11103::DEBUG::2012-07-16 16:49:30,520::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11103::DEBUG::2012-07-16 16:49:30,520::task::978::TaskManager.Task::(_decref) Task=`fad7d9fd-c0eb-4a43-9d47-039a6a5fbf6f`::ref 0 aborting False
>Thread-11104::DEBUG::2012-07-16 16:49:30,537::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11104::DEBUG::2012-07-16 16:49:30,538::task::588::TaskManager.Task::(_updateState) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::moving from state init -> state preparing
>Thread-11104::INFO::2012-07-16 16:49:30,538::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11104::DEBUG::2012-07-16 16:49:30,538::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`7c82d75f-9721-4f4c-af45-9ce909b59d65`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11104::DEBUG::2012-07-16 16:49:30,539::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11104::DEBUG::2012-07-16 16:49:30,539::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11104::DEBUG::2012-07-16 16:49:30,539::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`7c82d75f-9721-4f4c-af45-9ce909b59d65`::Granted request
>Thread-11104::DEBUG::2012-07-16 16:49:30,539::task::817::TaskManager.Task::(resourceAcquired) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11104::DEBUG::2012-07-16 16:49:30,540::task::978::TaskManager.Task::(_decref) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::ref 1 aborting False
>Thread-11104::INFO::2012-07-16 16:49:30,540::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11104::DEBUG::2012-07-16 16:49:30,541::task::1172::TaskManager.Task::(prepare) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11104::DEBUG::2012-07-16 16:49:30,541::task::588::TaskManager.Task::(_updateState) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::moving from state preparing -> state finished
>Thread-11104::DEBUG::2012-07-16 16:49:30,541::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11104::DEBUG::2012-07-16 16:49:30,541::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11104::DEBUG::2012-07-16 16:49:30,541::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11104::DEBUG::2012-07-16 16:49:30,542::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11104::DEBUG::2012-07-16 16:49:30,542::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11104::DEBUG::2012-07-16 16:49:30,542::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11104::DEBUG::2012-07-16 16:49:30,542::task::978::TaskManager.Task::(_decref) Task=`b9858efa-5f9d-46a6-9fa1-093bfcb5cd7c`::ref 0 aborting False
>Thread-11106::DEBUG::2012-07-16 16:49:30,730::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11106::DEBUG::2012-07-16 16:49:30,730::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11106::DEBUG::2012-07-16 16:49:30,730::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11106::DEBUG::2012-07-16 16:49:30,731::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11106::DEBUG::2012-07-16 16:49:30,731::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11106::DEBUG::2012-07-16 16:49:30,731::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.01', 'cpuIdle': '100.00', 'elapsedTime': '45', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11107::DEBUG::2012-07-16 16:49:32,757::task::588::TaskManager.Task::(_updateState) Task=`a38548ed-3d18-4bcf-a988-93f6cdb0de20`::moving from state init -> state preparing
>Thread-11107::INFO::2012-07-16 16:49:32,758::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11107::INFO::2012-07-16 16:49:32,758::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00177502632141', 'lastCheck': 1342457372.127709, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00118899345398', 'lastCheck': 1342457366.664586, 'code': 0, 'valid': True}}
>Thread-11107::DEBUG::2012-07-16 16:49:32,758::task::1172::TaskManager.Task::(prepare) Task=`a38548ed-3d18-4bcf-a988-93f6cdb0de20`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00177502632141', 'lastCheck': 1342457372.127709, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00118899345398', 'lastCheck': 1342457366.664586, 'code': 0, 'valid': True}}
>Thread-11107::DEBUG::2012-07-16 16:49:32,758::task::588::TaskManager.Task::(_updateState) Task=`a38548ed-3d18-4bcf-a988-93f6cdb0de20`::moving from state preparing -> state finished
>Thread-11107::DEBUG::2012-07-16 16:49:32,759::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11107::DEBUG::2012-07-16 16:49:32,759::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11107::DEBUG::2012-07-16 16:49:32,759::task::978::TaskManager.Task::(_decref) Task=`a38548ed-3d18-4bcf-a988-93f6cdb0de20`::ref 0 aborting False
>Thread-11108::DEBUG::2012-07-16 16:49:32,780::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11108::DEBUG::2012-07-16 16:49:32,780::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11108::DEBUG::2012-07-16 16:49:32,781::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11108::DEBUG::2012-07-16 16:49:32,781::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11110::DEBUG::2012-07-16 16:49:34,831::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11110::DEBUG::2012-07-16 16:49:34,831::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11110::DEBUG::2012-07-16 16:49:34,832::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11110::DEBUG::2012-07-16 16:49:34,832::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11110::DEBUG::2012-07-16 16:49:34,832::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11110::DEBUG::2012-07-16 16:49:34,832::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '1.11', 'cpuIdle': '100.00', 'elapsedTime': '49', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11112::DEBUG::2012-07-16 16:49:36,872::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11112::DEBUG::2012-07-16 16:49:36,872::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11112::DEBUG::2012-07-16 16:49:36,872::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11112::DEBUG::2012-07-16 16:49:36,872::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11112::DEBUG::2012-07-16 16:49:36,872::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11112::DEBUG::2012-07-16 16:49:36,873::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '1.15', 'cpuIdle': '100.00', 'elapsedTime': '51', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11114::DEBUG::2012-07-16 16:49:38,914::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11114::DEBUG::2012-07-16 16:49:38,915::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11114::DEBUG::2012-07-16 16:49:38,915::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11114::DEBUG::2012-07-16 16:49:38,915::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11114::DEBUG::2012-07-16 16:49:38,915::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11114::DEBUG::2012-07-16 16:49:38,916::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '1.19', 'cpuIdle': '100.00', 'elapsedTime': '53', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11115::DEBUG::2012-07-16 16:49:40,570::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11115::DEBUG::2012-07-16 16:49:40,570::task::588::TaskManager.Task::(_updateState) Task=`5eddca2e-9d03-48eb-a7d3-f3d36c30d0ed`::moving from state init -> state preparing
>Thread-11115::INFO::2012-07-16 16:49:40,571::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11115::INFO::2012-07-16 16:49:40,571::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11115::DEBUG::2012-07-16 16:49:40,571::task::1172::TaskManager.Task::(prepare) Task=`5eddca2e-9d03-48eb-a7d3-f3d36c30d0ed`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11115::DEBUG::2012-07-16 16:49:40,571::task::588::TaskManager.Task::(_updateState) Task=`5eddca2e-9d03-48eb-a7d3-f3d36c30d0ed`::moving from state preparing -> state finished
>Thread-11115::DEBUG::2012-07-16 16:49:40,571::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11115::DEBUG::2012-07-16 16:49:40,572::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11115::DEBUG::2012-07-16 16:49:40,572::task::978::TaskManager.Task::(_decref) Task=`5eddca2e-9d03-48eb-a7d3-f3d36c30d0ed`::ref 0 aborting False
>Thread-11116::DEBUG::2012-07-16 16:49:40,589::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11116::DEBUG::2012-07-16 16:49:40,590::task::588::TaskManager.Task::(_updateState) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::moving from state init -> state preparing
>Thread-11116::INFO::2012-07-16 16:49:40,590::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11116::DEBUG::2012-07-16 16:49:40,590::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`f71ff388-9c67-448e-aa30-041122269b99`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11116::DEBUG::2012-07-16 16:49:40,591::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11116::DEBUG::2012-07-16 16:49:40,591::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11116::DEBUG::2012-07-16 16:49:40,591::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`f71ff388-9c67-448e-aa30-041122269b99`::Granted request
>Thread-11116::DEBUG::2012-07-16 16:49:40,592::task::817::TaskManager.Task::(resourceAcquired) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11116::DEBUG::2012-07-16 16:49:40,592::task::978::TaskManager.Task::(_decref) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::ref 1 aborting False
>Thread-11116::INFO::2012-07-16 16:49:40,593::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11116::DEBUG::2012-07-16 16:49:40,593::task::1172::TaskManager.Task::(prepare) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389283840', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11116::DEBUG::2012-07-16 16:49:40,593::task::588::TaskManager.Task::(_updateState) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::moving from state preparing -> state finished
>Thread-11116::DEBUG::2012-07-16 16:49:40,593::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11116::DEBUG::2012-07-16 16:49:40,593::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11116::DEBUG::2012-07-16 16:49:40,594::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11116::DEBUG::2012-07-16 16:49:40,594::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11116::DEBUG::2012-07-16 16:49:40,594::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11116::DEBUG::2012-07-16 16:49:40,594::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11116::DEBUG::2012-07-16 16:49:40,594::task::978::TaskManager.Task::(_decref) Task=`1ddcdcc6-2b13-4dbd-94bc-1ebe70a7067a`::ref 0 aborting False
>Thread-11118::DEBUG::2012-07-16 16:49:40,958::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11118::DEBUG::2012-07-16 16:49:40,958::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11118::DEBUG::2012-07-16 16:49:40,959::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11118::DEBUG::2012-07-16 16:49:40,959::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11118::DEBUG::2012-07-16 16:49:40,959::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11118::DEBUG::2012-07-16 16:49:40,959::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '0.23', 'cpuIdle': '100.00', 'elapsedTime': '55', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>Thread-11119::DEBUG::2012-07-16 16:49:42,985::task::588::TaskManager.Task::(_updateState) Task=`973e0217-26b7-4c1e-a207-5c4de7b07ee1`::moving from state init -> state preparing
>Thread-11119::INFO::2012-07-16 16:49:42,985::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-11119::INFO::2012-07-16 16:49:42,986::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00169587135315', 'lastCheck': 1342457382.219183, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00118899345398', 'lastCheck': 1342457376.668665, 'code': 0, 'valid': True}}
>Thread-11119::DEBUG::2012-07-16 16:49:42,986::task::1172::TaskManager.Task::(prepare) Task=`973e0217-26b7-4c1e-a207-5c4de7b07ee1`::finished: {'1176e766-9bec-42ca-b527-317d00ae8490': {'delay': '0.00169587135315', 'lastCheck': 1342457382.219183, 'code': 0, 'valid': True}, 'a407d973-2213-49da-bf84-1b08afb41236': {'delay': '0.00118899345398', 'lastCheck': 1342457376.668665, 'code': 0, 'valid': True}}
>Thread-11119::DEBUG::2012-07-16 16:49:42,986::task::588::TaskManager.Task::(_updateState) Task=`973e0217-26b7-4c1e-a207-5c4de7b07ee1`::moving from state preparing -> state finished
>Thread-11119::DEBUG::2012-07-16 16:49:42,986::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11119::DEBUG::2012-07-16 16:49:42,986::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11119::DEBUG::2012-07-16 16:49:42,986::task::978::TaskManager.Task::(_decref) Task=`973e0217-26b7-4c1e-a207-5c4de7b07ee1`::ref 0 aborting False
>Thread-11120::DEBUG::2012-07-16 16:49:43,007::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11120::DEBUG::2012-07-16 16:49:43,007::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11120::DEBUG::2012-07-16 16:49:43,008::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11120::DEBUG::2012-07-16 16:49:43,008::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11122::DEBUG::2012-07-16 16:49:45,055::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11122::DEBUG::2012-07-16 16:49:45,056::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc stats not available
>Thread-11122::DEBUG::2012-07-16 16:49:45,056::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda stats not available
>Thread-11122::DEBUG::2012-07-16 16:49:45,056::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk hdc latency not available
>Thread-11122::DEBUG::2012-07-16 16:49:45,056::libvirtvm::269::vm.Vm::(_getDiskLatency) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Disk vda latency not available
>Thread-11122::DEBUG::2012-07-16 16:49:45,056::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '87210', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': '-1', 'timeOffset': '-2', 'hash': '7245065504041612412', 'pauseCode': 'NOERR', 'clientIp': '10.82.0.12', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:fe:4e:01', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'displayType': 'vnc', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '1147043840', 'apparentsize': '10737418240', 'imageID': 'cb7a38f2-de94-4973-9ca8-9fffade64651'}, u'hdc': {}}, 'monitorResponse': '0', 'statsAge': '1.33', 'cpuIdle': '100.00', 'elapsedTime': '60', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,271::libvirtvm::2414::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::event Saved detail 0 opaque None
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,600::libvirtvm::2414::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::event Stopped detail 0 opaque None
>libvirtEventLoop::INFO::2012-07-16 16:49:45,601::vm::628::vm.Vm::(_onQemuDeath) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::underlying process disconnected
>libvirtEventLoop::INFO::2012-07-16 16:49:45,601::libvirtvm::2045::vm.Vm::(releaseVm) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Release VM resources
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,607::utils::336::vm.Vm::(stop) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Stop statistics collection
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,607::vmChannels::152::vds::(unregister) Delete fileno 51 from listener.
>Thread-11050::DEBUG::2012-07-16 16:49:45,607::utils::367::vm.Vm::(run) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Stats thread finished
>VM Channels Listener::DEBUG::2012-07-16 16:49:45,608::vmChannels::88::vds::(_do_del_channels) fileno 51 was removed from listener.
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,609::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/sudo -n /usr/sbin/service ksmtuned retune' (cwd None)
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,642::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'Unknown operation retune\n'; <rc> = 1
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,643::vmChannels::152::vds::(unregister) Delete fileno 51 from listener.
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,644::task::588::TaskManager.Task::(_updateState) Task=`1112b567-5701-4dc3-8214-0711ef386537`::moving from state init -> state preparing
>libvirtEventLoop::INFO::2012-07-16 16:49:45,644::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='2c9311b8-0939-4f68-b801-bd20bfada988')
>libvirtEventLoop::INFO::2012-07-16 16:49:45,644::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,645::task::1172::TaskManager.Task::(prepare) Task=`1112b567-5701-4dc3-8214-0711ef386537`::finished: None
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,645::task::588::TaskManager.Task::(_updateState) Task=`1112b567-5701-4dc3-8214-0711ef386537`::moving from state preparing -> state finished
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,645::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,645::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,645::task::978::TaskManager.Task::(_decref) Task=`1112b567-5701-4dc3-8214-0711ef386537`::ref 0 aborting False
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,652::vm::920::vm.Vm::(setDownStatus) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Changed state to Down: User shut down
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,652::vmChannels::152::vds::(unregister) Delete fileno 51 from listener.
>libvirtEventLoop::DEBUG::2012-07-16 16:49:45,652::utils::336::vm.Vm::(stop) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Stop statistics collection
>VM Channels Listener::DEBUG::2012-07-16 16:49:46,609::vmChannels::88::vds::(_do_del_channels) fileno 51 was removed from listener.
>VM Channels Listener::DEBUG::2012-07-16 16:49:46,610::vmChannels::88::vds::(_do_del_channels) fileno 51 was removed from listener.
>Thread-11124::DEBUG::2012-07-16 16:49:47,105::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmGetStats with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11124::DEBUG::2012-07-16 16:49:47,106::BindingXMLRPC::879::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '7245065504041612412', 'exitMessage': 'User shut down', 'vmId': '2c9311b8-0939-4f68-b801-bd20bfada988', 'timeOffset': '-2', 'exitCode': 0}]}
>Thread-11125::DEBUG::2012-07-16 16:49:47,125::BindingXMLRPC::872::vds::(wrapper) client [150.xxx.xxx.xxx]::call vmDestroy with ('2c9311b8-0939-4f68-b801-bd20bfada988',) {}
>Thread-11125::INFO::2012-07-16 16:49:47,125::API::308::vds::(destroy) vmContainerLock acquired by vm 2c9311b8-0939-4f68-b801-bd20bfada988
>Thread-11125::DEBUG::2012-07-16 16:49:47,126::libvirtvm::2090::vm.Vm::(destroy) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::destroy Called
>Thread-11125::DEBUG::2012-07-16 16:49:47,126::libvirtvm::2085::vm.Vm::(deleteVm) vmId=`2c9311b8-0939-4f68-b801-bd20bfada988`::Total desktops after destroy of 2c9311b8-0939-4f68-b801-bd20bfada988 is 0
>Thread-11125::DEBUG::2012-07-16 16:49:47,126::BindingXMLRPC::879::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
>Thread-11127::DEBUG::2012-07-16 16:49:50,621::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11127::DEBUG::2012-07-16 16:49:50,622::task::588::TaskManager.Task::(_updateState) Task=`6b15cfcb-9913-4273-874a-cf88f4429758`::moving from state init -> state preparing
>Thread-11127::INFO::2012-07-16 16:49:50,622::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11127::INFO::2012-07-16 16:49:50,623::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11127::DEBUG::2012-07-16 16:49:50,623::task::1172::TaskManager.Task::(prepare) Task=`6b15cfcb-9913-4273-874a-cf88f4429758`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-11127::DEBUG::2012-07-16 16:49:50,623::task::588::TaskManager.Task::(_updateState) Task=`6b15cfcb-9913-4273-874a-cf88f4429758`::moving from state preparing -> state finished
>Thread-11127::DEBUG::2012-07-16 16:49:50,623::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-11127::DEBUG::2012-07-16 16:49:50,623::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11127::DEBUG::2012-07-16 16:49:50,624::task::978::TaskManager.Task::(_decref) Task=`6b15cfcb-9913-4273-874a-cf88f4429758`::ref 0 aborting False
>Thread-11128::DEBUG::2012-07-16 16:49:50,641::BindingXMLRPC::160::vds::(wrapper) [150.xxx.xxx.xxx]
>Thread-11128::DEBUG::2012-07-16 16:49:50,641::task::588::TaskManager.Task::(_updateState) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::moving from state init -> state preparing
>Thread-11128::INFO::2012-07-16 16:49:50,641::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='3966bab3-5801-4345-a808-a802ba96e380', options=None)
>Thread-11128::DEBUG::2012-07-16 16:49:50,642::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`906b1d82-b31e-4432-b492-df7507187672`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-11128::DEBUG::2012-07-16 16:49:50,642::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' for lock type 'shared'
>Thread-11128::DEBUG::2012-07-16 16:49:50,642::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free. Now locking as 'shared' (1 active user)
>Thread-11128::DEBUG::2012-07-16 16:49:50,643::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.3966bab3-5801-4345-a808-a802ba96e380`ReqID=`906b1d82-b31e-4432-b492-df7507187672`::Granted request
>Thread-11128::DEBUG::2012-07-16 16:49:50,643::task::817::TaskManager.Task::(resourceAcquired) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::_resourcesAcquired: Storage.3966bab3-5801-4345-a808-a802ba96e380 (shared)
>Thread-11128::DEBUG::2012-07-16 16:49:50,643::task::978::TaskManager.Task::(_decref) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::ref 1 aborting False
>Thread-11128::INFO::2012-07-16 16:49:50,644::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11128::DEBUG::2012-07-16 16:49:50,644::task::1172::TaskManager.Task::(prepare) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::finished: {'info': {'spm_id': 1, 'master_uuid': 'a407d973-2213-49da-bf84-1b08afb41236', 'name': 'A1-27', 'version': '0', 'domains': '1176e766-9bec-42ca-b527-317d00ae8490:Active,a407d973-2213-49da-bf84-1b08afb41236:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/3966bab3-5801-4345-a808-a802ba96e380/1176e766-9bec-42ca-b527-317d00ae8490/images/11111111-1111-1111-1111-111111111111', 'type': 'LOCALFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'1176e766-9bec-42ca-b527-317d00ae8490': {'status': 'Active', 'diskfree': '389545984', 'alerts': [], 'disktotal': '5958008832'}, 'a407d973-2213-49da-bf84-1b08afb41236': {'status': 'Active', 'diskfree': '3722210607104', 'alerts': [], 'disktotal': '3981369057280'}}}
>Thread-11128::DEBUG::2012-07-16 16:49:50,644::task::588::TaskManager.Task::(_updateState) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::moving from state preparing -> state finished
>Thread-11128::DEBUG::2012-07-16 16:49:50,645::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3966bab3-5801-4345-a808-a802ba96e380': < ResourceRef 'Storage.3966bab3-5801-4345-a808-a802ba96e380', isValid: 'True' obj: 'None'>}
>Thread-11128::DEBUG::2012-07-16 16:49:50,645::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-11128::DEBUG::2012-07-16 16:49:50,645::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380'
>Thread-11128::DEBUG::2012-07-16 16:49:50,645::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' (0 active users)
>Thread-11128::DEBUG::2012-07-16 16:49:50,645::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380' is free, finding out if anyone is waiting for it.
>Thread-11128::DEBUG::2012-07-16 16:49:50,646::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3966bab3-5801-4345-a808-a802ba96e380', Clearing records.
>Thread-11128::DEBUG::2012-07-16 16:49:50,646::task::978::TaskManager.Task::(_decref) Task=`5d3860ed-dca6-46fc-bcd4-0235b3a409ad`::ref 0 aborting False

Actions: View

Attachments on bug 840538: 598502 | 598503 | 598504