Attachment 607141 Details for Bug 851397 – vdsm.log

vdsm.log

vdsm.log (text/plain), 112.51 KB, created by EricLee on 2012-08-27 07:11:45 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: EricLee

Created: 2012-08-27 07:11:45 UTC

Size: 112.51 KB

patch

obsolete

>Thread-104::DEBUG::2012-08-27 14:51:41,681::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-104::DEBUG::2012-08-27 14:51:41,681::task::588::TaskManager.Task::(_updateState) Task=`eb8d0b83-93b1-48e1-a70a-ced8f583a60a`::moving from state init -> state preparing
>Thread-104::INFO::2012-08-27 14:51:41,682::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-104::INFO::2012-08-27 14:51:41,682::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-104::DEBUG::2012-08-27 14:51:41,682::task::1172::TaskManager.Task::(prepare) Task=`eb8d0b83-93b1-48e1-a70a-ced8f583a60a`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-104::DEBUG::2012-08-27 14:51:41,682::task::588::TaskManager.Task::(_updateState) Task=`eb8d0b83-93b1-48e1-a70a-ced8f583a60a`::moving from state preparing -> state finished
>Thread-104::DEBUG::2012-08-27 14:51:41,683::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-104::DEBUG::2012-08-27 14:51:41,683::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-104::DEBUG::2012-08-27 14:51:41,683::task::978::TaskManager.Task::(_decref) Task=`eb8d0b83-93b1-48e1-a70a-ced8f583a60a`::ref 0 aborting False
>Thread-106::DEBUG::2012-08-27 14:51:44,732::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-105::DEBUG::2012-08-27 14:51:44,735::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmCreate with ({'custom': {'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4b': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=7526253a-766d-40f3-a8a0-5ea438c13d4b,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_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=e77bdf79-b15a-4a3e-aafd-4be22aac7d69,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_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=8c693402-88b7-49f5-9c5e-5e43b03951a1,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_0474e977-a2ae-47f1-bcf0-812549429e1e': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=0474e977-a2ae-47f1-bcf0-812549429e1e,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', 'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4bdevice_ef9c9676-0190-47d4-b5ce-5771aab849b7device_eea8189f-905c-4526-8b7d-0945aa226d44': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=eea8189f-905c-4526-8b7d-0945aa226d44,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=3, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel2', 'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4bdevice_ef9c9676-0190-47d4-b5ce-5771aab849b7': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=ef9c9676-0190-47d4-b5ce-5771aab849b7,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'displayNetwork': 'rhevm', 'vmId': 'ce702a19-32ba-45d4-b84e-e748a9d19573', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '8ba90d28-9922-43fa-b2f7-30a6323bb82e', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '7745f42d-fe34-4991-934e-f803afa84b9b', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '224281dd-7258-417c-a46e-dc025185e03e', 'volumeID': '366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'imageID': '7d39b4af-60da-4af0-9469-c13efc293c1d', 'specParams': {}, 'readonly': 'false', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'deviceId': '7d39b4af-60da-4af0-9469-c13efc293c1d', '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:a8:7a:02', 'network': 'rhevm', 'specParams': {}, 'deviceId': 'b46afdd5-33a6-4e96-b4d3-46678a868656', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '0474e977-a2ae-47f1-bcf0-812549429e1e', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '770b323d-9d38-4a52-a9ae-87bac99990eb'}], 'smp': '1', 'vmType': 'kvm', 'timeOffset': '0', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs', 'smpCoresPerSocket': '1', 'vmName': 'rc1', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [595917c6]
>Thread-106::DEBUG::2012-08-27 14:51:44,735::task::588::TaskManager.Task::(_updateState) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::moving from state init -> state preparing
>Thread-106::INFO::2012-08-27 14:51:44,738::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-106::DEBUG::2012-08-27 14:51:44,739::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`1992b78d-0f26-49d3-8d18-591ad3759862`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-106::DEBUG::2012-08-27 14:51:44,740::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-106::DEBUG::2012-08-27 14:51:44,741::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-106::DEBUG::2012-08-27 14:51:44,741::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`1992b78d-0f26-49d3-8d18-591ad3759862`::Granted request
>Thread-106::DEBUG::2012-08-27 14:51:44,742::task::817::TaskManager.Task::(resourceAcquired) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-106::DEBUG::2012-08-27 14:51:44,742::task::978::TaskManager.Task::(_decref) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::ref 1 aborting False
>Thread-106::INFO::2012-08-27 14:51:44,746::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-106::DEBUG::2012-08-27 14:51:44,746::task::1172::TaskManager.Task::(prepare) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-106::DEBUG::2012-08-27 14:51:44,747::task::588::TaskManager.Task::(_updateState) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::moving from state preparing -> state finished
>Thread-106::DEBUG::2012-08-27 14:51:44,747::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-106::DEBUG::2012-08-27 14:51:44,747::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-106::DEBUG::2012-08-27 14:51:44,747::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-106::DEBUG::2012-08-27 14:51:44,748::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-106::DEBUG::2012-08-27 14:51:44,748::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-106::DEBUG::2012-08-27 14:51:44,748::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-106::DEBUG::2012-08-27 14:51:44,748::task::978::TaskManager.Task::(_decref) Task=`3d62a920-83c4-4e43-8943-6916fdc3bca5`::ref 0 aborting False
>Thread-105::INFO::2012-08-27 14:51:44,750::API::216::vds::(create) vmContainerLock acquired by vm ce702a19-32ba-45d4-b84e-e748a9d19573
>Thread-107::DEBUG::2012-08-27 14:51:44,753::vm::567::vm.Vm::(_startUnderlyingVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::Start
>Thread-105::DEBUG::2012-08-27 14:51:44,753::API::229::vds::(create) Total desktops after creation of ce702a19-32ba-45d4-b84e-e748a9d19573 is 1
>Thread-107::DEBUG::2012-08-27 14:51:44,753::vm::571::vm.Vm::(_startUnderlyingVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::_ongoingCreations acquired
>Thread-105::DEBUG::2012-08-27 14:51:44,754::BindingXMLRPC::870::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'vmId': 'ce702a19-32ba-45d4-b84e-e748a9d19573', 'pid': '0', 'timeOffset': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4b': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=7526253a-766d-40f3-a8a0-5ea438c13d4b,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_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=e77bdf79-b15a-4a3e-aafd-4be22aac7d69,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_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=8c693402-88b7-49f5-9c5e-5e43b03951a1,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_0474e977-a2ae-47f1-bcf0-812549429e1e': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=0474e977-a2ae-47f1-bcf0-812549429e1e,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', 'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4bdevice_ef9c9676-0190-47d4-b5ce-5771aab849b7device_eea8189f-905c-4526-8b7d-0945aa226d44': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=eea8189f-905c-4526-8b7d-0945aa226d44,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=3, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel2', 'device_0474e977-a2ae-47f1-bcf0-812549429e1edevice_e77bdf79-b15a-4a3e-aafd-4be22aac7d69device_8c693402-88b7-49f5-9c5e-5e43b03951a1device_7526253a-766d-40f3-a8a0-5ea438c13d4bdevice_ef9c9676-0190-47d4-b5ce-5771aab849b7': 'VmId=ce702a19-32ba-45d4-b84e-e748a9d19573,DeviceId=ef9c9676-0190-47d4-b5ce-5771aab849b7,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'displayNetwork': 'rhevm', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '8ba90d28-9922-43fa-b2f7-30a6323bb82e', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '7745f42d-fe34-4991-934e-f803afa84b9b', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '224281dd-7258-417c-a46e-dc025185e03e', 'volumeID': '366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'imageID': '7d39b4af-60da-4af0-9469-c13efc293c1d', 'specParams': {}, 'readonly': 'false', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'deviceId': '7d39b4af-60da-4af0-9469-c13efc293c1d', '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:a8:7a:02', 'network': 'rhevm', 'specParams': {}, 'deviceId': 'b46afdd5-33a6-4e96-b4d3-46678a868656', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '0474e977-a2ae-47f1-bcf0-812549429e1e', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '770b323d-9d38-4a52-a9ae-87bac99990eb'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 512, 'displayIp': '10.66.5.143', 'spiceSecureChannels': 'smain,sinputs', 'smpCoresPerSocket': '1', 'vmName': 'rc1', 'display': 'qxl', 'nice': '0'}}
>Thread-107::INFO::2012-08-27 14:51:44,754::libvirtvm::1306::vm.Vm::(_run) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::VM wrapper has started
>Thread-107::DEBUG::2012-08-27 14:51:44,755::task::588::TaskManager.Task::(_updateState) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::moving from state init -> state preparing
>Thread-107::INFO::2012-08-27 14:51:44,756::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='9bd82898-9672-4cc1-b7ad-ac722e00822b', spUUID='224281dd-7258-417c-a46e-dc025185e03e', imgUUID='7d39b4af-60da-4af0-9469-c13efc293c1d', volUUID='366a43a2-32e5-4868-bc1b-bed0ce31b8ef', options=None)
>Thread-107::DEBUG::2012-08-27 14:51:44,756::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`6e814a5f-fb14-4524-8b83-866a0cfd1a24`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-107::DEBUG::2012-08-27 14:51:44,756::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' for lock type 'shared'
>Thread-107::DEBUG::2012-08-27 14:51:44,757::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free. Now locking as 'shared' (1 active user)
>Thread-107::DEBUG::2012-08-27 14:51:44,757::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`6e814a5f-fb14-4524-8b83-866a0cfd1a24`::Granted request
>Thread-107::DEBUG::2012-08-27 14:51:44,757::task::817::TaskManager.Task::(resourceAcquired) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::_resourcesAcquired: Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b (shared)
>Thread-107::DEBUG::2012-08-27 14:51:44,758::task::978::TaskManager.Task::(_decref) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::ref 1 aborting False
>Thread-107::DEBUG::2012-08-27 14:51:44,759::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 366a43a2-32e5-4868-bc1b-bed0ce31b8ef
>Thread-107::DEBUG::2012-08-27 14:51:44,762::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 366a43a2-32e5-4868-bc1b-bed0ce31b8ef
>Thread-107::INFO::2012-08-27 14:51:44,763::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '8589934592'}
>Thread-107::DEBUG::2012-08-27 14:51:44,763::task::1172::TaskManager.Task::(prepare) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::finished: {'truesize': '0', 'apparentsize': '8589934592'}
>Thread-107::DEBUG::2012-08-27 14:51:44,763::task::588::TaskManager.Task::(_updateState) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::moving from state preparing -> state finished
>Thread-107::DEBUG::2012-08-27 14:51:44,763::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b': < ResourceRef 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', isValid: 'True' obj: 'None'>}
>Thread-107::DEBUG::2012-08-27 14:51:44,764::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-107::DEBUG::2012-08-27 14:51:44,764::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b'
>Thread-107::DEBUG::2012-08-27 14:51:44,764::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' (0 active users)
>Thread-107::DEBUG::2012-08-27 14:51:44,764::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free, finding out if anyone is waiting for it.
>Thread-107::DEBUG::2012-08-27 14:51:44,764::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', Clearing records.
>Thread-107::DEBUG::2012-08-27 14:51:44,765::task::978::TaskManager.Task::(_decref) Task=`e0f07248-1b80-4c9d-b1bf-86147d8db3c4`::ref 0 aborting False
>Thread-107::INFO::2012-08-27 14:51:44,765::clientIF::233::vds::(prepareVolumePath) prepared volume path: 
>Thread-107::DEBUG::2012-08-27 14:51:44,765::task::588::TaskManager.Task::(_updateState) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::moving from state init -> state preparing
>Thread-107::INFO::2012-08-27 14:51:44,765::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='9bd82898-9672-4cc1-b7ad-ac722e00822b', spUUID='224281dd-7258-417c-a46e-dc025185e03e', imgUUID='7d39b4af-60da-4af0-9469-c13efc293c1d', volUUID='366a43a2-32e5-4868-bc1b-bed0ce31b8ef')
>Thread-107::DEBUG::2012-08-27 14:51:44,766::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`804dee4e-e90a-46a6-8840-1effa197f73f`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-107::DEBUG::2012-08-27 14:51:44,766::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' for lock type 'shared'
>Thread-107::DEBUG::2012-08-27 14:51:44,766::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free. Now locking as 'shared' (1 active user)
>Thread-107::DEBUG::2012-08-27 14:51:44,766::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`804dee4e-e90a-46a6-8840-1effa197f73f`::Granted request
>Thread-107::DEBUG::2012-08-27 14:51:44,767::task::817::TaskManager.Task::(resourceAcquired) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::_resourcesAcquired: Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b (shared)
>Thread-107::DEBUG::2012-08-27 14:51:44,767::task::978::TaskManager.Task::(_decref) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::ref 1 aborting False
>Thread-107::DEBUG::2012-08-27 14:51:44,768::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 366a43a2-32e5-4868-bc1b-bed0ce31b8ef
>Thread-107::INFO::2012-08-27 14:51:44,771::image::319::Storage.Image::(getChain) sdUUID=9bd82898-9672-4cc1-b7ad-ac722e00822b imgUUID=7d39b4af-60da-4af0-9469-c13efc293c1d chain=[<storage.fileVolume.FileVolume object at 0x1609950>] 
>Thread-107::INFO::2012-08-27 14:51:44,773::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'chain': [{'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'volumeID': '366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'imageID': '7d39b4af-60da-4af0-9469-c13efc293c1d'}]}
>Thread-107::DEBUG::2012-08-27 14:51:44,773::task::1172::TaskManager.Task::(prepare) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::finished: {'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'chain': [{'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'volumeID': '366a43a2-32e5-4868-bc1b-bed0ce31b8ef', 'imageID': '7d39b4af-60da-4af0-9469-c13efc293c1d'}]}
>Thread-107::DEBUG::2012-08-27 14:51:44,773::task::588::TaskManager.Task::(_updateState) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::moving from state preparing -> state finished
>Thread-107::DEBUG::2012-08-27 14:51:44,774::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b': < ResourceRef 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', isValid: 'True' obj: 'None'>}
>Thread-107::DEBUG::2012-08-27 14:51:44,774::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-107::DEBUG::2012-08-27 14:51:44,774::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b'
>Thread-107::DEBUG::2012-08-27 14:51:44,775::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' (0 active users)
>Thread-107::DEBUG::2012-08-27 14:51:44,775::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free, finding out if anyone is waiting for it.
>Thread-107::DEBUG::2012-08-27 14:51:44,775::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', Clearing records.
>Thread-107::DEBUG::2012-08-27 14:51:44,775::task::978::TaskManager.Task::(_decref) Task=`bda16513-2577-4446-bb9e-b1bcc0748d65`::ref 0 aborting False
>Thread-107::INFO::2012-08-27 14:51:44,776::clientIF::233::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef
>Thread-107::DEBUG::2012-08-27 14:51:44,784::libvirtvm::1359::vm.Vm::(_run) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>rc1</name>
>	<uuid>ce702a19-32ba-45d4-b84e-e748a9d19573</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/rc1.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/rc1.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<listen network="vdsm-rhevm" type="network"/>
>		</graphics>
>		<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:a8:7a:02"/>
>			<model type="virtio"/>
>			<source bridge="rhevm"/>
>		</interface>
>		<memballoon model="virtio"/>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address  bus="1"  controller="0"  target="0"  type="drive" unit="0"/>
>			<source file="" 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/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/7d39b4af-60da-4af0-9469-c13efc293c1d/366a43a2-32e5-4868-bc1b-bed0ce31b8ef"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>7d39b4af-60da-4af0-9469-c13efc293c1d</serial>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="rhel6.3.0">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">6Server-6.3.0.3.el6</entry>
>			<entry name="serial">44454C4C-3800-104E-8058-C3C04F4B3258_00:15:17:62:AE:E8</entry>
>			<entry name="uuid">ce702a19-32ba-45d4-b84e-e748a9d19573</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Conroe</model>
>		<topology cores="1" sockets="1" threads="1"/>
>	</cpu>
></domain>
>
>Thread-107::DEBUG::2012-08-27 14:51:45,555::vm::583::vm.Vm::(_startUnderlyingVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::_ongoingCreations released
>Thread-107::ERROR::2012-08-27 14:51:45,555::vm::607::vm.Vm::(_startUnderlyingVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 573, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/libvirtvm.py", line 1385, in _run
>    self._connection.createXML(domxml, flags),
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2560, in createXML
>    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
>libvirtError: internal error Process exited while reading console log output: char device redirected to /dev/pts/1
>do_spice_init: starting 0.10.1
>reds_init_socket: reds_init_socket: binding socket to 10.66.5.143:5900 failed
>failed to initialize spice server
>Thread-107::DEBUG::2012-08-27 14:51:45,558::vm::923::vm.Vm::(setDownStatus) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::Changed state to Down: internal error Process exited while reading console log output: char device redirected to /dev/pts/1
>do_spice_init: starting 0.10.1
>reds_init_socket: reds_init_socket: binding socket to 10.66.5.143:5900 failed
>failed to initialize spice server
>Thread-110::DEBUG::2012-08-27 14:51:51,467::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmGetStats with ('ce702a19-32ba-45d4-b84e-e748a9d19573',) {} flowID [2967b967]
>Thread-110::DEBUG::2012-08-27 14:51:51,467::BindingXMLRPC::870::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '0', 'exitMessage': 'internal error Process exited while reading console log output: char device redirected to /dev/pts/1\ndo_spice_init: starting 0.10.1\nreds_init_socket: reds_init_socket: binding socket to 10.66.5.143:5900 failed\nfailed to initialize spice server', 'vmId': 'ce702a19-32ba-45d4-b84e-e748a9d19573', 'timeOffset': '0', 'exitCode': 1}]}
>Thread-111::DEBUG::2012-08-27 14:51:54,918::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmDestroy with ('ce702a19-32ba-45d4-b84e-e748a9d19573',) {} flowID [2967b967]
>Thread-111::INFO::2012-08-27 14:51:54,919::API::301::vds::(destroy) vmContainerLock acquired by vm ce702a19-32ba-45d4-b84e-e748a9d19573
>Thread-111::DEBUG::2012-08-27 14:51:54,919::libvirtvm::2109::vm.Vm::(destroy) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::destroy Called
>Thread-111::INFO::2012-08-27 14:51:54,919::libvirtvm::2064::vm.Vm::(releaseVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::Release VM resources
>Thread-111::WARNING::2012-08-27 14:51:54,920::vm::328::vm.Vm::(_set_lastStatus) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::trying to set state to Powering down when already Down
>Thread-111::DEBUG::2012-08-27 14:51:54,920::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/service ksmtuned retune' (cwd None)
>Thread-111::DEBUG::2012-08-27 14:51:54,953::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-111::DEBUG::2012-08-27 14:51:54,957::task::588::TaskManager.Task::(_updateState) Task=`5f25cfce-d01d-49d3-a3d4-36721f683a1f`::moving from state init -> state preparing
>Thread-111::INFO::2012-08-27 14:51:54,958::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='ce702a19-32ba-45d4-b84e-e748a9d19573')
>Thread-111::INFO::2012-08-27 14:51:54,960::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
>Thread-111::DEBUG::2012-08-27 14:51:54,961::task::1172::TaskManager.Task::(prepare) Task=`5f25cfce-d01d-49d3-a3d4-36721f683a1f`::finished: None
>Thread-111::DEBUG::2012-08-27 14:51:54,961::task::588::TaskManager.Task::(_updateState) Task=`5f25cfce-d01d-49d3-a3d4-36721f683a1f`::moving from state preparing -> state finished
>Thread-111::DEBUG::2012-08-27 14:51:54,961::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-111::DEBUG::2012-08-27 14:51:54,961::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-111::DEBUG::2012-08-27 14:51:54,961::task::978::TaskManager.Task::(_decref) Task=`5f25cfce-d01d-49d3-a3d4-36721f683a1f`::ref 0 aborting False
>Thread-111::DEBUG::2012-08-27 14:51:54,962::libvirtvm::2104::vm.Vm::(deleteVm) vmId=`ce702a19-32ba-45d4-b84e-e748a9d19573`::Total desktops after destroy of ce702a19-32ba-45d4-b84e-e748a9d19573 is 0
>Thread-111::DEBUG::2012-08-27 14:51:54,962::BindingXMLRPC::870::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
>Thread-112::DEBUG::2012-08-27 14:51:58,194::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-112::DEBUG::2012-08-27 14:51:58,194::task::588::TaskManager.Task::(_updateState) Task=`40d098d7-d9b8-4f11-b619-fc841be98826`::moving from state init -> state preparing
>Thread-112::INFO::2012-08-27 14:51:58,195::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-112::INFO::2012-08-27 14:51:58,195::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-112::DEBUG::2012-08-27 14:51:58,195::task::1172::TaskManager.Task::(prepare) Task=`40d098d7-d9b8-4f11-b619-fc841be98826`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-112::DEBUG::2012-08-27 14:51:58,195::task::588::TaskManager.Task::(_updateState) Task=`40d098d7-d9b8-4f11-b619-fc841be98826`::moving from state preparing -> state finished
>Thread-112::DEBUG::2012-08-27 14:51:58,196::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-112::DEBUG::2012-08-27 14:51:58,196::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-112::DEBUG::2012-08-27 14:51:58,196::task::978::TaskManager.Task::(_decref) Task=`40d098d7-d9b8-4f11-b619-fc841be98826`::ref 0 aborting False
>Thread-113::DEBUG::2012-08-27 14:51:59,975::task::588::TaskManager.Task::(_updateState) Task=`83ba453b-c4a2-4826-91d6-8bef8d2563bc`::moving from state init -> state preparing
>Thread-113::INFO::2012-08-27 14:51:59,975::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-113::INFO::2012-08-27 14:51:59,975::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00171685218811', 'lastCheck': 1346050318.898607, 'code': 0, 'valid': True}}
>Thread-113::DEBUG::2012-08-27 14:51:59,976::task::1172::TaskManager.Task::(prepare) Task=`83ba453b-c4a2-4826-91d6-8bef8d2563bc`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00171685218811', 'lastCheck': 1346050318.898607, 'code': 0, 'valid': True}}
>Thread-113::DEBUG::2012-08-27 14:51:59,976::task::588::TaskManager.Task::(_updateState) Task=`83ba453b-c4a2-4826-91d6-8bef8d2563bc`::moving from state preparing -> state finished
>Thread-113::DEBUG::2012-08-27 14:51:59,976::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-113::DEBUG::2012-08-27 14:51:59,976::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-113::DEBUG::2012-08-27 14:51:59,976::task::978::TaskManager.Task::(_decref) Task=`83ba453b-c4a2-4826-91d6-8bef8d2563bc`::ref 0 aborting False
>Thread-114::DEBUG::2012-08-27 14:52:01,606::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-114::DEBUG::2012-08-27 14:52:01,607::task::588::TaskManager.Task::(_updateState) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::moving from state init -> state preparing
>Thread-114::INFO::2012-08-27 14:52:01,607::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-114::DEBUG::2012-08-27 14:52:01,607::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`b2efe9ea-6e00-4293-b077-00490afc075e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-114::DEBUG::2012-08-27 14:52:01,608::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-114::DEBUG::2012-08-27 14:52:01,608::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-114::DEBUG::2012-08-27 14:52:01,608::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`b2efe9ea-6e00-4293-b077-00490afc075e`::Granted request
>Thread-114::DEBUG::2012-08-27 14:52:01,609::task::817::TaskManager.Task::(resourceAcquired) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-114::DEBUG::2012-08-27 14:52:01,609::task::978::TaskManager.Task::(_decref) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::ref 1 aborting False
>Thread-114::INFO::2012-08-27 14:52:01,612::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-114::DEBUG::2012-08-27 14:52:01,612::task::1172::TaskManager.Task::(prepare) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-114::DEBUG::2012-08-27 14:52:01,612::task::588::TaskManager.Task::(_updateState) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::moving from state preparing -> state finished
>Thread-114::DEBUG::2012-08-27 14:52:01,612::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-114::DEBUG::2012-08-27 14:52:01,613::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-114::DEBUG::2012-08-27 14:52:01,613::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-114::DEBUG::2012-08-27 14:52:01,613::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-114::DEBUG::2012-08-27 14:52:01,613::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-114::DEBUG::2012-08-27 14:52:01,613::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-114::DEBUG::2012-08-27 14:52:01,614::task::978::TaskManager.Task::(_decref) Task=`8d2b51ae-4d7d-48d3-81e8-27cd1914cc35`::ref 0 aborting False
>Thread-118::DEBUG::2012-08-27 14:52:14,882::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-118::DEBUG::2012-08-27 14:52:14,883::task::588::TaskManager.Task::(_updateState) Task=`905d68df-62a2-4be5-a38e-97f232dd39ff`::moving from state init -> state preparing
>Thread-118::INFO::2012-08-27 14:52:14,883::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-118::INFO::2012-08-27 14:52:14,883::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-118::DEBUG::2012-08-27 14:52:14,884::task::1172::TaskManager.Task::(prepare) Task=`905d68df-62a2-4be5-a38e-97f232dd39ff`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-118::DEBUG::2012-08-27 14:52:14,884::task::588::TaskManager.Task::(_updateState) Task=`905d68df-62a2-4be5-a38e-97f232dd39ff`::moving from state preparing -> state finished
>Thread-118::DEBUG::2012-08-27 14:52:14,884::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-118::DEBUG::2012-08-27 14:52:14,884::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118::DEBUG::2012-08-27 14:52:14,885::task::978::TaskManager.Task::(_decref) Task=`905d68df-62a2-4be5-a38e-97f232dd39ff`::ref 0 aborting False
>Thread-119::DEBUG::2012-08-27 14:52:18,237::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-119::DEBUG::2012-08-27 14:52:18,237::task::588::TaskManager.Task::(_updateState) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::moving from state init -> state preparing
>Thread-119::INFO::2012-08-27 14:52:18,238::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-119::DEBUG::2012-08-27 14:52:18,238::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`c9afbffc-60fc-4f47-a5ca-cdd66d45daa0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-119::DEBUG::2012-08-27 14:52:18,238::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-119::DEBUG::2012-08-27 14:52:18,238::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-119::DEBUG::2012-08-27 14:52:18,239::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`c9afbffc-60fc-4f47-a5ca-cdd66d45daa0`::Granted request
>Thread-119::DEBUG::2012-08-27 14:52:18,239::task::817::TaskManager.Task::(resourceAcquired) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-119::DEBUG::2012-08-27 14:52:18,239::task::978::TaskManager.Task::(_decref) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::ref 1 aborting False
>Thread-119::INFO::2012-08-27 14:52:18,242::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-119::DEBUG::2012-08-27 14:52:18,242::task::1172::TaskManager.Task::(prepare) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-119::DEBUG::2012-08-27 14:52:18,243::task::588::TaskManager.Task::(_updateState) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::moving from state preparing -> state finished
>Thread-119::DEBUG::2012-08-27 14:52:18,243::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-119::DEBUG::2012-08-27 14:52:18,243::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-119::DEBUG::2012-08-27 14:52:18,243::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-119::DEBUG::2012-08-27 14:52:18,244::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-119::DEBUG::2012-08-27 14:52:18,244::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-119::DEBUG::2012-08-27 14:52:18,244::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-119::DEBUG::2012-08-27 14:52:18,244::task::978::TaskManager.Task::(_decref) Task=`8939789b-aeec-4879-84bf-0e551eb06c65`::ref 0 aborting False
>Thread-122::DEBUG::2012-08-27 14:52:29,011::task::588::TaskManager.Task::(_updateState) Task=`9e874973-2d47-4bc1-bc48-87e2eb16d61b`::moving from state init -> state preparing
>Thread-122::INFO::2012-08-27 14:52:29,012::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-122::INFO::2012-08-27 14:52:29,012::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00149202346802', 'lastCheck': 1346050348.917232, 'code': 0, 'valid': True}}
>Thread-122::DEBUG::2012-08-27 14:52:29,012::task::1172::TaskManager.Task::(prepare) Task=`9e874973-2d47-4bc1-bc48-87e2eb16d61b`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00149202346802', 'lastCheck': 1346050348.917232, 'code': 0, 'valid': True}}
>Thread-122::DEBUG::2012-08-27 14:52:29,012::task::588::TaskManager.Task::(_updateState) Task=`9e874973-2d47-4bc1-bc48-87e2eb16d61b`::moving from state preparing -> state finished
>Thread-122::DEBUG::2012-08-27 14:52:29,012::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-122::DEBUG::2012-08-27 14:52:29,013::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-122::DEBUG::2012-08-27 14:52:29,013::task::978::TaskManager.Task::(_decref) Task=`9e874973-2d47-4bc1-bc48-87e2eb16d61b`::ref 0 aborting False
>Thread-123::DEBUG::2012-08-27 14:52:31,614::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-123::DEBUG::2012-08-27 14:52:31,614::task::588::TaskManager.Task::(_updateState) Task=`5938ce11-a8d5-4238-9b75-a6a055c16728`::moving from state init -> state preparing
>Thread-123::INFO::2012-08-27 14:52:31,615::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-123::INFO::2012-08-27 14:52:31,615::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-123::DEBUG::2012-08-27 14:52:31,615::task::1172::TaskManager.Task::(prepare) Task=`5938ce11-a8d5-4238-9b75-a6a055c16728`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-123::DEBUG::2012-08-27 14:52:31,615::task::588::TaskManager.Task::(_updateState) Task=`5938ce11-a8d5-4238-9b75-a6a055c16728`::moving from state preparing -> state finished
>Thread-123::DEBUG::2012-08-27 14:52:31,616::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-123::DEBUG::2012-08-27 14:52:31,616::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-123::DEBUG::2012-08-27 14:52:31,616::task::978::TaskManager.Task::(_decref) Task=`5938ce11-a8d5-4238-9b75-a6a055c16728`::ref 0 aborting False
>Thread-125::DEBUG::2012-08-27 14:52:34,954::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-125::DEBUG::2012-08-27 14:52:34,955::task::588::TaskManager.Task::(_updateState) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::moving from state init -> state preparing
>Thread-125::INFO::2012-08-27 14:52:34,955::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-125::DEBUG::2012-08-27 14:52:34,955::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`9212d1d9-d554-4547-a51b-227e7d83ef8a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-125::DEBUG::2012-08-27 14:52:34,955::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-125::DEBUG::2012-08-27 14:52:34,956::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-125::DEBUG::2012-08-27 14:52:34,956::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`9212d1d9-d554-4547-a51b-227e7d83ef8a`::Granted request
>Thread-125::DEBUG::2012-08-27 14:52:34,956::task::817::TaskManager.Task::(resourceAcquired) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-125::DEBUG::2012-08-27 14:52:34,956::task::978::TaskManager.Task::(_decref) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::ref 1 aborting False
>Thread-125::INFO::2012-08-27 14:52:34,959::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-125::DEBUG::2012-08-27 14:52:34,959::task::1172::TaskManager.Task::(prepare) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-125::DEBUG::2012-08-27 14:52:34,960::task::588::TaskManager.Task::(_updateState) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::moving from state preparing -> state finished
>Thread-125::DEBUG::2012-08-27 14:52:34,960::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-125::DEBUG::2012-08-27 14:52:34,960::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-125::DEBUG::2012-08-27 14:52:34,960::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-125::DEBUG::2012-08-27 14:52:34,961::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-125::DEBUG::2012-08-27 14:52:34,961::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-125::DEBUG::2012-08-27 14:52:34,961::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-125::DEBUG::2012-08-27 14:52:34,961::task::978::TaskManager.Task::(_decref) Task=`d13491d5-d14b-46dd-ace1-71ff29f4fe46`::ref 0 aborting False
>Thread-128::DEBUG::2012-08-27 14:52:48,282::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-128::DEBUG::2012-08-27 14:52:48,283::task::588::TaskManager.Task::(_updateState) Task=`d124ecbf-2163-48ce-b9d7-6da0038395ab`::moving from state init -> state preparing
>Thread-128::INFO::2012-08-27 14:52:48,284::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-128::INFO::2012-08-27 14:52:48,284::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-128::DEBUG::2012-08-27 14:52:48,284::task::1172::TaskManager.Task::(prepare) Task=`d124ecbf-2163-48ce-b9d7-6da0038395ab`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-128::DEBUG::2012-08-27 14:52:48,284::task::588::TaskManager.Task::(_updateState) Task=`d124ecbf-2163-48ce-b9d7-6da0038395ab`::moving from state preparing -> state finished
>Thread-128::DEBUG::2012-08-27 14:52:48,285::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-128::DEBUG::2012-08-27 14:52:48,285::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-128::DEBUG::2012-08-27 14:52:48,285::task::978::TaskManager.Task::(_decref) Task=`d124ecbf-2163-48ce-b9d7-6da0038395ab`::ref 0 aborting False
>Thread-130::DEBUG::2012-08-27 14:52:51,571::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-130::DEBUG::2012-08-27 14:52:51,571::task::588::TaskManager.Task::(_updateState) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::moving from state init -> state preparing
>Thread-130::INFO::2012-08-27 14:52:51,571::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-130::DEBUG::2012-08-27 14:52:51,572::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`668c3916-eecd-421e-a9f9-06621fad5944`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-130::DEBUG::2012-08-27 14:52:51,572::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-130::DEBUG::2012-08-27 14:52:51,572::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-130::DEBUG::2012-08-27 14:52:51,572::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`668c3916-eecd-421e-a9f9-06621fad5944`::Granted request
>Thread-130::DEBUG::2012-08-27 14:52:51,573::task::817::TaskManager.Task::(resourceAcquired) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-130::DEBUG::2012-08-27 14:52:51,573::task::978::TaskManager.Task::(_decref) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::ref 1 aborting False
>Thread-130::INFO::2012-08-27 14:52:51,576::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-130::DEBUG::2012-08-27 14:52:51,576::task::1172::TaskManager.Task::(prepare) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-130::DEBUG::2012-08-27 14:52:51,576::task::588::TaskManager.Task::(_updateState) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::moving from state preparing -> state finished
>Thread-130::DEBUG::2012-08-27 14:52:51,577::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-130::DEBUG::2012-08-27 14:52:51,577::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-130::DEBUG::2012-08-27 14:52:51,577::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-130::DEBUG::2012-08-27 14:52:51,577::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-130::DEBUG::2012-08-27 14:52:51,578::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-130::DEBUG::2012-08-27 14:52:51,578::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-130::DEBUG::2012-08-27 14:52:51,578::task::978::TaskManager.Task::(_decref) Task=`6691e38f-983d-469b-b64c-614f01d6f635`::ref 0 aborting False
>Thread-132::DEBUG::2012-08-27 14:52:58,613::task::588::TaskManager.Task::(_updateState) Task=`dcb04b47-149e-403b-be7e-16757da44358`::moving from state init -> state preparing
>Thread-132::INFO::2012-08-27 14:52:58,613::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-132::INFO::2012-08-27 14:52:58,614::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00213718414307', 'lastCheck': 1346050368.93169, 'code': 0, 'valid': True}}
>Thread-132::DEBUG::2012-08-27 14:52:58,614::task::1172::TaskManager.Task::(prepare) Task=`dcb04b47-149e-403b-be7e-16757da44358`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00213718414307', 'lastCheck': 1346050368.93169, 'code': 0, 'valid': True}}
>Thread-132::DEBUG::2012-08-27 14:52:58,614::task::588::TaskManager.Task::(_updateState) Task=`dcb04b47-149e-403b-be7e-16757da44358`::moving from state preparing -> state finished
>Thread-132::DEBUG::2012-08-27 14:52:58,614::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-132::DEBUG::2012-08-27 14:52:58,614::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-132::DEBUG::2012-08-27 14:52:58,615::task::978::TaskManager.Task::(_decref) Task=`dcb04b47-149e-403b-be7e-16757da44358`::ref 0 aborting False
>Thread-134::DEBUG::2012-08-27 14:53:04,814::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-134::DEBUG::2012-08-27 14:53:04,814::task::588::TaskManager.Task::(_updateState) Task=`2c761fa5-daad-46e6-bf83-b75cb5c866b0`::moving from state init -> state preparing
>Thread-134::INFO::2012-08-27 14:53:04,814::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-134::INFO::2012-08-27 14:53:04,815::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-134::DEBUG::2012-08-27 14:53:04,815::task::1172::TaskManager.Task::(prepare) Task=`2c761fa5-daad-46e6-bf83-b75cb5c866b0`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-134::DEBUG::2012-08-27 14:53:04,815::task::588::TaskManager.Task::(_updateState) Task=`2c761fa5-daad-46e6-bf83-b75cb5c866b0`::moving from state preparing -> state finished
>Thread-134::DEBUG::2012-08-27 14:53:04,815::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-134::DEBUG::2012-08-27 14:53:04,815::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-134::DEBUG::2012-08-27 14:53:04,816::task::978::TaskManager.Task::(_decref) Task=`2c761fa5-daad-46e6-bf83-b75cb5c866b0`::ref 0 aborting False
>Thread-136::DEBUG::2012-08-27 14:53:08,077::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-136::DEBUG::2012-08-27 14:53:08,077::task::588::TaskManager.Task::(_updateState) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::moving from state init -> state preparing
>Thread-136::INFO::2012-08-27 14:53:08,077::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-136::DEBUG::2012-08-27 14:53:08,078::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`f2c3c06f-44c7-4941-8124-118cc5808133`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-136::DEBUG::2012-08-27 14:53:08,078::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-136::DEBUG::2012-08-27 14:53:08,078::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-136::DEBUG::2012-08-27 14:53:08,078::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`f2c3c06f-44c7-4941-8124-118cc5808133`::Granted request
>Thread-136::DEBUG::2012-08-27 14:53:08,079::task::817::TaskManager.Task::(resourceAcquired) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-136::DEBUG::2012-08-27 14:53:08,079::task::978::TaskManager.Task::(_decref) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::ref 1 aborting False
>Thread-136::INFO::2012-08-27 14:53:08,082::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-136::DEBUG::2012-08-27 14:53:08,082::task::1172::TaskManager.Task::(prepare) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-136::DEBUG::2012-08-27 14:53:08,082::task::588::TaskManager.Task::(_updateState) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::moving from state preparing -> state finished
>Thread-136::DEBUG::2012-08-27 14:53:08,082::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-136::DEBUG::2012-08-27 14:53:08,083::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-136::DEBUG::2012-08-27 14:53:08,083::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-136::DEBUG::2012-08-27 14:53:08,083::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-136::DEBUG::2012-08-27 14:53:08,083::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-136::DEBUG::2012-08-27 14:53:08,083::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-136::DEBUG::2012-08-27 14:53:08,084::task::978::TaskManager.Task::(_decref) Task=`681feeb1-5dd5-4eaf-9453-60ebd9ac608d`::ref 0 aborting False
>Thread-23::DEBUG::2012-08-27 14:53:18,946::domainMonitor::125::Storage.DomainMonitor::(_monitorDomain) Refreshing domain 9bd82898-9672-4cc1-b7ad-ac722e00822b
>Thread-23::DEBUG::2012-08-27 14:53:18,947::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-23::DEBUG::2012-08-27 14:53:18,947::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 9bd82898-9672-4cc1-b7ad-ac722e00822b' (cwd None)
>Thread-23::DEBUG::2012-08-27 14:53:19,081::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "9bd82898-9672-4cc1-b7ad-ac722e00822b" not found\n'; <rc> = 5
>Thread-23::WARNING::2012-08-27 14:53:19,082::lvm::356::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "9bd82898-9672-4cc1-b7ad-ac722e00822b" not found']
>Thread-23::DEBUG::2012-08-27 14:53:19,082::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-23::DEBUG::2012-08-27 14:53:19,088::fileSD::105::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.66.6.217:_home_nfs_rhevm/9bd82898-9672-4cc1-b7ad-ac722e00822b
>Thread-23::DEBUG::2012-08-27 14:53:19,088::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-23::DEBUG::2012-08-27 14:53:19,090::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=217', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=whuang', 'POOL_DOMAINS=9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'POOL_SPM_ID=2', 'POOL_SPM_LVER=4', 'POOL_UUID=224281dd-7258-417c-a46e-dc025185e03e', 'REMOTE_PATH=10.66.6.217:/home/nfs/rhevm', 'ROLE=Master', 'SDUUID=9bd82898-9672-4cc1-b7ad-ac722e00822b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=7834f2aebf7f2847c1326ddba6d1a6c7c9f6ad76']
>Thread-23::DEBUG::2012-08-27 14:53:19,092::fileSD::389::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-23::WARNING::2012-08-27 14:53:19,092::sd::317::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9bd82898-9672-4cc1-b7ad-ac722e00822b_imageNS already registered
>Thread-23::WARNING::2012-08-27 14:53:19,092::sd::323::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9bd82898-9672-4cc1-b7ad-ac722e00822b_volumeNS already registered
>Thread-139::DEBUG::2012-08-27 14:53:21,326::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-139::DEBUG::2012-08-27 14:53:21,327::task::588::TaskManager.Task::(_updateState) Task=`da5b527c-1665-4cc5-9371-d7f7bab8422c`::moving from state init -> state preparing
>Thread-139::INFO::2012-08-27 14:53:21,327::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-139::INFO::2012-08-27 14:53:21,328::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-139::DEBUG::2012-08-27 14:53:21,328::task::1172::TaskManager.Task::(prepare) Task=`da5b527c-1665-4cc5-9371-d7f7bab8422c`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-139::DEBUG::2012-08-27 14:53:21,328::task::588::TaskManager.Task::(_updateState) Task=`da5b527c-1665-4cc5-9371-d7f7bab8422c`::moving from state preparing -> state finished
>Thread-139::DEBUG::2012-08-27 14:53:21,328::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-139::DEBUG::2012-08-27 14:53:21,328::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-139::DEBUG::2012-08-27 14:53:21,329::task::978::TaskManager.Task::(_decref) Task=`da5b527c-1665-4cc5-9371-d7f7bab8422c`::ref 0 aborting False
>Thread-146::DEBUG::2012-08-27 14:53:24,648::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-146::DEBUG::2012-08-27 14:53:24,649::task::588::TaskManager.Task::(_updateState) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::moving from state init -> state preparing
>Thread-146::INFO::2012-08-27 14:53:24,649::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-146::DEBUG::2012-08-27 14:53:24,650::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`52286914-1706-4830-9c0d-ce84f7b77ca0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-146::DEBUG::2012-08-27 14:53:24,650::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-146::DEBUG::2012-08-27 14:53:24,650::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-146::DEBUG::2012-08-27 14:53:24,650::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`52286914-1706-4830-9c0d-ce84f7b77ca0`::Granted request
>Thread-146::DEBUG::2012-08-27 14:53:24,651::task::817::TaskManager.Task::(resourceAcquired) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-146::DEBUG::2012-08-27 14:53:24,651::task::978::TaskManager.Task::(_decref) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::ref 1 aborting False
>Thread-146::INFO::2012-08-27 14:53:24,654::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-146::DEBUG::2012-08-27 14:53:24,654::task::1172::TaskManager.Task::(prepare) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-146::DEBUG::2012-08-27 14:53:24,654::task::588::TaskManager.Task::(_updateState) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::moving from state preparing -> state finished
>Thread-146::DEBUG::2012-08-27 14:53:24,654::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-146::DEBUG::2012-08-27 14:53:24,655::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-146::DEBUG::2012-08-27 14:53:24,655::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-146::DEBUG::2012-08-27 14:53:24,655::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-146::DEBUG::2012-08-27 14:53:24,655::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-146::DEBUG::2012-08-27 14:53:24,655::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-146::DEBUG::2012-08-27 14:53:24,656::task::978::TaskManager.Task::(_decref) Task=`34dfd589-8e96-4ed9-b74a-8492c436ebd2`::ref 0 aborting False
>Thread-147::DEBUG::2012-08-27 14:53:27,362::task::588::TaskManager.Task::(_updateState) Task=`91a19796-de71-48e0-b592-3e4cff4ba01a`::moving from state init -> state preparing
>Thread-147::INFO::2012-08-27 14:53:27,362::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-147::INFO::2012-08-27 14:53:27,363::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00146102905273', 'lastCheck': 1346050399.0985639, 'code': 0, 'valid': True}}
>Thread-147::DEBUG::2012-08-27 14:53:27,363::task::1172::TaskManager.Task::(prepare) Task=`91a19796-de71-48e0-b592-3e4cff4ba01a`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00146102905273', 'lastCheck': 1346050399.0985639, 'code': 0, 'valid': True}}
>Thread-147::DEBUG::2012-08-27 14:53:27,363::task::588::TaskManager.Task::(_updateState) Task=`91a19796-de71-48e0-b592-3e4cff4ba01a`::moving from state preparing -> state finished
>Thread-147::DEBUG::2012-08-27 14:53:27,363::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-147::DEBUG::2012-08-27 14:53:27,363::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-147::DEBUG::2012-08-27 14:53:27,364::task::978::TaskManager.Task::(_decref) Task=`91a19796-de71-48e0-b592-3e4cff4ba01a`::ref 0 aborting False
>Thread-150::DEBUG::2012-08-27 14:53:37,497::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-150::DEBUG::2012-08-27 14:53:37,497::task::588::TaskManager.Task::(_updateState) Task=`7ba56c76-3fe3-4b9a-8229-807936f21a2b`::moving from state init -> state preparing
>Thread-150::INFO::2012-08-27 14:53:37,497::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-150::INFO::2012-08-27 14:53:37,498::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-150::DEBUG::2012-08-27 14:53:37,498::task::1172::TaskManager.Task::(prepare) Task=`7ba56c76-3fe3-4b9a-8229-807936f21a2b`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-150::DEBUG::2012-08-27 14:53:37,498::task::588::TaskManager.Task::(_updateState) Task=`7ba56c76-3fe3-4b9a-8229-807936f21a2b`::moving from state preparing -> state finished
>Thread-150::DEBUG::2012-08-27 14:53:37,498::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-150::DEBUG::2012-08-27 14:53:37,499::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-150::DEBUG::2012-08-27 14:53:37,499::task::978::TaskManager.Task::(_decref) Task=`7ba56c76-3fe3-4b9a-8229-807936f21a2b`::ref 0 aborting False
>Thread-151::DEBUG::2012-08-27 14:53:40,720::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-151::DEBUG::2012-08-27 14:53:40,721::task::588::TaskManager.Task::(_updateState) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::moving from state init -> state preparing
>Thread-151::INFO::2012-08-27 14:53:40,721::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-151::DEBUG::2012-08-27 14:53:40,721::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`bac81a4a-36ff-4542-944c-99ffbc70da77`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-151::DEBUG::2012-08-27 14:53:40,722::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-151::DEBUG::2012-08-27 14:53:40,722::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-151::DEBUG::2012-08-27 14:53:40,722::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`bac81a4a-36ff-4542-944c-99ffbc70da77`::Granted request
>Thread-151::DEBUG::2012-08-27 14:53:40,722::task::817::TaskManager.Task::(resourceAcquired) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-151::DEBUG::2012-08-27 14:53:40,723::task::978::TaskManager.Task::(_decref) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::ref 1 aborting False
>Thread-151::INFO::2012-08-27 14:53:40,726::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-151::DEBUG::2012-08-27 14:53:40,726::task::1172::TaskManager.Task::(prepare) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-151::DEBUG::2012-08-27 14:53:40,727::task::588::TaskManager.Task::(_updateState) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::moving from state preparing -> state finished
>Thread-151::DEBUG::2012-08-27 14:53:40,727::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-151::DEBUG::2012-08-27 14:53:40,727::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-151::DEBUG::2012-08-27 14:53:40,727::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-151::DEBUG::2012-08-27 14:53:40,728::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-151::DEBUG::2012-08-27 14:53:40,728::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-151::DEBUG::2012-08-27 14:53:40,728::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-151::DEBUG::2012-08-27 14:53:40,728::task::978::TaskManager.Task::(_decref) Task=`103a4d88-6711-4bf0-8805-ee32a5c9ce24`::ref 0 aborting False
>Thread-155::DEBUG::2012-08-27 14:53:54,165::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-155::DEBUG::2012-08-27 14:53:54,165::task::588::TaskManager.Task::(_updateState) Task=`9915150c-87da-480e-90bc-a427e48f1e7d`::moving from state init -> state preparing
>Thread-155::INFO::2012-08-27 14:53:54,166::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-155::INFO::2012-08-27 14:53:54,166::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-155::DEBUG::2012-08-27 14:53:54,166::task::1172::TaskManager.Task::(prepare) Task=`9915150c-87da-480e-90bc-a427e48f1e7d`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-155::DEBUG::2012-08-27 14:53:54,166::task::588::TaskManager.Task::(_updateState) Task=`9915150c-87da-480e-90bc-a427e48f1e7d`::moving from state preparing -> state finished
>Thread-155::DEBUG::2012-08-27 14:53:54,167::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-155::DEBUG::2012-08-27 14:53:54,167::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-155::DEBUG::2012-08-27 14:53:54,167::task::978::TaskManager.Task::(_decref) Task=`9915150c-87da-480e-90bc-a427e48f1e7d`::ref 0 aborting False
>Thread-156::DEBUG::2012-08-27 14:53:56,711::task::588::TaskManager.Task::(_updateState) Task=`778745c0-0e9e-4b8b-8198-a98a3d9e5011`::moving from state init -> state preparing
>Thread-156::INFO::2012-08-27 14:53:56,712::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-156::INFO::2012-08-27 14:53:56,712::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00150203704834', 'lastCheck': 1346050429.1178889, 'code': 0, 'valid': True}}
>Thread-156::DEBUG::2012-08-27 14:53:56,712::task::1172::TaskManager.Task::(prepare) Task=`778745c0-0e9e-4b8b-8198-a98a3d9e5011`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00150203704834', 'lastCheck': 1346050429.1178889, 'code': 0, 'valid': True}}
>Thread-156::DEBUG::2012-08-27 14:53:56,712::task::588::TaskManager.Task::(_updateState) Task=`778745c0-0e9e-4b8b-8198-a98a3d9e5011`::moving from state preparing -> state finished
>Thread-156::DEBUG::2012-08-27 14:53:56,712::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-156::DEBUG::2012-08-27 14:53:56,713::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-156::DEBUG::2012-08-27 14:53:56,713::task::978::TaskManager.Task::(_decref) Task=`778745c0-0e9e-4b8b-8198-a98a3d9e5011`::ref 0 aborting False
>Thread-157::DEBUG::2012-08-27 14:53:57,564::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-157::DEBUG::2012-08-27 14:53:57,564::task::588::TaskManager.Task::(_updateState) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::moving from state init -> state preparing
>Thread-157::INFO::2012-08-27 14:53:57,565::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-157::DEBUG::2012-08-27 14:53:57,565::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`230ab067-2acf-4a0b-9e6a-3334c75bd7f0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-157::DEBUG::2012-08-27 14:53:57,565::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-157::DEBUG::2012-08-27 14:53:57,565::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-157::DEBUG::2012-08-27 14:53:57,566::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`230ab067-2acf-4a0b-9e6a-3334c75bd7f0`::Granted request
>Thread-157::DEBUG::2012-08-27 14:53:57,566::task::817::TaskManager.Task::(resourceAcquired) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-157::DEBUG::2012-08-27 14:53:57,566::task::978::TaskManager.Task::(_decref) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::ref 1 aborting False
>Thread-157::INFO::2012-08-27 14:53:57,569::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-157::DEBUG::2012-08-27 14:53:57,569::task::1172::TaskManager.Task::(prepare) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-157::DEBUG::2012-08-27 14:53:57,570::task::588::TaskManager.Task::(_updateState) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::moving from state preparing -> state finished
>Thread-157::DEBUG::2012-08-27 14:53:57,570::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-157::DEBUG::2012-08-27 14:53:57,570::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-157::DEBUG::2012-08-27 14:53:57,570::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-157::DEBUG::2012-08-27 14:53:57,571::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-157::DEBUG::2012-08-27 14:53:57,571::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-157::DEBUG::2012-08-27 14:53:57,571::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-157::DEBUG::2012-08-27 14:53:57,571::task::978::TaskManager.Task::(_decref) Task=`3e097039-16fa-45fc-b5e1-89b219ce0fa3`::ref 0 aborting False
>Thread-161::DEBUG::2012-08-27 14:54:10,412::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-161::DEBUG::2012-08-27 14:54:10,413::task::588::TaskManager.Task::(_updateState) Task=`39180d9c-f200-48a3-999d-3512187a9112`::moving from state init -> state preparing
>Thread-161::INFO::2012-08-27 14:54:10,413::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-161::INFO::2012-08-27 14:54:10,414::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-161::DEBUG::2012-08-27 14:54:10,414::task::1172::TaskManager.Task::(prepare) Task=`39180d9c-f200-48a3-999d-3512187a9112`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-161::DEBUG::2012-08-27 14:54:10,414::task::588::TaskManager.Task::(_updateState) Task=`39180d9c-f200-48a3-999d-3512187a9112`::moving from state preparing -> state finished
>Thread-161::DEBUG::2012-08-27 14:54:10,414::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-161::DEBUG::2012-08-27 14:54:10,414::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-161::DEBUG::2012-08-27 14:54:10,415::task::978::TaskManager.Task::(_decref) Task=`39180d9c-f200-48a3-999d-3512187a9112`::ref 0 aborting False
>Thread-162::DEBUG::2012-08-27 14:54:13,618::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-162::DEBUG::2012-08-27 14:54:13,619::task::588::TaskManager.Task::(_updateState) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::moving from state init -> state preparing
>Thread-162::INFO::2012-08-27 14:54:13,619::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-162::DEBUG::2012-08-27 14:54:13,620::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`a0c5b381-3643-4662-aba8-1161c3d13197`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-162::DEBUG::2012-08-27 14:54:13,620::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-162::DEBUG::2012-08-27 14:54:13,620::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-162::DEBUG::2012-08-27 14:54:13,620::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`a0c5b381-3643-4662-aba8-1161c3d13197`::Granted request
>Thread-162::DEBUG::2012-08-27 14:54:13,621::task::817::TaskManager.Task::(resourceAcquired) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-162::DEBUG::2012-08-27 14:54:13,621::task::978::TaskManager.Task::(_decref) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::ref 1 aborting False
>Thread-162::INFO::2012-08-27 14:54:13,624::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-162::DEBUG::2012-08-27 14:54:13,624::task::1172::TaskManager.Task::(prepare) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-162::DEBUG::2012-08-27 14:54:13,624::task::588::TaskManager.Task::(_updateState) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::moving from state preparing -> state finished
>Thread-162::DEBUG::2012-08-27 14:54:13,624::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-162::DEBUG::2012-08-27 14:54:13,625::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-162::DEBUG::2012-08-27 14:54:13,625::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-162::DEBUG::2012-08-27 14:54:13,625::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-162::DEBUG::2012-08-27 14:54:13,625::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-162::DEBUG::2012-08-27 14:54:13,625::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-162::DEBUG::2012-08-27 14:54:13,626::task::978::TaskManager.Task::(_decref) Task=`47db8405-287f-4717-aee2-e2ed1abcf7fb`::ref 0 aborting False
>Thread-165::DEBUG::2012-08-27 14:54:25,281::task::588::TaskManager.Task::(_updateState) Task=`533bf649-b2a4-4286-8bb1-667b5b45ae0c`::moving from state init -> state preparing
>Thread-165::INFO::2012-08-27 14:54:25,281::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-165::INFO::2012-08-27 14:54:25,281::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00201606750488', 'lastCheck': 1346050459.137032, 'code': 0, 'valid': True}}
>Thread-165::DEBUG::2012-08-27 14:54:25,281::task::1172::TaskManager.Task::(prepare) Task=`533bf649-b2a4-4286-8bb1-667b5b45ae0c`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00201606750488', 'lastCheck': 1346050459.137032, 'code': 0, 'valid': True}}
>Thread-165::DEBUG::2012-08-27 14:54:25,282::task::588::TaskManager.Task::(_updateState) Task=`533bf649-b2a4-4286-8bb1-667b5b45ae0c`::moving from state preparing -> state finished
>Thread-165::DEBUG::2012-08-27 14:54:25,282::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-165::DEBUG::2012-08-27 14:54:25,282::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-165::DEBUG::2012-08-27 14:54:25,282::task::978::TaskManager.Task::(_decref) Task=`533bf649-b2a4-4286-8bb1-667b5b45ae0c`::ref 0 aborting False
>Thread-166::DEBUG::2012-08-27 14:54:26,928::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-166::DEBUG::2012-08-27 14:54:26,928::task::588::TaskManager.Task::(_updateState) Task=`ad859c73-a462-4771-a902-62b5b857c150`::moving from state init -> state preparing
>Thread-166::INFO::2012-08-27 14:54:26,929::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-166::INFO::2012-08-27 14:54:26,929::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-166::DEBUG::2012-08-27 14:54:26,929::task::1172::TaskManager.Task::(prepare) Task=`ad859c73-a462-4771-a902-62b5b857c150`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-166::DEBUG::2012-08-27 14:54:26,929::task::588::TaskManager.Task::(_updateState) Task=`ad859c73-a462-4771-a902-62b5b857c150`::moving from state preparing -> state finished
>Thread-166::DEBUG::2012-08-27 14:54:26,929::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-166::DEBUG::2012-08-27 14:54:26,930::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-166::DEBUG::2012-08-27 14:54:26,930::task::978::TaskManager.Task::(_decref) Task=`ad859c73-a462-4771-a902-62b5b857c150`::ref 0 aborting False
>Thread-168::DEBUG::2012-08-27 14:54:30,427::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-168::DEBUG::2012-08-27 14:54:30,427::task::588::TaskManager.Task::(_updateState) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::moving from state init -> state preparing
>Thread-168::INFO::2012-08-27 14:54:30,427::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-168::DEBUG::2012-08-27 14:54:30,428::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`726e8ffb-0e98-4668-a2ff-15216a82cdd4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-168::DEBUG::2012-08-27 14:54:30,428::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-168::DEBUG::2012-08-27 14:54:30,428::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-168::DEBUG::2012-08-27 14:54:30,429::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`726e8ffb-0e98-4668-a2ff-15216a82cdd4`::Granted request
>Thread-168::DEBUG::2012-08-27 14:54:30,429::task::817::TaskManager.Task::(resourceAcquired) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-168::DEBUG::2012-08-27 14:54:30,429::task::978::TaskManager.Task::(_decref) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::ref 1 aborting False
>Thread-168::INFO::2012-08-27 14:54:30,432::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-168::DEBUG::2012-08-27 14:54:30,432::task::1172::TaskManager.Task::(prepare) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-168::DEBUG::2012-08-27 14:54:30,432::task::588::TaskManager.Task::(_updateState) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::moving from state preparing -> state finished
>Thread-168::DEBUG::2012-08-27 14:54:30,433::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-168::DEBUG::2012-08-27 14:54:30,433::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-168::DEBUG::2012-08-27 14:54:30,433::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-168::DEBUG::2012-08-27 14:54:30,433::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-168::DEBUG::2012-08-27 14:54:30,433::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-168::DEBUG::2012-08-27 14:54:30,434::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-168::DEBUG::2012-08-27 14:54:30,434::task::978::TaskManager.Task::(_decref) Task=`63c3642a-042f-40f4-8856-41a806a36ee5`::ref 0 aborting False
>Thread-171::DEBUG::2012-08-27 14:54:46,097::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-171::DEBUG::2012-08-27 14:54:46,098::task::588::TaskManager.Task::(_updateState) Task=`8a14d38c-7013-4e3c-92c4-f816acdb0511`::moving from state init -> state preparing
>Thread-171::INFO::2012-08-27 14:54:46,098::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-171::INFO::2012-08-27 14:54:46,098::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-171::DEBUG::2012-08-27 14:54:46,099::task::1172::TaskManager.Task::(prepare) Task=`8a14d38c-7013-4e3c-92c4-f816acdb0511`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-171::DEBUG::2012-08-27 14:54:46,099::task::588::TaskManager.Task::(_updateState) Task=`8a14d38c-7013-4e3c-92c4-f816acdb0511`::moving from state preparing -> state finished
>Thread-171::DEBUG::2012-08-27 14:54:46,099::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-171::DEBUG::2012-08-27 14:54:46,099::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-171::DEBUG::2012-08-27 14:54:46,100::task::978::TaskManager.Task::(_decref) Task=`8a14d38c-7013-4e3c-92c4-f816acdb0511`::ref 0 aborting False
>Thread-173::DEBUG::2012-08-27 14:54:49,380::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-173::DEBUG::2012-08-27 14:54:49,381::task::588::TaskManager.Task::(_updateState) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::moving from state init -> state preparing
>Thread-173::INFO::2012-08-27 14:54:49,381::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-173::DEBUG::2012-08-27 14:54:49,382::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`c3e9cbc2-8e71-4b4e-8d1e-4d4e804bbc26`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-173::DEBUG::2012-08-27 14:54:49,382::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-173::DEBUG::2012-08-27 14:54:49,382::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-173::DEBUG::2012-08-27 14:54:49,382::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`c3e9cbc2-8e71-4b4e-8d1e-4d4e804bbc26`::Granted request
>Thread-173::DEBUG::2012-08-27 14:54:49,383::task::817::TaskManager.Task::(resourceAcquired) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-173::DEBUG::2012-08-27 14:54:49,383::task::978::TaskManager.Task::(_decref) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::ref 1 aborting False
>Thread-173::INFO::2012-08-27 14:54:49,386::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-173::DEBUG::2012-08-27 14:54:49,386::task::1172::TaskManager.Task::(prepare) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-173::DEBUG::2012-08-27 14:54:49,386::task::588::TaskManager.Task::(_updateState) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::moving from state preparing -> state finished
>Thread-173::DEBUG::2012-08-27 14:54:49,386::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-173::DEBUG::2012-08-27 14:54:49,387::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-173::DEBUG::2012-08-27 14:54:49,387::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-173::DEBUG::2012-08-27 14:54:49,387::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-173::DEBUG::2012-08-27 14:54:49,387::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-173::DEBUG::2012-08-27 14:54:49,387::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-173::DEBUG::2012-08-27 14:54:49,388::task::978::TaskManager.Task::(_decref) Task=`81cfd4b6-ac1c-4f90-8440-916066131f38`::ref 0 aborting False
>Thread-175::DEBUG::2012-08-27 14:54:57,043::task::588::TaskManager.Task::(_updateState) Task=`b59fc677-f294-422a-92ae-9d618b079a00`::moving from state init -> state preparing
>Thread-175::INFO::2012-08-27 14:54:57,044::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-175::INFO::2012-08-27 14:54:57,044::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00166296958923', 'lastCheck': 1346050489.1565659, 'code': 0, 'valid': True}}
>Thread-175::DEBUG::2012-08-27 14:54:57,044::task::1172::TaskManager.Task::(prepare) Task=`b59fc677-f294-422a-92ae-9d618b079a00`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00166296958923', 'lastCheck': 1346050489.1565659, 'code': 0, 'valid': True}}
>Thread-175::DEBUG::2012-08-27 14:54:57,045::task::588::TaskManager.Task::(_updateState) Task=`b59fc677-f294-422a-92ae-9d618b079a00`::moving from state preparing -> state finished
>Thread-175::DEBUG::2012-08-27 14:54:57,045::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-175::DEBUG::2012-08-27 14:54:57,045::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-175::DEBUG::2012-08-27 14:54:57,045::task::978::TaskManager.Task::(_decref) Task=`b59fc677-f294-422a-92ae-9d618b079a00`::ref 0 aborting False
>Thread-177::DEBUG::2012-08-27 14:55:03,101::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-177::DEBUG::2012-08-27 14:55:03,101::task::588::TaskManager.Task::(_updateState) Task=`218ef21c-3e29-49d5-bbb3-982b31ad6dd6`::moving from state init -> state preparing
>Thread-177::INFO::2012-08-27 14:55:03,101::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-177::INFO::2012-08-27 14:55:03,102::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-177::DEBUG::2012-08-27 14:55:03,102::task::1172::TaskManager.Task::(prepare) Task=`218ef21c-3e29-49d5-bbb3-982b31ad6dd6`::finished: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 4}}
>Thread-177::DEBUG::2012-08-27 14:55:03,102::task::588::TaskManager.Task::(_updateState) Task=`218ef21c-3e29-49d5-bbb3-982b31ad6dd6`::moving from state preparing -> state finished
>Thread-177::DEBUG::2012-08-27 14:55:03,102::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-177::DEBUG::2012-08-27 14:55:03,103::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-177::DEBUG::2012-08-27 14:55:03,103::task::978::TaskManager.Task::(_decref) Task=`218ef21c-3e29-49d5-bbb3-982b31ad6dd6`::ref 0 aborting False
>Thread-179::DEBUG::2012-08-27 14:55:06,372::BindingXMLRPC::164::vds::(wrapper) [10.66.5.12]
>Thread-179::DEBUG::2012-08-27 14:55:06,372::task::588::TaskManager.Task::(_updateState) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::moving from state init -> state preparing
>Thread-179::INFO::2012-08-27 14:55:06,372::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='224281dd-7258-417c-a46e-dc025185e03e', options=None)
>Thread-179::DEBUG::2012-08-27 14:55:06,373::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`6823a6b0-4c81-4575-a046-a7824cff6a3f`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-179::DEBUG::2012-08-27 14:55:06,373::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' for lock type 'shared'
>Thread-179::DEBUG::2012-08-27 14:55:06,373::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free. Now locking as 'shared' (1 active user)
>Thread-179::DEBUG::2012-08-27 14:55:06,373::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.224281dd-7258-417c-a46e-dc025185e03e`ReqID=`6823a6b0-4c81-4575-a046-a7824cff6a3f`::Granted request
>Thread-179::DEBUG::2012-08-27 14:55:06,374::task::817::TaskManager.Task::(resourceAcquired) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::_resourcesAcquired: Storage.224281dd-7258-417c-a46e-dc025185e03e (shared)
>Thread-179::DEBUG::2012-08-27 14:55:06,374::task::978::TaskManager.Task::(_decref) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::ref 1 aborting False
>Thread-179::INFO::2012-08-27 14:55:06,377::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-179::DEBUG::2012-08-27 14:55:06,377::task::1172::TaskManager.Task::(prepare) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::finished: {'info': {'spm_id': 2, 'master_uuid': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'name': 'whuang', 'version': '3', 'domains': '9bd82898-9672-4cc1-b7ad-ac722e00822b:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 4}, 'dominfo': {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'status': 'Active', 'diskfree': '454605930496', 'alerts': [], 'disktotal': '523730157568'}}}
>Thread-179::DEBUG::2012-08-27 14:55:06,377::task::588::TaskManager.Task::(_updateState) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::moving from state preparing -> state finished
>Thread-179::DEBUG::2012-08-27 14:55:06,377::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.224281dd-7258-417c-a46e-dc025185e03e': < ResourceRef 'Storage.224281dd-7258-417c-a46e-dc025185e03e', isValid: 'True' obj: 'None'>}
>Thread-179::DEBUG::2012-08-27 14:55:06,378::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-179::DEBUG::2012-08-27 14:55:06,378::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e'
>Thread-179::DEBUG::2012-08-27 14:55:06,378::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' (0 active users)
>Thread-179::DEBUG::2012-08-27 14:55:06,378::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e' is free, finding out if anyone is waiting for it.
>Thread-179::DEBUG::2012-08-27 14:55:06,379::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.224281dd-7258-417c-a46e-dc025185e03e', Clearing records.
>Thread-179::DEBUG::2012-08-27 14:55:06,379::task::978::TaskManager.Task::(_decref) Task=`d2566869-4240-4a86-bfe0-6bc20a9cf104`::ref 0 aborting False

Actions: View

Attachments on bug 851397: 606750 | 606751 | 607141 | 607142 | 607143 | 607144