Attachment 602368 Details for Bug 844398 – vdsm.log referred in comment 13.

vdsm.log referred in comment 13.

vdsm.log (text/x-log), 158.33 KB, created by Eduardo Warszawski on 2012-08-05 16:38:01 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Eduardo Warszawski

Created: 2012-08-05 16:38:01 UTC

Size: 158.33 KB

patch

obsolete

>MainThread::INFO::2012-08-05 10:16:02,816::vdsm::71::vds::(run) I am the actual vdsm 4.10-0.239
>MainThread::DEBUG::2012-08-05 10:16:02,954::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2012-08-05 10:16:02,954::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::DEBUG::2012-08-05 10:16:03,002::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/kill -9 26300' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:03,016::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 26300: No such process\n'; <rc> = 1
>MainThread::DEBUG::2012-08-05 10:16:03,016::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
>MainThread::DEBUG::2012-08-05 10:16:03,017::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py d417eb4f-e870-4a33-8f17-ed694a0021d7 27038' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:03,135::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
>MainThread::DEBUG::2012-08-05 10:16:03,136::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
>MainThread::DEBUG::2012-08-05 10:16:03,136::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
>MainThread::DEBUG::2012-08-05 10:16:03,136::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
>MainThread::DEBUG::2012-08-05 10:16:03,136::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
>MainThread::DEBUG::2012-08-05 10:16:03,136::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
>MainThread::DEBUG::2012-08-05 10:16:03,137::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
>MainThread::DEBUG::2012-08-05 10:16:05,021::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2012-08-05 10:16:05,025::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
>MainThread::DEBUG::2012-08-05 10:16:05,025::multipath::106::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2012-08-05 10:16:05,026::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:05,109::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2012-08-05 10:16:05,109::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>MainThread::DEBUG::2012-08-05 10:16:05,111::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvs --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,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:05,192::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2012-08-05 10:16:05,192::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>MainThread::DEBUG::2012-08-05 10:16:05,193::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>MainThread::DEBUG::2012-08-05 10:16:05,193::__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' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:05,266::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>MainThread::DEBUG::2012-08-05 10:16:05,266::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>MainThread::DEBUG::2012-08-05 10:16:05,266::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm lvs --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,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:05,337::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:05,338::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2012-08-05 10:16:05,339::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>Thread-12::DEBUG::2012-08-05 10:16:05,339::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:05,340::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-12::DEBUG::2012-08-05 10:16:05,340::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:05,341::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>MainThread::DEBUG::2012-08-05 10:16:05,347::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:05,350::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-12::DEBUG::2012-08-05 10:16:05,350::misc::1071::SamplingMethod::(__call__) Returning last result
>MainThread::DEBUG::2012-08-05 10:16:05,358::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>MainThread::INFO::2012-08-05 10:16:05,359::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2012-08-05 10:16:05,359::vmChannels::127::vds::(run) Starting VM channels listener thread.
>MainThread::WARNING::2012-08-05 10:16:05,365::clientIF::169::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
>Thread-14::DEBUG::2012-08-05 10:16:05,933::BindingXMLRPC::872::vds::(wrapper) client [10.35.1.234]::call getCapabilities with () {}
>Thread-12::DEBUG::2012-08-05 10:16:05,983::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-14::DEBUG::2012-08-05 10:16:06,024::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
>Thread-14::DEBUG::2012-08-05 10:16:06,037::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2012-08-05 10:16:06,037::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
>Thread-14::DEBUG::2012-08-05 10:16:06,052::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2012-08-05 10:16:06,052::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:06,064::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:06,064::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,065::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-05 10:16:06,066::hsm::355::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>Thread-14::DEBUG::2012-08-05 10:16:06,068::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2012-08-05 10:16:06,068::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:06,075::hsm::387::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>Thread-12::DEBUG::2012-08-05 10:16:06,075::hsm::388::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_export1', '/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1']
>Thread-12::DEBUG::2012-08-05 10:16:06,075::hsm::390::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>Thread-12::DEBUG::2012-08-05 10:16:06,077::hsm::433::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>Thread-12::DEBUG::2012-08-05 10:16:06,077::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`8ee2c7a2-ace7-4694-b6b4-1cb0040d89a0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-12::DEBUG::2012-08-05 10:16:06,077::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'exclusive'
>Thread-12::DEBUG::2012-08-05 10:16:06,077::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'exclusive' (1 active user)
>Thread-12::DEBUG::2012-08-05 10:16:06,078::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`8ee2c7a2-ace7-4694-b6b4-1cb0040d89a0`::Granted request
>Thread-12::INFO::2012-08-05 10:16:06,078::sp::622::Storage.StoragePool::(connect) Connect host #1 to the storage pool 22c33e31-f5f8-49f7-afb7-309bafd407b2 with master domain: 1e49d867-4438-4484-a1ca-f6ab7013a319 (ver = 1)
>Thread-12::DEBUG::2012-08-05 10:16:06,078::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,078::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,078::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,079::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,079::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-14::DEBUG::2012-08-05 10:16:06,079::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:06,080::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-14::DEBUG::2012-08-05 10:16:06,080::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:06,080::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-12::DEBUG::2012-08-05 10:16:06,084::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:06,084::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-12::DEBUG::2012-08-05 10:16:06,084::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:06,084::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-14::DEBUG::2012-08-05 10:16:06,093::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:06,096::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-12::DEBUG::2012-08-05 10:16:06,096::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-14::DEBUG::2012-08-05 10:16:06,309::BindingXMLRPC::879::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff'}], 'FC': []}, 'packages2': {'kernel': {'release': '262.el6.x86_64', 'buildtime': 1333899480.0, 'version': '2.6.32'}, 'spice-server': {'release': '5.el6', 'buildtime': '1333631639', 'version': '0.10.1'}, 'vdsm': {'release': '0.239.gitf693264.el6', 'buildtime': '1343813065', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}, 'libvirt': {'release': '21.el6', 'buildtime': '1337779106', 'version': '0.9.10'}, 'qemu-img': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'interface': 'engine', 'gateway': '0.0.0.0', 'ports': []}, 'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'bridged': True, 'interface': 'ovirtmgmt', 'gateway': '10.35.1.254', 'ports': ['em1']}}, 'bridges': {'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'ports': ['em1']}, 'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': []}}, 'uuid': '4C4C4544-0043-5010-8038-CAC04F37354A_18:03:73:cb:c1:ce', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '18:03:73:CB:C1:CE', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'BRIDGE': 'ovirtmgmt'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '18:03:73:cb:c1:ce', 'speed': 1000}}, 'software_revision': '0.239', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,sse4_2,x2apic,popcnt,aes,xsave,avx,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_Penryn,model_Westmere,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff', 'netConfigDirty': 'False', 'memSize': '7750', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.10', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.3.0', u'pc', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '6.3.0.2.el6', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '0.0.0.0'}}
>Thread-15::DEBUG::2012-08-05 10:16:06,479::BindingXMLRPC::872::vds::(wrapper) client [10.35.1.234]::call getCapabilities with () {}
>Thread-15::DEBUG::2012-08-05 10:16:06,489::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
>Thread-15::DEBUG::2012-08-05 10:16:06,503::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2012-08-05 10:16:06,503::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
>Thread-15::DEBUG::2012-08-05 10:16:06,517::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2012-08-05 10:16:06,517::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
>Thread-15::DEBUG::2012-08-05 10:16:06,526::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2012-08-05 10:16:06,527::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
>Thread-15::DEBUG::2012-08-05 10:16:06,537::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2012-08-05 10:16:06,538::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
>Thread-15::DEBUG::2012-08-05 10:16:06,550::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2012-08-05 10:16:06,551::BindingXMLRPC::879::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff'}], 'FC': []}, 'packages2': {'kernel': {'release': '262.el6.x86_64', 'buildtime': 1333899480.0, 'version': '2.6.32'}, 'spice-server': {'release': '5.el6', 'buildtime': '1333631639', 'version': '0.10.1'}, 'vdsm': {'release': '0.239.gitf693264.el6', 'buildtime': '1343813065', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}, 'libvirt': {'release': '21.el6', 'buildtime': '1337779106', 'version': '0.9.10'}, 'qemu-img': {'release': '2.295.el6_3.1', 'buildtime': '1342464920', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'interface': 'engine', 'gateway': '0.0.0.0', 'ports': []}, 'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'bridged': True, 'interface': 'ovirtmgmt', 'gateway': '10.35.1.254', 'ports': ['em1']}}, 'bridges': {'ovirtmgmt': {'addr': '10.35.1.62', 'cfg': {'DELAY': '0', 'BOOTPROTO': 'dhcp', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'ports': ['em1']}, 'engine': {'addr': '', 'cfg': {'DEVICE': 'engine', 'DELAY': '0', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'STP': 'no'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': []}}, 'uuid': '4C4C4544-0043-5010-8038-CAC04F37354A_18:03:73:cb:c1:ce', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '18:03:73:CB:C1:CE', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'BRIDGE': 'ovirtmgmt'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '18:03:73:cb:c1:ce', 'speed': 1000}}, 'software_revision': '0.239', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,sse4_2,x2apic,popcnt,aes,xsave,avx,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_Penryn,model_Westmere,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:27c1ec9f7eff', 'netConfigDirty': 'False', 'memSize': '7750', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.10', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.3.0', u'pc', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '6.3.0.2.el6', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '10.35.1.234'}}
>Thread-12::DEBUG::2012-08-05 10:16:06,724::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:06,770::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:06,770::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,770::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,771::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,771::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,771::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,771::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,771::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-05 10:16:06,771::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:06,772::__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 1e49d867-4438-4484-a1ca-f6ab7013a319' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:06,853::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "1e49d867-4438-4484-a1ca-f6ab7013a319" not found\n'; <rc> = 5
>Thread-12::WARNING::2012-08-05 10:16:06,854::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1e49d867-4438-4484-a1ca-f6ab7013a319" not found']
>Thread-12::DEBUG::2012-08-05 10:16:06,854::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,894::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-21::DEBUG::2012-08-05 10:16:06,903::task::568::TaskManager.Task::(_updateState) Task=`df4c4a3e-7710-42cc-a26f-20c9cc8d20cf`::moving from state init -> state preparing
>Thread-21::INFO::2012-08-05 10:16:06,914::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=6, spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', conList=[{'port': '', 'connection': 'multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'nfs', 'password': '******', 'id': '02fdfde1-102a-4ef3-817c-79c7410b2a9b'}], options=None)
>Thread-21::DEBUG::2012-08-05 10:16:06,929::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,929::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,929::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,930::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,930::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2012-08-05 10:16:06,930::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::INFO::2012-08-05 10:16:06,930::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '02fdfde1-102a-4ef3-817c-79c7410b2a9b'}]}
>Thread-21::DEBUG::2012-08-05 10:16:06,930::task::1151::TaskManager.Task::(prepare) Task=`df4c4a3e-7710-42cc-a26f-20c9cc8d20cf`::finished: {'statuslist': [{'status': 0, 'id': '02fdfde1-102a-4ef3-817c-79c7410b2a9b'}]}
>Thread-21::DEBUG::2012-08-05 10:16:06,931::task::568::TaskManager.Task::(_updateState) Task=`df4c4a3e-7710-42cc-a26f-20c9cc8d20cf`::moving from state preparing -> state finished
>Thread-21::DEBUG::2012-08-05 10:16:06,931::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21::DEBUG::2012-08-05 10:16:06,931::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21::DEBUG::2012-08-05 10:16:06,931::task::957::TaskManager.Task::(_decref) Task=`df4c4a3e-7710-42cc-a26f-20c9cc8d20cf`::ref 0 aborting False
>Thread-12::DEBUG::2012-08-05 10:16:06,949::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1/1e49d867-4438-4484-a1ca-f6ab7013a319
>Thread-12::DEBUG::2012-08-05 10:16:06,949::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-34::DEBUG::2012-08-05 10:16:06,969::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-34::DEBUG::2012-08-05 10:16:06,970::task::568::TaskManager.Task::(_updateState) Task=`0042dcd6-a428-4eeb-abfd-5d9e15a53cd9`::moving from state init -> state preparing
>Thread-34::INFO::2012-08-05 10:16:06,970::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', hostID=1, scsiKey='22c33e31-f5f8-49f7-afb7-309bafd407b2', msdUUID='1e49d867-4438-4484-a1ca-f6ab7013a319', masterVersion=1, options=None)
>Thread-34::DEBUG::2012-08-05 10:16:06,970::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`0a9252a7-01e4-4a21-ae73-df047a2fc54e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-34::DEBUG::2012-08-05 10:16:06,970::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'exclusive'
>Thread-34::DEBUG::2012-08-05 10:16:06,970::resourceManager::510::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is currently locked, Entering queue (1 in queue)
>Thread-12::DEBUG::2012-08-05 10:16:06,987::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>Thread-12::DEBUG::2012-08-05 10:16:07,019::fileSD::419::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-12::DEBUG::2012-08-05 10:16:07,019::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '1e49d867-4438-4484-a1ca-f6ab7013a319_imageNS'
>Thread-12::DEBUG::2012-08-05 10:16:07,019::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '1e49d867-4438-4484-a1ca-f6ab7013a319_volumeNS'
>Thread-12::DEBUG::2012-08-05 10:16:07,020::sp::1519::Storage.StoragePool::(getMasterDomain) Master domain 1e49d867-4438-4484-a1ca-f6ab7013a319 verified, version 1
>Thread-12::DEBUG::2012-08-05 10:16:07,020::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-12::DEBUG::2012-08-05 10:16:07,020::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:07,026::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>Thread-12::DEBUG::2012-08-05 10:16:07,026::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-12::DEBUG::2012-08-05 10:16:07,026::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:07,027::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-12::DEBUG::2012-08-05 10:16:07,027::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-12::DEBUG::2012-08-05 10:16:07,027::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:07,036::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-12::DEBUG::2012-08-05 10:16:07,036::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-05 10:16:07,682::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:07,731::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,732::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,733::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-05 10:16:07,733::sp::1554::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `22c33e31-f5f8-49f7-afb7-309bafd407b2` started monitoring domain `1e49d867-4438-4484-a1ca-f6ab7013a319`
>Thread-12::DEBUG::2012-08-05 10:16:07,734::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-12::DEBUG::2012-08-05 10:16:07,736::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-12::DEBUG::2012-08-05 10:16:07,741::__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' (cwd None)
>Thread-12::DEBUG::2012-08-05 10:16:07,813::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-12::DEBUG::2012-08-05 10:16:07,813::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-12::INFO::2012-08-05 10:16:07,821::sp::1118::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1/1e49d867-4438-4484-a1ca-f6ab7013a319 to /rhev/data-center/22c33e31-f5f8-49f7-afb7-309bafd407b2/1e49d867-4438-4484-a1ca-f6ab7013a319
>Thread-12::INFO::2012-08-05 10:16:07,822::sp::1118::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1/1e49d867-4438-4484-a1ca-f6ab7013a319 to /rhev/data-center/22c33e31-f5f8-49f7-afb7-309bafd407b2/mastersd
>Thread-12::DEBUG::2012-08-05 10:16:07,822::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-12::DEBUG::2012-08-05 10:16:07,822::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-12::DEBUG::2012-08-05 10:16:07,822::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-12::DEBUG::2012-08-05 10:16:07,823::resourceManager::568::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' has 1 requests in queue. Handling top request.
>Thread-12::DEBUG::2012-08-05 10:16:07,823::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`0a9252a7-01e4-4a21-ae73-df047a2fc54e`::Granted request
>Thread-12::DEBUG::2012-08-05 10:16:07,823::resourceManager::589::ResourceManager::(releaseResource) Request 'Request for Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 - exclusive: granted' was granted
>Thread-34::DEBUG::2012-08-05 10:16:07,823::sp::1519::Storage.StoragePool::(getMasterDomain) Master domain 1e49d867-4438-4484-a1ca-f6ab7013a319 verified, version 1
>Thread-34::DEBUG::2012-08-05 10:16:07,824::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-34::DEBUG::2012-08-05 10:16:07,824::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-34::DEBUG::2012-08-05 10:16:07,824::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-34::DEBUG::2012-08-05 10:16:07,824::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-34::INFO::2012-08-05 10:16:07,824::logUtils::39::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: None
>Thread-34::DEBUG::2012-08-05 10:16:07,825::task::1151::TaskManager.Task::(prepare) Task=`0042dcd6-a428-4eeb-abfd-5d9e15a53cd9`::finished: None
>Thread-34::DEBUG::2012-08-05 10:16:07,825::task::568::TaskManager.Task::(_updateState) Task=`0042dcd6-a428-4eeb-abfd-5d9e15a53cd9`::moving from state preparing -> state finished
>Thread-34::DEBUG::2012-08-05 10:16:07,825::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-34::DEBUG::2012-08-05 10:16:07,825::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-34::DEBUG::2012-08-05 10:16:07,825::task::957::TaskManager.Task::(_decref) Task=`0042dcd6-a428-4eeb-abfd-5d9e15a53cd9`::ref 0 aborting False
>Thread-53::DEBUG::2012-08-05 10:16:13,861::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-53::DEBUG::2012-08-05 10:16:13,862::task::568::TaskManager.Task::(_updateState) Task=`b0ce49c5-bc5c-4c0a-808c-3f1b9d2848d7`::moving from state init -> state preparing
>Thread-53::INFO::2012-08-05 10:16:13,862::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-53::DEBUG::2012-08-05 10:16:13,871::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>Thread-53::INFO::2012-08-05 10:16:13,871::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 2}}
>Thread-53::DEBUG::2012-08-05 10:16:13,871::task::1151::TaskManager.Task::(prepare) Task=`b0ce49c5-bc5c-4c0a-808c-3f1b9d2848d7`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 2}}
>Thread-53::DEBUG::2012-08-05 10:16:13,871::task::568::TaskManager.Task::(_updateState) Task=`b0ce49c5-bc5c-4c0a-808c-3f1b9d2848d7`::moving from state preparing -> state finished
>Thread-53::DEBUG::2012-08-05 10:16:13,871::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-53::DEBUG::2012-08-05 10:16:13,871::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-53::DEBUG::2012-08-05 10:16:13,871::task::957::TaskManager.Task::(_decref) Task=`b0ce49c5-bc5c-4c0a-808c-3f1b9d2848d7`::ref 0 aborting False
>Thread-54::DEBUG::2012-08-05 10:16:13,878::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-54::DEBUG::2012-08-05 10:16:13,878::task::568::TaskManager.Task::(_updateState) Task=`6cd45c0e-6137-4e66-b4fe-c6f9d0fdc5b4`::moving from state init -> state preparing
>Thread-54::INFO::2012-08-05 10:16:13,879::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-54::DEBUG::2012-08-05 10:16:13,884::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>Thread-54::INFO::2012-08-05 10:16:13,884::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 2}}
>Thread-54::DEBUG::2012-08-05 10:16:13,885::task::1151::TaskManager.Task::(prepare) Task=`6cd45c0e-6137-4e66-b4fe-c6f9d0fdc5b4`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 2}}
>Thread-54::DEBUG::2012-08-05 10:16:13,885::task::568::TaskManager.Task::(_updateState) Task=`6cd45c0e-6137-4e66-b4fe-c6f9d0fdc5b4`::moving from state preparing -> state finished
>Thread-54::DEBUG::2012-08-05 10:16:13,885::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-54::DEBUG::2012-08-05 10:16:13,885::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-54::DEBUG::2012-08-05 10:16:13,885::task::957::TaskManager.Task::(_decref) Task=`6cd45c0e-6137-4e66-b4fe-c6f9d0fdc5b4`::ref 0 aborting False
>Thread-55::DEBUG::2012-08-05 10:16:13,954::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-55::DEBUG::2012-08-05 10:16:13,954::task::568::TaskManager.Task::(_updateState) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::moving from state init -> state preparing
>Thread-55::INFO::2012-08-05 10:16:13,954::logUtils::37::dispatcher::(wrapper) Run and protect: spmStart(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', prevID=1, prevLVER='2', recoveryMode=None, scsiFencing='false', maxHostID=250, domVersion='3', options=None)
>Thread-55::DEBUG::2012-08-05 10:16:13,954::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`2c88f6d6-e3da-449f-ac8d-ff72ae5490d3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-55::DEBUG::2012-08-05 10:16:13,955::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'exclusive'
>Thread-55::DEBUG::2012-08-05 10:16:13,955::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'exclusive' (1 active user)
>Thread-55::DEBUG::2012-08-05 10:16:13,955::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`2c88f6d6-e3da-449f-ac8d-ff72ae5490d3`::Granted request
>Thread-55::DEBUG::2012-08-05 10:16:13,955::task::794::TaskManager.Task::(resourceAcquired) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (exclusive)
>Thread-55::DEBUG::2012-08-05 10:16:13,955::task::957::TaskManager.Task::(_decref) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::ref 1 aborting False
>Thread-55::INFO::2012-08-05 10:16:13,956::logUtils::39::dispatcher::(wrapper) Run and protect: spmStart, Return response: None
>Thread-55::DEBUG::2012-08-05 10:16:13,956::task::1146::TaskManager.Task::(prepare) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::Prepare: 1 jobs exist, move to acquiring
>Thread-55::DEBUG::2012-08-05 10:16:13,956::task::568::TaskManager.Task::(_updateState) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::moving from state preparing -> state acquiring
>Thread-55::DEBUG::2012-08-05 10:16:13,956::task::568::TaskManager.Task::(_updateState) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::moving from state acquiring -> state queued
>Thread-55::DEBUG::2012-08-05 10:16:13,956::taskManager::50::TaskManager::(_queueTask) queuing task: bffcf609-c458-434d-a21b-b39d9e2b48b6
>Thread-55::DEBUG::2012-08-05 10:16:13,956::taskManager::56::TaskManager::(_queueTask) task queued: bffcf609-c458-434d-a21b-b39d9e2b48b6
>Thread-1::DEBUG::2012-08-05 10:16:13,956::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-55::DEBUG::2012-08-05 10:16:13,956::task::1148::TaskManager.Task::(prepare) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::returning
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,957::threadPool::212::Misc.ThreadPool.WorkerThread::(run) Task: bffcf609-c458-434d-a21b-b39d9e2b48b6 running: <bound method Task.commit of <storage.task.Task instance at 0x7fc7f43b06c8>> with: None
>Thread-55::DEBUG::2012-08-05 10:16:13,957::task::957::TaskManager.Task::(_decref) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::ref 0 aborting False
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,957::task::1159::TaskManager.Task::(commit) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::committing task: bffcf609-c458-434d-a21b-b39d9e2b48b6
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,958::task::568::TaskManager.Task::(_updateState) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::moving from state queued -> state running
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,958::task::872::TaskManager.Task::(_runJobs) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::Task.run: running job 0: spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x1573f90>> (args: (1, '2', 'false', 250, 3) kwargs: {})
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,958::task::304::TaskManager.Task::(run) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::Job.run: running spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x1573f90>> (args: (1, '2', 'false', 250, 3) kwargs: {}) callback None
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,958::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,958::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,964::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,965::misc::1071::SamplingMethod::(__call__) Returning last result
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,969::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,972::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::INFO::2012-08-05 10:16:13,972::safelease::160::SANLock::(acquireHostId) Acquiring host id for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 (id: 1)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:13,973::safelease::178::SANLock::(acquireHostId) Host id for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 successfully acquired (id: 1)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::INFO::2012-08-05 10:16:13,973::safelease::211::SANLock::(acquire) Acquiring cluster lock for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 (id: 1)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,038::safelease::235::SANLock::(acquire) Cluster lock for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 successfully acquired (id: 1)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,038::sp::256::Storage.StoragePool::(startSpm) spm lock acquired successfully
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,041::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=2', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=9b97384d1a2de659c266d2968cad84a0c06ce24a']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,041::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,041::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,041::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=3', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=02773e6b8fdc999a1fdc85be3f0e983f36bd44e5']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,076::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,077::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`7c5bdbc4-f7d8-4e01-a3d1-9f7c8d31a8ce`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,077::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'exclusive'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,077::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'exclusive' (1 active user)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,077::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`7c5bdbc4-f7d8-4e01-a3d1-9f7c8d31a8ce`::Granted request
>bffcf609-c458-434d-a21b-b39d9e2b48b6::INFO::2012-08-05 10:16:14,077::sp::403::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `1e49d867-4438-4484-a1ca-f6ab7013a319`
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,078::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1e49d867-4438-4484-a1ca-f6ab7013a319`ReqID=`9b9d90fd-bf92-45ec-a629-730c8e020f7b`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,078::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319' for lock type 'exclusive'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,078::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319' is free. Now locking as 'exclusive' (1 active user)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,078::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1e49d867-4438-4484-a1ca-f6ab7013a319`ReqID=`9b9d90fd-bf92-45ec-a629-730c8e020f7b`::Granted request
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319' (0 active users)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319' is free, finding out if anyone is waiting for it.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1e49d867-4438-4484-a1ca-f6ab7013a319', Clearing records.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::sp::407::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,079::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,080::__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 1e49d867-4438-4484-a1ca-f6ab7013a319' (cwd None)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,159::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "1e49d867-4438-4484-a1ca-f6ab7013a319" not found\n'; <rc> = 5
>bffcf609-c458-434d-a21b-b39d9e2b48b6::WARNING::2012-08-05 10:16:14,160::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1e49d867-4438-4484-a1ca-f6ab7013a319" not found']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,161::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,174::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix1/1e49d867-4438-4484-a1ca-f6ab7013a319
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,174::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,191::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sdposix', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=dcposix', 'POOL_DOMAINS=1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=3', 'POOL_UUID=22c33e31-f5f8-49f7-afb7-309bafd407b2', 'REMOTE_PATH=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix1', 'ROLE=Master', 'SDUUID=1e49d867-4438-4484-a1ca-f6ab7013a319', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=02773e6b8fdc999a1fdc85be3f0e983f36bd44e5']
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,194::fileSD::419::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>bffcf609-c458-434d-a21b-b39d9e2b48b6::WARNING::2012-08-05 10:16:14,194::sd::348::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1e49d867-4438-4484-a1ca-f6ab7013a319_imageNS already registered
>bffcf609-c458-434d-a21b-b39d9e2b48b6::WARNING::2012-08-05 10:16:14,194::sd::356::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1e49d867-4438-4484-a1ca-f6ab7013a319_volumeNS already registered
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,194::sp::414::Storage.StoragePool::(_upgradePool) Registering with state change event
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,194::sp::416::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,195::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,195::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,195::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,195::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,197::sp::305::Storage.StoragePool::(startSpm) ended.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,197::task::568::TaskManager.Task::(_updateState) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::moving from state running -> state finished
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,197::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::task::880::TaskManager.Task::(_runJobs) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::Task.run: exit - success: result 
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,198::task::957::TaskManager.Task::(_decref) Task=`bffcf609-c458-434d-a21b-b39d9e2b48b6`::ref 0 aborting False
>bffcf609-c458-434d-a21b-b39d9e2b48b6::DEBUG::2012-08-05 10:16:14,199::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Thread-73::DEBUG::2012-08-05 10:16:14,967::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-73::DEBUG::2012-08-05 10:16:14,967::task::568::TaskManager.Task::(_updateState) Task=`ad481b48-6535-4487-b154-d4bc6666cd43`::moving from state init -> state preparing
>Thread-73::INFO::2012-08-05 10:16:14,967::logUtils::37::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='bffcf609-c458-434d-a21b-b39d9e2b48b6', spUUID=None, options=None)
>Thread-73::DEBUG::2012-08-05 10:16:14,967::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: bffcf609-c458-434d-a21b-b39d9e2b48b6
>Thread-73::DEBUG::2012-08-05 10:16:14,967::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bffcf609-c458-434d-a21b-b39d9e2b48b6'}
>Thread-73::INFO::2012-08-05 10:16:14,968::logUtils::39::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bffcf609-c458-434d-a21b-b39d9e2b48b6'}}
>Thread-73::DEBUG::2012-08-05 10:16:14,968::task::1151::TaskManager.Task::(prepare) Task=`ad481b48-6535-4487-b154-d4bc6666cd43`::finished: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'bffcf609-c458-434d-a21b-b39d9e2b48b6'}}
>Thread-73::DEBUG::2012-08-05 10:16:14,968::task::568::TaskManager.Task::(_updateState) Task=`ad481b48-6535-4487-b154-d4bc6666cd43`::moving from state preparing -> state finished
>Thread-73::DEBUG::2012-08-05 10:16:14,968::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-73::DEBUG::2012-08-05 10:16:14,968::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-73::DEBUG::2012-08-05 10:16:14,968::task::957::TaskManager.Task::(_decref) Task=`ad481b48-6535-4487-b154-d4bc6666cd43`::ref 0 aborting False
>Thread-74::DEBUG::2012-08-05 10:16:14,975::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-74::DEBUG::2012-08-05 10:16:14,975::task::568::TaskManager.Task::(_updateState) Task=`534067fd-cd26-418d-877e-d1563cd4133c`::moving from state init -> state preparing
>Thread-74::INFO::2012-08-05 10:16:14,975::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-74::INFO::2012-08-05 10:16:14,975::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-74::DEBUG::2012-08-05 10:16:14,976::task::1151::TaskManager.Task::(prepare) Task=`534067fd-cd26-418d-877e-d1563cd4133c`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-74::DEBUG::2012-08-05 10:16:14,976::task::568::TaskManager.Task::(_updateState) Task=`534067fd-cd26-418d-877e-d1563cd4133c`::moving from state preparing -> state finished
>Thread-74::DEBUG::2012-08-05 10:16:14,976::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-74::DEBUG::2012-08-05 10:16:14,976::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-74::DEBUG::2012-08-05 10:16:14,976::task::957::TaskManager.Task::(_decref) Task=`534067fd-cd26-418d-877e-d1563cd4133c`::ref 0 aborting False
>Thread-75::DEBUG::2012-08-05 10:16:14,986::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-75::DEBUG::2012-08-05 10:16:14,986::task::568::TaskManager.Task::(_updateState) Task=`5171de07-3ad5-4b44-94e1-3b3b4a7cebd3`::moving from state init -> state preparing
>Thread-75::INFO::2012-08-05 10:16:14,986::logUtils::37::dispatcher::(wrapper) Run and protect: clearTask(taskID='bffcf609-c458-434d-a21b-b39d9e2b48b6', spUUID=None, options=None)
>Thread-75::DEBUG::2012-08-05 10:16:14,986::taskManager::157::TaskManager::(clearTask) Entry. taskID: bffcf609-c458-434d-a21b-b39d9e2b48b6
>Thread-75::DEBUG::2012-08-05 10:16:14,986::taskManager::162::TaskManager::(clearTask) Return.
>Thread-75::INFO::2012-08-05 10:16:14,986::logUtils::39::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-75::DEBUG::2012-08-05 10:16:14,987::task::1151::TaskManager.Task::(prepare) Task=`5171de07-3ad5-4b44-94e1-3b3b4a7cebd3`::finished: None
>Thread-75::DEBUG::2012-08-05 10:16:14,987::task::568::TaskManager.Task::(_updateState) Task=`5171de07-3ad5-4b44-94e1-3b3b4a7cebd3`::moving from state preparing -> state finished
>Thread-75::DEBUG::2012-08-05 10:16:14,987::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-75::DEBUG::2012-08-05 10:16:14,987::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-75::DEBUG::2012-08-05 10:16:14,987::task::957::TaskManager.Task::(_decref) Task=`5171de07-3ad5-4b44-94e1-3b3b4a7cebd3`::ref 0 aborting False
>Thread-76::DEBUG::2012-08-05 10:16:15,086::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-76::DEBUG::2012-08-05 10:16:15,086::task::568::TaskManager.Task::(_updateState) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::moving from state init -> state preparing
>Thread-76::INFO::2012-08-05 10:16:15,086::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-76::DEBUG::2012-08-05 10:16:15,087::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d285f299-7e9d-4c16-a8d4-c5af5928458a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-76::DEBUG::2012-08-05 10:16:15,087::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-76::DEBUG::2012-08-05 10:16:15,087::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-76::DEBUG::2012-08-05 10:16:15,087::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d285f299-7e9d-4c16-a8d4-c5af5928458a`::Granted request
>Thread-76::DEBUG::2012-08-05 10:16:15,087::task::794::TaskManager.Task::(resourceAcquired) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-76::DEBUG::2012-08-05 10:16:15,088::task::957::TaskManager.Task::(_decref) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::ref 1 aborting False
>Thread-76::INFO::2012-08-05 10:16:15,093::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-76::DEBUG::2012-08-05 10:16:15,094::task::1151::TaskManager.Task::(prepare) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-76::DEBUG::2012-08-05 10:16:15,094::task::568::TaskManager.Task::(_updateState) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::moving from state preparing -> state finished
>Thread-76::DEBUG::2012-08-05 10:16:15,094::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-76::DEBUG::2012-08-05 10:16:15,094::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-76::DEBUG::2012-08-05 10:16:15,094::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-76::DEBUG::2012-08-05 10:16:15,094::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-76::DEBUG::2012-08-05 10:16:15,094::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-76::DEBUG::2012-08-05 10:16:15,095::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-76::DEBUG::2012-08-05 10:16:15,095::task::957::TaskManager.Task::(_decref) Task=`197a4e2a-da77-4d5f-a111-53a771aa864f`::ref 0 aborting False
>Thread-77::DEBUG::2012-08-05 10:16:15,171::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-77::DEBUG::2012-08-05 10:16:15,171::task::568::TaskManager.Task::(_updateState) Task=`c09129b9-13d9-422d-a63f-17f88570de85`::moving from state init -> state preparing
>Thread-77::INFO::2012-08-05 10:16:15,172::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksInfo(spUUID=None, options=None)
>Thread-77::DEBUG::2012-08-05 10:16:15,172::taskManager::177::TaskManager::(getAllTasksInfo) Entry.
>Thread-77::DEBUG::2012-08-05 10:16:15,172::taskManager::188::TaskManager::(getAllTasksInfo) Return. Response: {}
>Thread-77::INFO::2012-08-05 10:16:15,172::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksInfo, Return response: {'allTasksInfo': {}}
>Thread-77::DEBUG::2012-08-05 10:16:15,172::task::1151::TaskManager.Task::(prepare) Task=`c09129b9-13d9-422d-a63f-17f88570de85`::finished: {'allTasksInfo': {}}
>Thread-77::DEBUG::2012-08-05 10:16:15,172::task::568::TaskManager.Task::(_updateState) Task=`c09129b9-13d9-422d-a63f-17f88570de85`::moving from state preparing -> state finished
>Thread-77::DEBUG::2012-08-05 10:16:15,172::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-77::DEBUG::2012-08-05 10:16:15,172::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-77::DEBUG::2012-08-05 10:16:15,172::task::957::TaskManager.Task::(_decref) Task=`c09129b9-13d9-422d-a63f-17f88570de85`::ref 0 aborting False
>Thread-78::DEBUG::2012-08-05 10:16:15,183::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-78::DEBUG::2012-08-05 10:16:15,184::task::568::TaskManager.Task::(_updateState) Task=`a5254b09-344a-417d-9448-8e8e241e6ede`::moving from state init -> state preparing
>Thread-78::INFO::2012-08-05 10:16:15,184::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksInfo(spUUID=None, options=None)
>Thread-78::DEBUG::2012-08-05 10:16:15,184::taskManager::177::TaskManager::(getAllTasksInfo) Entry.
>Thread-78::DEBUG::2012-08-05 10:16:15,184::taskManager::188::TaskManager::(getAllTasksInfo) Return. Response: {}
>Thread-78::INFO::2012-08-05 10:16:15,184::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksInfo, Return response: {'allTasksInfo': {}}
>Thread-78::DEBUG::2012-08-05 10:16:15,184::task::1151::TaskManager.Task::(prepare) Task=`a5254b09-344a-417d-9448-8e8e241e6ede`::finished: {'allTasksInfo': {}}
>Thread-78::DEBUG::2012-08-05 10:16:15,184::task::568::TaskManager.Task::(_updateState) Task=`a5254b09-344a-417d-9448-8e8e241e6ede`::moving from state preparing -> state finished
>Thread-78::DEBUG::2012-08-05 10:16:15,184::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-78::DEBUG::2012-08-05 10:16:15,185::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-78::DEBUG::2012-08-05 10:16:15,185::task::957::TaskManager.Task::(_decref) Task=`a5254b09-344a-417d-9448-8e8e241e6ede`::ref 0 aborting False
>Thread-80::DEBUG::2012-08-05 10:16:18,013::task::568::TaskManager.Task::(_updateState) Task=`1b1e5b4a-359a-459b-a20a-a3615316df95`::moving from state init -> state preparing
>Thread-80::INFO::2012-08-05 10:16:18,014::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-80::INFO::2012-08-05 10:16:18,014::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00641894340515', 'lastCheck': 1344150977.772491, 'code': 0, 'valid': True}}
>Thread-80::DEBUG::2012-08-05 10:16:18,014::task::1151::TaskManager.Task::(prepare) Task=`1b1e5b4a-359a-459b-a20a-a3615316df95`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00641894340515', 'lastCheck': 1344150977.772491, 'code': 0, 'valid': True}}
>Thread-80::DEBUG::2012-08-05 10:16:18,014::task::568::TaskManager.Task::(_updateState) Task=`1b1e5b4a-359a-459b-a20a-a3615316df95`::moving from state preparing -> state finished
>Thread-80::DEBUG::2012-08-05 10:16:18,014::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-80::DEBUG::2012-08-05 10:16:18,014::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-80::DEBUG::2012-08-05 10:16:18,014::task::957::TaskManager.Task::(_decref) Task=`1b1e5b4a-359a-459b-a20a-a3615316df95`::ref 0 aborting False
>Thread-85::DEBUG::2012-08-05 10:16:25,166::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-85::DEBUG::2012-08-05 10:16:25,166::task::568::TaskManager.Task::(_updateState) Task=`58f5f215-c331-4ad4-a7f2-87070d69581b`::moving from state init -> state preparing
>Thread-85::INFO::2012-08-05 10:16:25,167::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-85::INFO::2012-08-05 10:16:25,167::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-85::DEBUG::2012-08-05 10:16:25,167::task::1151::TaskManager.Task::(prepare) Task=`58f5f215-c331-4ad4-a7f2-87070d69581b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-85::DEBUG::2012-08-05 10:16:25,167::task::568::TaskManager.Task::(_updateState) Task=`58f5f215-c331-4ad4-a7f2-87070d69581b`::moving from state preparing -> state finished
>Thread-85::DEBUG::2012-08-05 10:16:25,167::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-85::DEBUG::2012-08-05 10:16:25,167::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-85::DEBUG::2012-08-05 10:16:25,167::task::957::TaskManager.Task::(_decref) Task=`58f5f215-c331-4ad4-a7f2-87070d69581b`::ref 0 aborting False
>Thread-86::DEBUG::2012-08-05 10:16:25,174::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-86::DEBUG::2012-08-05 10:16:25,175::task::568::TaskManager.Task::(_updateState) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::moving from state init -> state preparing
>Thread-86::INFO::2012-08-05 10:16:25,175::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-86::DEBUG::2012-08-05 10:16:25,175::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d006b2fc-5795-4848-87b5-c228d58afefe`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-86::DEBUG::2012-08-05 10:16:25,175::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-86::DEBUG::2012-08-05 10:16:25,175::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-86::DEBUG::2012-08-05 10:16:25,176::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d006b2fc-5795-4848-87b5-c228d58afefe`::Granted request
>Thread-86::DEBUG::2012-08-05 10:16:25,176::task::794::TaskManager.Task::(resourceAcquired) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-86::DEBUG::2012-08-05 10:16:25,176::task::957::TaskManager.Task::(_decref) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::ref 1 aborting False
>Thread-86::INFO::2012-08-05 10:16:25,182::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-86::DEBUG::2012-08-05 10:16:25,182::task::1151::TaskManager.Task::(prepare) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-86::DEBUG::2012-08-05 10:16:25,182::task::568::TaskManager.Task::(_updateState) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::moving from state preparing -> state finished
>Thread-86::DEBUG::2012-08-05 10:16:25,182::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-86::DEBUG::2012-08-05 10:16:25,182::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-86::DEBUG::2012-08-05 10:16:25,183::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-86::DEBUG::2012-08-05 10:16:25,183::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-86::DEBUG::2012-08-05 10:16:25,183::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-86::DEBUG::2012-08-05 10:16:25,183::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-86::DEBUG::2012-08-05 10:16:25,183::task::957::TaskManager.Task::(_decref) Task=`6daa9a58-205a-4981-8953-1d7c5cda5824`::ref 0 aborting False
>Thread-88::DEBUG::2012-08-05 10:16:28,202::task::568::TaskManager.Task::(_updateState) Task=`de1e4b2f-b816-4a03-af95-aee95e837282`::moving from state init -> state preparing
>Thread-88::INFO::2012-08-05 10:16:28,203::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-88::INFO::2012-08-05 10:16:28,203::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00776791572571', 'lastCheck': 1344150987.7894959, 'code': 0, 'valid': True}}
>Thread-88::DEBUG::2012-08-05 10:16:28,203::task::1151::TaskManager.Task::(prepare) Task=`de1e4b2f-b816-4a03-af95-aee95e837282`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00776791572571', 'lastCheck': 1344150987.7894959, 'code': 0, 'valid': True}}
>Thread-88::DEBUG::2012-08-05 10:16:28,203::task::568::TaskManager.Task::(_updateState) Task=`de1e4b2f-b816-4a03-af95-aee95e837282`::moving from state preparing -> state finished
>Thread-88::DEBUG::2012-08-05 10:16:28,203::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-88::DEBUG::2012-08-05 10:16:28,203::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-88::DEBUG::2012-08-05 10:16:28,204::task::957::TaskManager.Task::(_decref) Task=`de1e4b2f-b816-4a03-af95-aee95e837282`::ref 0 aborting False
>Thread-93::DEBUG::2012-08-05 10:16:35,320::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-93::DEBUG::2012-08-05 10:16:35,320::task::568::TaskManager.Task::(_updateState) Task=`7abcf61a-973d-437d-a1f9-067a90b9ed9e`::moving from state init -> state preparing
>Thread-93::INFO::2012-08-05 10:16:35,320::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-93::INFO::2012-08-05 10:16:35,320::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-93::DEBUG::2012-08-05 10:16:35,320::task::1151::TaskManager.Task::(prepare) Task=`7abcf61a-973d-437d-a1f9-067a90b9ed9e`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-93::DEBUG::2012-08-05 10:16:35,321::task::568::TaskManager.Task::(_updateState) Task=`7abcf61a-973d-437d-a1f9-067a90b9ed9e`::moving from state preparing -> state finished
>Thread-93::DEBUG::2012-08-05 10:16:35,321::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-93::DEBUG::2012-08-05 10:16:35,321::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-93::DEBUG::2012-08-05 10:16:35,321::task::957::TaskManager.Task::(_decref) Task=`7abcf61a-973d-437d-a1f9-067a90b9ed9e`::ref 0 aborting False
>Thread-94::DEBUG::2012-08-05 10:16:35,326::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-94::DEBUG::2012-08-05 10:16:35,327::task::568::TaskManager.Task::(_updateState) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::moving from state init -> state preparing
>Thread-94::INFO::2012-08-05 10:16:35,327::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-94::DEBUG::2012-08-05 10:16:35,327::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`07f3344f-362b-4664-bd9a-6700bdd46efa`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-94::DEBUG::2012-08-05 10:16:35,327::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-94::DEBUG::2012-08-05 10:16:35,328::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-94::DEBUG::2012-08-05 10:16:35,328::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`07f3344f-362b-4664-bd9a-6700bdd46efa`::Granted request
>Thread-94::DEBUG::2012-08-05 10:16:35,328::task::794::TaskManager.Task::(resourceAcquired) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-94::DEBUG::2012-08-05 10:16:35,328::task::957::TaskManager.Task::(_decref) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::ref 1 aborting False
>Thread-94::INFO::2012-08-05 10:16:35,334::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-94::DEBUG::2012-08-05 10:16:35,334::task::1151::TaskManager.Task::(prepare) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-94::DEBUG::2012-08-05 10:16:35,334::task::568::TaskManager.Task::(_updateState) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::moving from state preparing -> state finished
>Thread-94::DEBUG::2012-08-05 10:16:35,334::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-94::DEBUG::2012-08-05 10:16:35,334::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-94::DEBUG::2012-08-05 10:16:35,335::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-94::DEBUG::2012-08-05 10:16:35,335::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-94::DEBUG::2012-08-05 10:16:35,335::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-94::DEBUG::2012-08-05 10:16:35,335::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-94::DEBUG::2012-08-05 10:16:35,335::task::957::TaskManager.Task::(_decref) Task=`a1220d4f-03e0-4f22-a7ea-da7c7f694b9a`::ref 0 aborting False
>Thread-96::DEBUG::2012-08-05 10:16:38,331::task::568::TaskManager.Task::(_updateState) Task=`a6b21b25-1987-4166-88c5-1882ce8a6664`::moving from state init -> state preparing
>Thread-96::INFO::2012-08-05 10:16:38,332::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-96::INFO::2012-08-05 10:16:38,332::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00692200660706', 'lastCheck': 1344150997.8054039, 'code': 0, 'valid': True}}
>Thread-96::DEBUG::2012-08-05 10:16:38,332::task::1151::TaskManager.Task::(prepare) Task=`a6b21b25-1987-4166-88c5-1882ce8a6664`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00692200660706', 'lastCheck': 1344150997.8054039, 'code': 0, 'valid': True}}
>Thread-96::DEBUG::2012-08-05 10:16:38,332::task::568::TaskManager.Task::(_updateState) Task=`a6b21b25-1987-4166-88c5-1882ce8a6664`::moving from state preparing -> state finished
>Thread-96::DEBUG::2012-08-05 10:16:38,332::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-96::DEBUG::2012-08-05 10:16:38,332::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-96::DEBUG::2012-08-05 10:16:38,332::task::957::TaskManager.Task::(_decref) Task=`a6b21b25-1987-4166-88c5-1882ce8a6664`::ref 0 aborting False
>Thread-101::DEBUG::2012-08-05 10:16:45,431::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-101::DEBUG::2012-08-05 10:16:45,431::task::568::TaskManager.Task::(_updateState) Task=`d703a0e5-f975-4e61-8419-c4de31898578`::moving from state init -> state preparing
>Thread-101::INFO::2012-08-05 10:16:45,431::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-101::INFO::2012-08-05 10:16:45,431::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-101::DEBUG::2012-08-05 10:16:45,431::task::1151::TaskManager.Task::(prepare) Task=`d703a0e5-f975-4e61-8419-c4de31898578`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-101::DEBUG::2012-08-05 10:16:45,432::task::568::TaskManager.Task::(_updateState) Task=`d703a0e5-f975-4e61-8419-c4de31898578`::moving from state preparing -> state finished
>Thread-101::DEBUG::2012-08-05 10:16:45,432::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-101::DEBUG::2012-08-05 10:16:45,432::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-101::DEBUG::2012-08-05 10:16:45,432::task::957::TaskManager.Task::(_decref) Task=`d703a0e5-f975-4e61-8419-c4de31898578`::ref 0 aborting False
>Thread-102::DEBUG::2012-08-05 10:16:45,437::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-102::DEBUG::2012-08-05 10:16:45,437::task::568::TaskManager.Task::(_updateState) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::moving from state init -> state preparing
>Thread-102::INFO::2012-08-05 10:16:45,437::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-102::DEBUG::2012-08-05 10:16:45,437::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`8d000f3d-bc83-4419-a3ee-711f6f03d160`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-102::DEBUG::2012-08-05 10:16:45,438::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-102::DEBUG::2012-08-05 10:16:45,438::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-102::DEBUG::2012-08-05 10:16:45,438::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`8d000f3d-bc83-4419-a3ee-711f6f03d160`::Granted request
>Thread-102::DEBUG::2012-08-05 10:16:45,438::task::794::TaskManager.Task::(resourceAcquired) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-102::DEBUG::2012-08-05 10:16:45,438::task::957::TaskManager.Task::(_decref) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::ref 1 aborting False
>Thread-102::INFO::2012-08-05 10:16:45,444::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-102::DEBUG::2012-08-05 10:16:45,444::task::1151::TaskManager.Task::(prepare) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-102::DEBUG::2012-08-05 10:16:45,444::task::568::TaskManager.Task::(_updateState) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::moving from state preparing -> state finished
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-102::DEBUG::2012-08-05 10:16:45,445::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-102::DEBUG::2012-08-05 10:16:45,445::task::957::TaskManager.Task::(_decref) Task=`3477be33-a285-44ee-991e-9f01af4bbf13`::ref 0 aborting False
>Thread-104::DEBUG::2012-08-05 10:16:48,469::task::568::TaskManager.Task::(_updateState) Task=`37199137-ee9e-417c-87ef-9e6fe849b9cf`::moving from state init -> state preparing
>Thread-104::INFO::2012-08-05 10:16:48,469::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-104::INFO::2012-08-05 10:16:48,469::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00764012336731', 'lastCheck': 1344151007.8218229, 'code': 0, 'valid': True}}
>Thread-104::DEBUG::2012-08-05 10:16:48,469::task::1151::TaskManager.Task::(prepare) Task=`37199137-ee9e-417c-87ef-9e6fe849b9cf`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00764012336731', 'lastCheck': 1344151007.8218229, 'code': 0, 'valid': True}}
>Thread-104::DEBUG::2012-08-05 10:16:48,469::task::568::TaskManager.Task::(_updateState) Task=`37199137-ee9e-417c-87ef-9e6fe849b9cf`::moving from state preparing -> state finished
>Thread-104::DEBUG::2012-08-05 10:16:48,469::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-104::DEBUG::2012-08-05 10:16:48,470::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-104::DEBUG::2012-08-05 10:16:48,470::task::957::TaskManager.Task::(_decref) Task=`37199137-ee9e-417c-87ef-9e6fe849b9cf`::ref 0 aborting False
>Thread-109::DEBUG::2012-08-05 10:16:55,531::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-109::DEBUG::2012-08-05 10:16:55,531::task::568::TaskManager.Task::(_updateState) Task=`264d3873-ebf7-4c77-9321-d158c667a0d5`::moving from state init -> state preparing
>Thread-109::INFO::2012-08-05 10:16:55,531::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-109::INFO::2012-08-05 10:16:55,532::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-109::DEBUG::2012-08-05 10:16:55,532::task::1151::TaskManager.Task::(prepare) Task=`264d3873-ebf7-4c77-9321-d158c667a0d5`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-109::DEBUG::2012-08-05 10:16:55,532::task::568::TaskManager.Task::(_updateState) Task=`264d3873-ebf7-4c77-9321-d158c667a0d5`::moving from state preparing -> state finished
>Thread-109::DEBUG::2012-08-05 10:16:55,532::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-109::DEBUG::2012-08-05 10:16:55,532::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-109::DEBUG::2012-08-05 10:16:55,532::task::957::TaskManager.Task::(_decref) Task=`264d3873-ebf7-4c77-9321-d158c667a0d5`::ref 0 aborting False
>Thread-110::DEBUG::2012-08-05 10:16:55,537::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-110::DEBUG::2012-08-05 10:16:55,537::task::568::TaskManager.Task::(_updateState) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::moving from state init -> state preparing
>Thread-110::INFO::2012-08-05 10:16:55,537::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-110::DEBUG::2012-08-05 10:16:55,537::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`182b13ae-7387-4f50-b7af-38e30b687155`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-110::DEBUG::2012-08-05 10:16:55,537::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-110::DEBUG::2012-08-05 10:16:55,538::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-110::DEBUG::2012-08-05 10:16:55,538::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`182b13ae-7387-4f50-b7af-38e30b687155`::Granted request
>Thread-110::DEBUG::2012-08-05 10:16:55,538::task::794::TaskManager.Task::(resourceAcquired) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-110::DEBUG::2012-08-05 10:16:55,538::task::957::TaskManager.Task::(_decref) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::ref 1 aborting False
>Thread-110::INFO::2012-08-05 10:16:55,544::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-110::DEBUG::2012-08-05 10:16:55,544::task::1151::TaskManager.Task::(prepare) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-110::DEBUG::2012-08-05 10:16:55,544::task::568::TaskManager.Task::(_updateState) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::moving from state preparing -> state finished
>Thread-110::DEBUG::2012-08-05 10:16:55,544::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-110::DEBUG::2012-08-05 10:16:55,545::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-110::DEBUG::2012-08-05 10:16:55,545::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-110::DEBUG::2012-08-05 10:16:55,545::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-110::DEBUG::2012-08-05 10:16:55,545::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-110::DEBUG::2012-08-05 10:16:55,545::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-110::DEBUG::2012-08-05 10:16:55,545::task::957::TaskManager.Task::(_decref) Task=`379ffc45-cfe3-4ebb-8743-0ef36659d04f`::ref 0 aborting False
>Thread-112::DEBUG::2012-08-05 10:16:58,586::task::568::TaskManager.Task::(_updateState) Task=`6a0d2233-ec6d-46fd-ad1d-fe720917ed7f`::moving from state init -> state preparing
>Thread-112::INFO::2012-08-05 10:16:58,586::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-112::INFO::2012-08-05 10:16:58,586::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00719785690308', 'lastCheck': 1344151017.8378749, 'code': 0, 'valid': True}}
>Thread-112::DEBUG::2012-08-05 10:16:58,586::task::1151::TaskManager.Task::(prepare) Task=`6a0d2233-ec6d-46fd-ad1d-fe720917ed7f`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00719785690308', 'lastCheck': 1344151017.8378749, 'code': 0, 'valid': True}}
>Thread-112::DEBUG::2012-08-05 10:16:58,587::task::568::TaskManager.Task::(_updateState) Task=`6a0d2233-ec6d-46fd-ad1d-fe720917ed7f`::moving from state preparing -> state finished
>Thread-112::DEBUG::2012-08-05 10:16:58,587::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-112::DEBUG::2012-08-05 10:16:58,587::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-112::DEBUG::2012-08-05 10:16:58,587::task::957::TaskManager.Task::(_decref) Task=`6a0d2233-ec6d-46fd-ad1d-fe720917ed7f`::ref 0 aborting False
>Thread-117::DEBUG::2012-08-05 10:17:05,632::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-117::DEBUG::2012-08-05 10:17:05,633::task::568::TaskManager.Task::(_updateState) Task=`fe88519a-122e-4233-9c72-15f2ad608a85`::moving from state init -> state preparing
>Thread-117::INFO::2012-08-05 10:17:05,633::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-117::INFO::2012-08-05 10:17:05,633::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-117::DEBUG::2012-08-05 10:17:05,633::task::1151::TaskManager.Task::(prepare) Task=`fe88519a-122e-4233-9c72-15f2ad608a85`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-117::DEBUG::2012-08-05 10:17:05,633::task::568::TaskManager.Task::(_updateState) Task=`fe88519a-122e-4233-9c72-15f2ad608a85`::moving from state preparing -> state finished
>Thread-117::DEBUG::2012-08-05 10:17:05,633::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-117::DEBUG::2012-08-05 10:17:05,634::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-117::DEBUG::2012-08-05 10:17:05,634::task::957::TaskManager.Task::(_decref) Task=`fe88519a-122e-4233-9c72-15f2ad608a85`::ref 0 aborting False
>Thread-118::DEBUG::2012-08-05 10:17:05,638::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-118::DEBUG::2012-08-05 10:17:05,638::task::568::TaskManager.Task::(_updateState) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::moving from state init -> state preparing
>Thread-118::INFO::2012-08-05 10:17:05,638::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-118::DEBUG::2012-08-05 10:17:05,639::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`806bd53c-1723-4bfa-ada1-596c70b5e971`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-118::DEBUG::2012-08-05 10:17:05,639::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-118::DEBUG::2012-08-05 10:17:05,639::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-118::DEBUG::2012-08-05 10:17:05,639::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`806bd53c-1723-4bfa-ada1-596c70b5e971`::Granted request
>Thread-118::DEBUG::2012-08-05 10:17:05,640::task::794::TaskManager.Task::(resourceAcquired) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-118::DEBUG::2012-08-05 10:17:05,640::task::957::TaskManager.Task::(_decref) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::ref 1 aborting False
>Thread-118::INFO::2012-08-05 10:17:05,645::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-118::DEBUG::2012-08-05 10:17:05,646::task::1151::TaskManager.Task::(prepare) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-118::DEBUG::2012-08-05 10:17:05,646::task::568::TaskManager.Task::(_updateState) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::moving from state preparing -> state finished
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-118::DEBUG::2012-08-05 10:17:05,646::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-118::DEBUG::2012-08-05 10:17:05,646::task::957::TaskManager.Task::(_decref) Task=`343a02eb-ad41-472d-b62f-1a6f711ff568`::ref 0 aborting False
>Thread-120::DEBUG::2012-08-05 10:17:08,699::task::568::TaskManager.Task::(_updateState) Task=`15fe2739-6bfb-42c5-9424-63a360582711`::moving from state init -> state preparing
>Thread-120::INFO::2012-08-05 10:17:08,699::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-120::INFO::2012-08-05 10:17:08,700::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00816011428833', 'lastCheck': 1344151027.858886, 'code': 0, 'valid': True}}
>Thread-120::DEBUG::2012-08-05 10:17:08,700::task::1151::TaskManager.Task::(prepare) Task=`15fe2739-6bfb-42c5-9424-63a360582711`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00816011428833', 'lastCheck': 1344151027.858886, 'code': 0, 'valid': True}}
>Thread-120::DEBUG::2012-08-05 10:17:08,700::task::568::TaskManager.Task::(_updateState) Task=`15fe2739-6bfb-42c5-9424-63a360582711`::moving from state preparing -> state finished
>Thread-120::DEBUG::2012-08-05 10:17:08,700::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-120::DEBUG::2012-08-05 10:17:08,700::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-120::DEBUG::2012-08-05 10:17:08,700::task::957::TaskManager.Task::(_decref) Task=`15fe2739-6bfb-42c5-9424-63a360582711`::ref 0 aborting False
>Thread-125::DEBUG::2012-08-05 10:17:15,688::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-125::DEBUG::2012-08-05 10:17:15,689::task::568::TaskManager.Task::(_updateState) Task=`46b6b53a-8f13-4491-bb80-e1323095323c`::moving from state init -> state preparing
>Thread-125::INFO::2012-08-05 10:17:15,689::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-125::INFO::2012-08-05 10:17:15,690::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-125::DEBUG::2012-08-05 10:17:15,690::task::1151::TaskManager.Task::(prepare) Task=`46b6b53a-8f13-4491-bb80-e1323095323c`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-125::DEBUG::2012-08-05 10:17:15,690::task::568::TaskManager.Task::(_updateState) Task=`46b6b53a-8f13-4491-bb80-e1323095323c`::moving from state preparing -> state finished
>Thread-125::DEBUG::2012-08-05 10:17:15,690::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-125::DEBUG::2012-08-05 10:17:15,690::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-125::DEBUG::2012-08-05 10:17:15,690::task::957::TaskManager.Task::(_decref) Task=`46b6b53a-8f13-4491-bb80-e1323095323c`::ref 0 aborting False
>Thread-126::DEBUG::2012-08-05 10:17:15,695::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-126::DEBUG::2012-08-05 10:17:15,695::task::568::TaskManager.Task::(_updateState) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::moving from state init -> state preparing
>Thread-126::INFO::2012-08-05 10:17:15,695::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-126::DEBUG::2012-08-05 10:17:15,695::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`0c45081b-e124-428a-8bc9-995d39ce02e4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-126::DEBUG::2012-08-05 10:17:15,695::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-126::DEBUG::2012-08-05 10:17:15,696::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-126::DEBUG::2012-08-05 10:17:15,696::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`0c45081b-e124-428a-8bc9-995d39ce02e4`::Granted request
>Thread-126::DEBUG::2012-08-05 10:17:15,696::task::794::TaskManager.Task::(resourceAcquired) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-126::DEBUG::2012-08-05 10:17:15,697::task::957::TaskManager.Task::(_decref) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::ref 1 aborting False
>Thread-126::INFO::2012-08-05 10:17:15,703::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-126::DEBUG::2012-08-05 10:17:15,704::task::1151::TaskManager.Task::(prepare) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-126::DEBUG::2012-08-05 10:17:15,704::task::568::TaskManager.Task::(_updateState) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::moving from state preparing -> state finished
>Thread-126::DEBUG::2012-08-05 10:17:15,704::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-126::DEBUG::2012-08-05 10:17:15,704::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-126::DEBUG::2012-08-05 10:17:15,704::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-126::DEBUG::2012-08-05 10:17:15,704::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-126::DEBUG::2012-08-05 10:17:15,704::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-126::DEBUG::2012-08-05 10:17:15,705::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-126::DEBUG::2012-08-05 10:17:15,705::task::957::TaskManager.Task::(_decref) Task=`3182df5a-03b4-421f-86ea-f20151fc1abf`::ref 0 aborting False
>Thread-128::DEBUG::2012-08-05 10:17:18,828::task::568::TaskManager.Task::(_updateState) Task=`1fe4501a-a4d5-49d2-8e66-d47b3759e208`::moving from state init -> state preparing
>Thread-128::INFO::2012-08-05 10:17:18,828::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-128::INFO::2012-08-05 10:17:18,829::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00614500045776', 'lastCheck': 1344151037.875145, 'code': 0, 'valid': True}}
>Thread-128::DEBUG::2012-08-05 10:17:18,829::task::1151::TaskManager.Task::(prepare) Task=`1fe4501a-a4d5-49d2-8e66-d47b3759e208`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00614500045776', 'lastCheck': 1344151037.875145, 'code': 0, 'valid': True}}
>Thread-128::DEBUG::2012-08-05 10:17:18,829::task::568::TaskManager.Task::(_updateState) Task=`1fe4501a-a4d5-49d2-8e66-d47b3759e208`::moving from state preparing -> state finished
>Thread-128::DEBUG::2012-08-05 10:17:18,829::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-128::DEBUG::2012-08-05 10:17:18,829::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-128::DEBUG::2012-08-05 10:17:18,829::task::957::TaskManager.Task::(_decref) Task=`1fe4501a-a4d5-49d2-8e66-d47b3759e208`::ref 0 aborting False
>Thread-133::DEBUG::2012-08-05 10:17:25,783::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-133::DEBUG::2012-08-05 10:17:25,784::task::568::TaskManager.Task::(_updateState) Task=`887b9e63-3bea-40e9-b2cf-1c3151d5bc92`::moving from state init -> state preparing
>Thread-133::INFO::2012-08-05 10:17:25,784::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-133::INFO::2012-08-05 10:17:25,784::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-133::DEBUG::2012-08-05 10:17:25,784::task::1151::TaskManager.Task::(prepare) Task=`887b9e63-3bea-40e9-b2cf-1c3151d5bc92`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-133::DEBUG::2012-08-05 10:17:25,784::task::568::TaskManager.Task::(_updateState) Task=`887b9e63-3bea-40e9-b2cf-1c3151d5bc92`::moving from state preparing -> state finished
>Thread-133::DEBUG::2012-08-05 10:17:25,785::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-133::DEBUG::2012-08-05 10:17:25,785::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-133::DEBUG::2012-08-05 10:17:25,785::task::957::TaskManager.Task::(_decref) Task=`887b9e63-3bea-40e9-b2cf-1c3151d5bc92`::ref 0 aborting False
>Thread-134::DEBUG::2012-08-05 10:17:25,789::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-134::DEBUG::2012-08-05 10:17:25,790::task::568::TaskManager.Task::(_updateState) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::moving from state init -> state preparing
>Thread-134::INFO::2012-08-05 10:17:25,790::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-134::DEBUG::2012-08-05 10:17:25,790::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d5d8d4cf-77a8-4592-b2a8-2dc23dce3d28`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-134::DEBUG::2012-08-05 10:17:25,790::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-134::DEBUG::2012-08-05 10:17:25,790::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-134::DEBUG::2012-08-05 10:17:25,791::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`d5d8d4cf-77a8-4592-b2a8-2dc23dce3d28`::Granted request
>Thread-134::DEBUG::2012-08-05 10:17:25,791::task::794::TaskManager.Task::(resourceAcquired) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-134::DEBUG::2012-08-05 10:17:25,791::task::957::TaskManager.Task::(_decref) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::ref 1 aborting False
>Thread-134::INFO::2012-08-05 10:17:25,797::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-134::DEBUG::2012-08-05 10:17:25,797::task::1151::TaskManager.Task::(prepare) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898718760960', 'alerts': [], 'disktotal': '976783147008'}}}
>Thread-134::DEBUG::2012-08-05 10:17:25,797::task::568::TaskManager.Task::(_updateState) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::moving from state preparing -> state finished
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-134::DEBUG::2012-08-05 10:17:25,797::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-134::DEBUG::2012-08-05 10:17:25,798::task::957::TaskManager.Task::(_decref) Task=`96185a91-5045-4566-9d11-28a9165e9a26`::ref 0 aborting False
>Thread-136::DEBUG::2012-08-05 10:17:28,972::task::568::TaskManager.Task::(_updateState) Task=`e504cf07-077c-445b-b0ca-04d5b0072789`::moving from state init -> state preparing
>Thread-136::INFO::2012-08-05 10:17:28,972::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-136::INFO::2012-08-05 10:17:28,973::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00766491889954', 'lastCheck': 1344151047.89363, 'code': 0, 'valid': True}}
>Thread-136::DEBUG::2012-08-05 10:17:28,973::task::1151::TaskManager.Task::(prepare) Task=`e504cf07-077c-445b-b0ca-04d5b0072789`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00766491889954', 'lastCheck': 1344151047.89363, 'code': 0, 'valid': True}}
>Thread-136::DEBUG::2012-08-05 10:17:28,973::task::568::TaskManager.Task::(_updateState) Task=`e504cf07-077c-445b-b0ca-04d5b0072789`::moving from state preparing -> state finished
>Thread-136::DEBUG::2012-08-05 10:17:28,973::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-136::DEBUG::2012-08-05 10:17:28,973::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-136::DEBUG::2012-08-05 10:17:28,973::task::957::TaskManager.Task::(_decref) Task=`e504cf07-077c-445b-b0ca-04d5b0072789`::ref 0 aborting False
>Thread-141::DEBUG::2012-08-05 10:17:35,865::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-141::DEBUG::2012-08-05 10:17:35,865::task::568::TaskManager.Task::(_updateState) Task=`89efa380-0d6d-45a1-8fd2-246505646ddc`::moving from state init -> state preparing
>Thread-141::INFO::2012-08-05 10:17:35,866::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-141::INFO::2012-08-05 10:17:35,866::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-141::DEBUG::2012-08-05 10:17:35,866::task::1151::TaskManager.Task::(prepare) Task=`89efa380-0d6d-45a1-8fd2-246505646ddc`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-141::DEBUG::2012-08-05 10:17:35,866::task::568::TaskManager.Task::(_updateState) Task=`89efa380-0d6d-45a1-8fd2-246505646ddc`::moving from state preparing -> state finished
>Thread-141::DEBUG::2012-08-05 10:17:35,866::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-141::DEBUG::2012-08-05 10:17:35,866::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-141::DEBUG::2012-08-05 10:17:35,866::task::957::TaskManager.Task::(_decref) Task=`89efa380-0d6d-45a1-8fd2-246505646ddc`::ref 0 aborting False
>Thread-142::DEBUG::2012-08-05 10:17:35,871::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-142::DEBUG::2012-08-05 10:17:35,871::task::568::TaskManager.Task::(_updateState) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::moving from state init -> state preparing
>Thread-142::INFO::2012-08-05 10:17:35,871::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-142::DEBUG::2012-08-05 10:17:35,871::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`a50e8e55-4716-4148-9610-f339c7fabacf`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-142::DEBUG::2012-08-05 10:17:35,872::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-142::DEBUG::2012-08-05 10:17:35,872::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-142::DEBUG::2012-08-05 10:17:35,872::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`a50e8e55-4716-4148-9610-f339c7fabacf`::Granted request
>Thread-142::DEBUG::2012-08-05 10:17:35,872::task::794::TaskManager.Task::(resourceAcquired) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-142::DEBUG::2012-08-05 10:17:35,872::task::957::TaskManager.Task::(_decref) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::ref 1 aborting False
>Thread-142::INFO::2012-08-05 10:17:35,878::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976782098432'}}}
>Thread-142::DEBUG::2012-08-05 10:17:35,878::task::1151::TaskManager.Task::(prepare) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976782098432'}}}
>Thread-142::DEBUG::2012-08-05 10:17:35,878::task::568::TaskManager.Task::(_updateState) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::moving from state preparing -> state finished
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-142::DEBUG::2012-08-05 10:17:35,878::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-142::DEBUG::2012-08-05 10:17:35,879::task::957::TaskManager.Task::(_decref) Task=`842eab4d-5ba2-481a-bb1b-d21dd58d8f0d`::ref 0 aborting False
>Thread-143::DEBUG::2012-08-05 10:17:36,735::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-143::DEBUG::2012-08-05 10:17:36,735::task::568::TaskManager.Task::(_updateState) Task=`23c3637f-247d-4388-a6d5-57babaa36c5a`::moving from state init -> state preparing
>Thread-143::INFO::2012-08-05 10:17:36,735::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=6, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'posixfs', 'password': '******', 'id': '266711d4-14c2-404b-8499-5e1417492728'}], options=None)
>Thread-143::INFO::2012-08-05 10:17:36,735::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '266711d4-14c2-404b-8499-5e1417492728'}]}
>Thread-143::DEBUG::2012-08-05 10:17:36,735::task::1151::TaskManager.Task::(prepare) Task=`23c3637f-247d-4388-a6d5-57babaa36c5a`::finished: {'statuslist': [{'status': 0, 'id': '266711d4-14c2-404b-8499-5e1417492728'}]}
>Thread-143::DEBUG::2012-08-05 10:17:36,736::task::568::TaskManager.Task::(_updateState) Task=`23c3637f-247d-4388-a6d5-57babaa36c5a`::moving from state preparing -> state finished
>Thread-143::DEBUG::2012-08-05 10:17:36,736::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-143::DEBUG::2012-08-05 10:17:36,736::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-143::DEBUG::2012-08-05 10:17:36,736::task::957::TaskManager.Task::(_decref) Task=`23c3637f-247d-4388-a6d5-57babaa36c5a`::ref 0 aborting False
>Thread-144::DEBUG::2012-08-05 10:17:36,779::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-144::DEBUG::2012-08-05 10:17:36,779::task::568::TaskManager.Task::(_updateState) Task=`07a7545e-c211-4573-900d-cf44b65874a5`::moving from state init -> state preparing
>Thread-144::INFO::2012-08-05 10:17:36,779::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=6, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'posixfs', 'password': '******', 'id': '266711d4-14c2-404b-8499-5e1417492728'}], options=None)
>Thread-144::DEBUG::2012-08-05 10:17:36,786::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t posixfs multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix-sd' (cwd None)
>Thread-144::ERROR::2012-08-05 10:17:36,808::hsm::1948::Storage.HSM::(connectStorageServer) Could not connect to storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 1945, in connectStorageServer
>    conObj.connect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 179, in connect
>    self._mount.mount(self.options, self._vfsType)
>  File "/usr/share/vdsm/storage/mount.py", line 190, in mount
>    return self._runcmd(cmd, timeout)
>  File "/usr/share/vdsm/storage/mount.py", line 206, in _runcmd
>    raise MountError(rc, ";".join((out, err)))
>MountError: (32, ";mount: unknown filesystem type 'posixfs'\n")
>Thread-144::DEBUG::2012-08-05 10:17:36,810::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-144::DEBUG::2012-08-05 10:17:36,810::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-144::DEBUG::2012-08-05 10:17:36,810::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-144::DEBUG::2012-08-05 10:17:36,810::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-144::DEBUG::2012-08-05 10:17:36,810::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-144::DEBUG::2012-08-05 10:17:36,811::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-144::INFO::2012-08-05 10:17:36,811::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 477, 'id': '266711d4-14c2-404b-8499-5e1417492728'}]}
>Thread-144::DEBUG::2012-08-05 10:17:36,811::task::1151::TaskManager.Task::(prepare) Task=`07a7545e-c211-4573-900d-cf44b65874a5`::finished: {'statuslist': [{'status': 477, 'id': '266711d4-14c2-404b-8499-5e1417492728'}]}
>Thread-144::DEBUG::2012-08-05 10:17:36,811::task::568::TaskManager.Task::(_updateState) Task=`07a7545e-c211-4573-900d-cf44b65874a5`::moving from state preparing -> state finished
>Thread-144::DEBUG::2012-08-05 10:17:36,811::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-144::DEBUG::2012-08-05 10:17:36,811::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-144::DEBUG::2012-08-05 10:17:36,812::task::957::TaskManager.Task::(_decref) Task=`07a7545e-c211-4573-900d-cf44b65874a5`::ref 0 aborting False
>Thread-145::DEBUG::2012-08-05 10:17:37,008::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-145::DEBUG::2012-08-05 10:17:37,008::task::568::TaskManager.Task::(_updateState) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::moving from state init -> state preparing
>Thread-145::INFO::2012-08-05 10:17:37,008::logUtils::37::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=6, sdUUID='a06f358b-1fb8-4a1d-971d-05e41ccf035e', domainName='posix-storage-domain', typeSpecificArg='multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd', domClass=1, domVersion='3', options=None)
>Thread-145::DEBUG::2012-08-05 10:17:37,008::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-145::DEBUG::2012-08-05 10:17:37,009::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-145::DEBUG::2012-08-05 10:17:37,009::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-145::DEBUG::2012-08-05 10:17:37,009::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-145::DEBUG::2012-08-05 10:17:37,009::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-145::DEBUG::2012-08-05 10:17:37,018::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-145::DEBUG::2012-08-05 10:17:37,018::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-145::DEBUG::2012-08-05 10:17:37,649::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-145::DEBUG::2012-08-05 10:17:37,701::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-145::DEBUG::2012-08-05 10:17:37,701::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,701::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,701::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,702::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,702::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,702::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,702::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-145::DEBUG::2012-08-05 10:17:37,702::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-145::DEBUG::2012-08-05 10:17:37,704::__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 a06f358b-1fb8-4a1d-971d-05e41ccf035e' (cwd None)
>Thread-145::DEBUG::2012-08-05 10:17:37,789::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "a06f358b-1fb8-4a1d-971d-05e41ccf035e" not found\n'; <rc> = 5
>Thread-145::WARNING::2012-08-05 10:17:37,789::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "a06f358b-1fb8-4a1d-971d-05e41ccf035e" not found']
>Thread-145::DEBUG::2012-08-05 10:17:37,790::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-145::INFO::2012-08-05 10:17:37,800::nfsSD::64::Storage.StorageDomain::(create) sdUUID=a06f358b-1fb8-4a1d-971d-05e41ccf035e domainName=posix-storage-domain remotePath=multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd domClass=1
>Thread-145::ERROR::2012-08-05 10:17:37,807::task::833::TaskManager.Task::(_setError) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 840, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 2152, in createStorageDomain
>    typeSpecificArg, storageType, domVersion)
>  File "/usr/share/vdsm/storage/nfsSD.py", line 75, in create
>    cls._preCreateValidation(sdUUID, mntPoint, remotePath, version)
>  File "/usr/share/vdsm/storage/nfsSD.py", line 44, in _preCreateValidation
>    raise se.StorageDomainFSNotMounted(domPath)
>StorageDomainFSNotMounted: Storage domain remote path not mounted: ('/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix-sd',)
>Thread-145::DEBUG::2012-08-05 10:17:37,807::task::852::TaskManager.Task::(_run) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::Task._run: 024ea012-33dc-4e9d-b186-dfa0f4b76e68 (6, 'a06f358b-1fb8-4a1d-971d-05e41ccf035e', 'posix-storage-domain', 'multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd', 1, '3') {} failed - stopping task
>Thread-145::DEBUG::2012-08-05 10:17:37,807::task::1177::TaskManager.Task::(stop) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::stopping in state preparing (force False)
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::957::TaskManager.Task::(_decref) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::ref 1 aborting True
>Thread-145::INFO::2012-08-05 10:17:37,808::task::1134::TaskManager.Task::(prepare) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::aborting: Task is aborted: 'Storage domain remote path not mounted' - code 360
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::1139::TaskManager.Task::(prepare) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::Prepare: aborted: Storage domain remote path not mounted
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::957::TaskManager.Task::(_decref) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::ref 0 aborting True
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::892::TaskManager.Task::(_doAbort) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::Task._doAbort: force False
>Thread-145::DEBUG::2012-08-05 10:17:37,808::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::568::TaskManager.Task::(_updateState) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::moving from state preparing -> state aborting
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::523::TaskManager.Task::(__state_aborting) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::_aborting: recover policy none
>Thread-145::DEBUG::2012-08-05 10:17:37,808::task::568::TaskManager.Task::(_updateState) Task=`024ea012-33dc-4e9d-b186-dfa0f4b76e68`::moving from state aborting -> state failed
>Thread-145::DEBUG::2012-08-05 10:17:37,808::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-145::DEBUG::2012-08-05 10:17:37,808::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-145::ERROR::2012-08-05 10:17:37,809::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Storage domain remote path not mounted: ('/rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix-sd',)", 'code': 360}}
>Thread-164::DEBUG::2012-08-05 10:17:37,980::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-164::DEBUG::2012-08-05 10:17:37,981::task::568::TaskManager.Task::(_updateState) Task=`27f9cf58-b5e4-4795-9bcf-36ee66bdc425`::moving from state init -> state preparing
>Thread-164::INFO::2012-08-05 10:17:37,981::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=6, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'multipass.eng.lab.tlv.redhat.com:/export/images/rnd/amureini/posix-sd', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'posixfs', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000'}], options=None)
>Thread-164::DEBUG::2012-08-05 10:17:37,981::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix-sd' (cwd None)
>Thread-164::ERROR::2012-08-05 10:17:37,998::hsm::2022::Storage.HSM::(disconnectStorageServer) Could not disconnect from storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 2019, in disconnectStorageServer
>    conObj.disconnect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 185, in disconnect
>    self._mount.umount(True, True)
>  File "/usr/share/vdsm/storage/mount.py", line 218, in umount
>    return self._runcmd(cmd, timeout)
>  File "/usr/share/vdsm/storage/mount.py", line 206, in _runcmd
>    raise MountError(rc, ";".join((out, err)))
>MountError: (1, ';umount: /rhev/data-center/mnt/multipass.eng.lab.tlv.redhat.com:_export_images_rnd_amureini_posix-sd: not mounted\n')
>Thread-164::DEBUG::2012-08-05 10:17:37,998::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-164::DEBUG::2012-08-05 10:17:37,998::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-164::DEBUG::2012-08-05 10:17:37,999::misc::1061::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-164::DEBUG::2012-08-05 10:17:37,999::misc::1063::SamplingMethod::(__call__) Got in to sampling method
>Thread-164::DEBUG::2012-08-05 10:17:37,999::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-164::DEBUG::2012-08-05 10:17:38,007::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-164::DEBUG::2012-08-05 10:17:38,007::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-164::DEBUG::2012-08-05 10:17:38,680::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-164::DEBUG::2012-08-05 10:17:38,736::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-164::DEBUG::2012-08-05 10:17:38,737::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,737::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,737::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,737::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,738::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,738::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-164::DEBUG::2012-08-05 10:17:38,738::misc::1071::SamplingMethod::(__call__) Returning last result
>Thread-164::INFO::2012-08-05 10:17:38,738::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-164::DEBUG::2012-08-05 10:17:38,738::task::1151::TaskManager.Task::(prepare) Task=`27f9cf58-b5e4-4795-9bcf-36ee66bdc425`::finished: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-164::DEBUG::2012-08-05 10:17:38,738::task::568::TaskManager.Task::(_updateState) Task=`27f9cf58-b5e4-4795-9bcf-36ee66bdc425`::moving from state preparing -> state finished
>Thread-164::DEBUG::2012-08-05 10:17:38,739::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-164::DEBUG::2012-08-05 10:17:38,739::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-164::DEBUG::2012-08-05 10:17:38,739::task::957::TaskManager.Task::(_decref) Task=`27f9cf58-b5e4-4795-9bcf-36ee66bdc425`::ref 0 aborting False
>Thread-165::DEBUG::2012-08-05 10:17:39,061::task::568::TaskManager.Task::(_updateState) Task=`f0b5cc8b-3b33-4333-8886-db7b10167340`::moving from state init -> state preparing
>Thread-165::INFO::2012-08-05 10:17:39,061::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-165::INFO::2012-08-05 10:17:39,062::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00651407241821', 'lastCheck': 1344151057.9094861, 'code': 0, 'valid': True}}
>Thread-165::DEBUG::2012-08-05 10:17:39,062::task::1151::TaskManager.Task::(prepare) Task=`f0b5cc8b-3b33-4333-8886-db7b10167340`::finished: {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'delay': '0.00651407241821', 'lastCheck': 1344151057.9094861, 'code': 0, 'valid': True}}
>Thread-165::DEBUG::2012-08-05 10:17:39,062::task::568::TaskManager.Task::(_updateState) Task=`f0b5cc8b-3b33-4333-8886-db7b10167340`::moving from state preparing -> state finished
>Thread-165::DEBUG::2012-08-05 10:17:39,062::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-165::DEBUG::2012-08-05 10:17:39,062::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-165::DEBUG::2012-08-05 10:17:39,062::task::957::TaskManager.Task::(_decref) Task=`f0b5cc8b-3b33-4333-8886-db7b10167340`::ref 0 aborting False
>Thread-170::DEBUG::2012-08-05 10:17:45,936::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-170::DEBUG::2012-08-05 10:17:45,937::task::568::TaskManager.Task::(_updateState) Task=`f375a520-7c8f-4fc7-bc44-f879fda7f1b8`::moving from state init -> state preparing
>Thread-170::INFO::2012-08-05 10:17:45,937::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-170::INFO::2012-08-05 10:17:45,937::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-170::DEBUG::2012-08-05 10:17:45,937::task::1151::TaskManager.Task::(prepare) Task=`f375a520-7c8f-4fc7-bc44-f879fda7f1b8`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3}}
>Thread-170::DEBUG::2012-08-05 10:17:45,937::task::568::TaskManager.Task::(_updateState) Task=`f375a520-7c8f-4fc7-bc44-f879fda7f1b8`::moving from state preparing -> state finished
>Thread-170::DEBUG::2012-08-05 10:17:45,938::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-170::DEBUG::2012-08-05 10:17:45,938::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-170::DEBUG::2012-08-05 10:17:45,938::task::957::TaskManager.Task::(_decref) Task=`f375a520-7c8f-4fc7-bc44-f879fda7f1b8`::ref 0 aborting False
>Thread-171::DEBUG::2012-08-05 10:17:45,942::BindingXMLRPC::160::vds::(wrapper) [10.35.1.234]
>Thread-171::DEBUG::2012-08-05 10:17:45,943::task::568::TaskManager.Task::(_updateState) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::moving from state init -> state preparing
>Thread-171::INFO::2012-08-05 10:17:45,943::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22c33e31-f5f8-49f7-afb7-309bafd407b2', options=None)
>Thread-171::DEBUG::2012-08-05 10:17:45,943::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`e5bbe6aa-851c-468a-b01f-75fb460b9100`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-171::DEBUG::2012-08-05 10:17:45,943::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' for lock type 'shared'
>Thread-171::DEBUG::2012-08-05 10:17:45,943::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free. Now locking as 'shared' (1 active user)
>Thread-171::DEBUG::2012-08-05 10:17:45,944::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2`ReqID=`e5bbe6aa-851c-468a-b01f-75fb460b9100`::Granted request
>Thread-171::DEBUG::2012-08-05 10:17:45,944::task::794::TaskManager.Task::(resourceAcquired) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::_resourcesAcquired: Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2 (shared)
>Thread-171::DEBUG::2012-08-05 10:17:45,944::task::957::TaskManager.Task::(_decref) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::ref 1 aborting False
>Thread-171::INFO::2012-08-05 10:17:45,950::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976782098432'}}}
>Thread-171::DEBUG::2012-08-05 10:17:45,950::task::1151::TaskManager.Task::(prepare) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::finished: {'info': {'spm_id': 1, 'master_uuid': '1e49d867-4438-4484-a1ca-f6ab7013a319', 'name': 'dcposix', 'version': '3', 'domains': '1e49d867-4438-4484-a1ca-f6ab7013a319:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'POSIXFS', 'master_ver': 1, 'lver': 3}, 'dominfo': {'1e49d867-4438-4484-a1ca-f6ab7013a319': {'status': 'Active', 'diskfree': '898717712384', 'alerts': [], 'disktotal': '976782098432'}}}
>Thread-171::DEBUG::2012-08-05 10:17:45,951::task::568::TaskManager.Task::(_updateState) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::moving from state preparing -> state finished
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2': < ResourceRef 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', isValid: 'True' obj: 'None'>}
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2'
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' (0 active users)
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2' is free, finding out if anyone is waiting for it.
>Thread-171::DEBUG::2012-08-05 10:17:45,951::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22c33e31-f5f8-49f7-afb7-309bafd407b2', Clearing records.
>Thread-171::DEBUG::2012-08-05 10:17:45,952::task::957::TaskManager.Task::(_decref) Task=`bf8ee2b7-bed5-4e05-a2a8-781d023e26de`::ref 0 aborting False
>MainThread::INFO::2012-08-05 10:17:57,163::vmChannels::135::vds::(stop) VM channels listener was stopped.
>MainThread::DEBUG::2012-08-05 10:17:57,164::task::568::TaskManager.Task::(_updateState) Task=`240d04a5-3f1f-4852-a36e-9a671522f4f5`::moving from state init -> state preparing
>MainThread::INFO::2012-08-05 10:17:57,164::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2012-08-05 10:17:57,164::storageServer::617::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>Thread-35::DEBUG::2012-08-05 10:17:57,220::domainMonitor::182::Storage.DomainMonitor::(_monitorDomain) Monitorg for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 is stopping
>Thread-35::INFO::2012-08-05 10:17:57,220::safelease::183::SANLock::(releaseHostId) Releasing host id for domain 1e49d867-4438-4484-a1ca-f6ab7013a319 (id: 1)
>Thread-35::DEBUG::2012-08-05 10:17:57,221::domainMonitor::191::Storage.DomainMonitor::(_monitorDomain) Unable to release the host id 1 for the domain 1e49d867-4438-4484-a1ca-f6ab7013a319
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/domainMonitor.py", line 188, in _monitorDomain
>    domain.releaseHostId(hostId, unused=True)
>  File "/usr/share/vdsm/storage/sd.py", line 426, in releaseHostId
>    self._clusterLock.releaseHostId(hostId, async, unused)
>  File "/usr/share/vdsm/storage/safelease.py", line 190, in releaseHostId
>    raise se.ReleaseHostIdFailure(self._sdUUID, e)
>ReleaseHostIdFailure: Cannot release host id: ('1e49d867-4438-4484-a1ca-f6ab7013a319', SanlockException(16, 'Sanlock lockspace remove failure', 'Device or resource busy'))
>MainThread::DEBUG::2012-08-05 10:17:57,221::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2012-08-05 10:17:57,221::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2012-08-05 10:17:57,221::task::1151::TaskManager.Task::(prepare) Task=`240d04a5-3f1f-4852-a36e-9a671522f4f5`::finished: None
>MainThread::DEBUG::2012-08-05 10:17:57,221::task::568::TaskManager.Task::(_updateState) Task=`240d04a5-3f1f-4852-a36e-9a671522f4f5`::moving from state preparing -> state finished
>MainThread::DEBUG::2012-08-05 10:17:57,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2012-08-05 10:17:57,222::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2012-08-05 10:17:57,222::task::957::TaskManager.Task::(_decref) Task=`240d04a5-3f1f-4852-a36e-9a671522f4f5`::ref 0 aborting False
>MainThread::INFO::2012-08-05 10:17:57,222::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 13 other threads...
>MainThread::INFO::2012-08-05 10:17:57,222::vdsm::79::vds::(run) <_MainThread(MainThread, started 140498355541760)>
>MainThread::INFO::2012-08-05 10:17:57,222::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140498278524672)>
>MainThread::INFO::2012-08-05 10:17:57,222::vdsm::79::vds::(run) <WorkerThread(Thread-6, started daemon 140497775490816)>
>MainThread::INFO::2012-08-05 10:17:57,222::vmChannels::135::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <Listener(VM Channels Listener, started daemon 140497330878208)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-9, started daemon 140497744021248)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-8, started daemon 140497754511104)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-7, started daemon 140497765000960)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-5, started daemon 140498127693568)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-4, started daemon 140498138183424)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-3, started daemon 140498148673280)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(Thread-2, started daemon 140498159163136)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <WorkerThread(bffcf609-c458-434d-a21b-b39d9e2b48b6, started daemon 140498169652992)>
>MainThread::INFO::2012-08-05 10:17:57,223::vdsm::79::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 140497351857920)>
>MainThread::INFO::2012-08-05 10:17:57,224::vdsm::79::vds::(run) <WorkerThread(Thread-10, started daemon 140497733531392)>

Actions: View

Attachments on bug 844398: 601271 | 601901 | 602368