Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 607141 Details for
Bug 851397
can not start guest in rhevm
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
vdsm.log
vdsm.log (text/plain), 112.51 KB, created by
EricLee
on 2012-08-27 07:11:45 UTC
(
hide
)
Description:
vdsm.log
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 851397
:
606750
|
606751
| 607141 |
607142
|
607143
|
607144