MainThread::INFO::2012-11-26 01:38:04,562::vdsm::70::vds::(run) I am the actual vdsm 4.10-10
MainThread::DEBUG::2012-11-26 01:38:04,912::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-11-26 01:38:04,912::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-11-26 01:38:04,969::multipath::110::Storage.Multipath::(isEnabled) multipath Defaulting to False
MainThread::DEBUG::2012-11-26 01:38:04,970::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/cp /tmp/tmpncuZt5 /etc/multipath.conf' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:04,993::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:04,993::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:05,015::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = ''; <rc> = 1
MainThread::DEBUG::2012-11-26 01:38:05,016::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/sbin/service multipathd restart' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:05,264::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = 'Redirecting to /bin/systemctl restart  multipathd.service\n'; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:05,265::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:05,338::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:05,339::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-11-26 01:38:05,341::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:05,436::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:05,436::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-11-26 01:38:05,436::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-11-26 01:38:05,437::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:05,516::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:05,517::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-11-26 01:38:05,518::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:05,596::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-11-26 01:38:05,597::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-11-26 01:38:05,598::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-11-26 01:38:05,599::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-26 01:38:05,599::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-11-26 01:38:05,599::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-26 01:38:05,600::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:05,613::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-11-26 01:38:05,623::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-11-26 01:38:05,623::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-11-26 01:38:05,624::supervdsm::103::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm [Errno 2] No such file or directory: '/var/run/vdsm/svdsm.pid'
Thread-12::DEBUG::2012-11-26 01:38:05,624::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
Thread-12::DEBUG::2012-11-26 01:38:05,634::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py f797b338-93e4-4e15-90bf-23c45966a8bd 9975' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:05,647::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-11-26 01:38:05,649::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-11-26 01:38:05,663::vmChannels::127::vds::(run) Starting VM channels listener thread.
MainThread::ERROR::2012-11-26 01:38:05,665::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
MainThread::DEBUG::2012-11-26 01:38:05,968::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-11-26 01:38:05,968::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-11-26 01:38:05,968::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-11-26 01:38:05,969::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-11-26 01:38:05,969::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-11-26 01:38:05,969::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-11-26 01:38:05,970::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
Thread-14::DEBUG::2012-11-26 01:38:06,168::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2012-11-26 01:38:06,329::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:06,367::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:06,368::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:06,404::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:06,405::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:06,442::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:06,443::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:06,473::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:06,474::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:06,511::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:06,767::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68'}], 'FC': []}, 'packages2': {'kernel': {'release': '1.fc17.x86_64', 'buildtime': 1350912755.0, 'version': '3.6.3'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'AMD Phenom(tm) 9350e Quad-Core Processor', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '192.168.178.21', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.178.1', 'ports': ['eth0']}}, 'uuid': '409FFD0D-150D-DD11-8933-001FC6D67884_00:1f:c6:d6:78:84', 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': '00:1f:c6:d6:78:84', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '192.168.178.21', 'mtu': '1500'}}, 'software_revision': '10', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,mmx,fxsr,sse,sse2,ht,syscall,nx,mmxext,fxsr_opt,pdpe1gb,rdtscp,lm,3dnowext,3dnow,constant_tsc,rep_good,nopl,nonstop_tsc,extd_apicid,pni,monitor,cx16,popcnt,lahf_lm,cmp_legacy,svm,extapic,cr8_legacy,abm,sse4a,misalignsse,3dnowprefetch,osvw,ibs,hw_pstate,npt,lbrv,svm_lock,model_athlon,model_phenom,model_Opteron_G1', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68', 'netConfigDirty': 'False', 'memSize': '7734', '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': '2005.354', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '0.0.0.0'}}
Thread-15::DEBUG::2012-11-26 01:38:06,931::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-15::DEBUG::2012-11-26 01:38:06,945::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-15::DEBUG::2012-11-26 01:38:06,975::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-11-26 01:38:06,975::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-15::DEBUG::2012-11-26 01:38:07,003::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-11-26 01:38:07,004::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-15::DEBUG::2012-11-26 01:38:07,031::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-11-26 01:38:07,032::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-15::DEBUG::2012-11-26 01:38:07,060::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-11-26 01:38:07,060::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-15::DEBUG::2012-11-26 01:38:07,088::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-11-26 01:38:07,090::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68'}], 'FC': []}, 'packages2': {'kernel': {'release': '1.fc17.x86_64', 'buildtime': 1350912755.0, 'version': '3.6.3'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'AMD Phenom(tm) 9350e Quad-Core Processor', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '192.168.178.21', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.178.1', 'ports': ['eth0']}}, 'uuid': '409FFD0D-150D-DD11-8933-001FC6D67884_00:1f:c6:d6:78:84', 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': '00:1f:c6:d6:78:84', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '192.168.178.21', 'mtu': '1500'}}, 'software_revision': '10', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,mmx,fxsr,sse,sse2,ht,syscall,nx,mmxext,fxsr_opt,pdpe1gb,rdtscp,lm,3dnowext,3dnow,constant_tsc,rep_good,nopl,nonstop_tsc,extd_apicid,pni,monitor,cx16,popcnt,lahf_lm,cmp_legacy,svm,extapic,cr8_legacy,abm,sse4a,misalignsse,3dnowprefetch,osvw,ibs,hw_pstate,npt,lbrv,svm_lock,model_athlon,model_phenom,model_Opteron_G1', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68', 'netConfigDirty': 'False', 'memSize': '7734', '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': '2005.354', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
MainThread::INFO::2012-11-26 01:38:09,187::vdsm::70::vds::(run) I am the actual vdsm 4.10-10
MainThread::DEBUG::2012-11-26 01:38:09,405::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-11-26 01:38:09,406::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-11-26 01:38:09,455::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/kill -9 10082' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:09,480::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 10082: No such process\n'; <rc> = 1
MainThread::DEBUG::2012-11-26 01:38:09,481::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-11-26 01:38:09,481::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 510a9d7d-45c2-46a2-9bce-9f94c7494591 10292' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:09,736::supervdsmServer::306::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-11-26 01:38:09,736::supervdsmServer::310::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-11-26 01:38:09,737::supervdsmServer::313::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-11-26 01:38:09,737::supervdsmServer::317::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-11-26 01:38:09,737::supervdsmServer::321::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-11-26 01:38:09,737::supervdsmServer::327::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-11-26 01:38:09,738::supervdsmServer::338::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-11-26 01:38:11,492::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-11-26 01:38:11,987::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-11-26 01:38:11,988::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-11-26 01:38:11,988::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:12,067::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:12,068::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-11-26 01:38:12,070::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:12,164::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:12,165::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-11-26 01:38:12,165::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-11-26 01:38:12,165::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:12,242::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-11-26 01:38:12,243::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-11-26 01:38:12,243::__init__::1249::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 = [ \\"a%35000000000000279|350000f0009030183%\\", \\"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-11-26 01:38:12,321::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-11-26 01:38:12,322::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-11-26 01:38:12,324::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-11-26 01:38:12,324::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-26 01:38:12,325::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-11-26 01:38:12,325::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-26 01:38:12,325::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-11-26 01:38:12,339::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-11-26 01:38:12,348::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-11-26 01:38:12,349::misc::1063::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-11-26 01:38:12,363::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-11-26 01:38:12,364::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-11-26 01:38:12,366::vmChannels::127::vds::(run) Starting VM channels listener thread.
MainThread::ERROR::2012-11-26 01:38:12,369::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
Thread-14::DEBUG::2012-11-26 01:38:14,046::BindingXMLRPC::859::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2012-11-26 01:38:14,218::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:14,251::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:14,251::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:14,284::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:14,285::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:14,319::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:14,320::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:14,352::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:14,353::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-14::DEBUG::2012-11-26 01:38:14,383::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-11-26 01:38:14,645::BindingXMLRPC::865::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68'}], 'FC': []}, 'packages2': {'kernel': {'release': '1.fc17.x86_64', 'buildtime': 1350912755.0, 'version': '3.6.3'}, 'spice-server': {'release': '5.fc17', 'buildtime': '1336983054', 'version': '0.10.1'}, 'vdsm': {'release': '10.fc17', 'buildtime': '1349383616', 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': '1349654831', 'version': '0.9.11.6'}, 'qemu-img': {'release': '2.fc17', 'buildtime': '1349642820', 'version': '1.0.1'}}, 'cpuModel': 'AMD Phenom(tm) 9350e Quad-Core Processor', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '192.168.178.21', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'dhcp', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.178.1', 'ports': ['eth0']}}, 'uuid': '409FFD0D-150D-DD11-8933-001FC6D67884_00:1f:c6:d6:78:84', 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': '00:1f:c6:d6:78:84', 'netmask': '255.255.255.0', 'speed': 100, 'addr': '192.168.178.21', 'mtu': '1500'}}, 'software_revision': '10', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,mmx,fxsr,sse,sse2,ht,syscall,nx,mmxext,fxsr_opt,pdpe1gb,rdtscp,lm,3dnowext,3dnow,constant_tsc,rep_good,nopl,nonstop_tsc,extd_apicid,pni,monitor,cx16,popcnt,lahf_lm,cmp_legacy,svm,extapic,cr8_legacy,abm,sse4a,misalignsse,3dnowprefetch,osvw,ibs,hw_pstate,npt,lbrv,svm_lock,model_athlon,model_phenom,model_Opteron_G1', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:a9c2f9fb4b68', 'netConfigDirty': 'False', 'memSize': '7734', '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': '2005.354', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '17', 'name': 'Fedora'}, 'lastClient': '0.0.0.0'}}
Thread-12::DEBUG::2012-11-26 01:38:15,668::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-11-26 01:38:18,670::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-11-26 01:38:18,704::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,704::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,705::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,705::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,705::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,705::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-26 01:38:18,705::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-11-26 01:38:18,706::hsm::362::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-11-26 01:38:18,712::hsm::394::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-11-26 01:38:18,712::hsm::395::Storage.HSM::(__cleanStorageRepository) Mount list: []
Thread-12::DEBUG::2012-11-26 01:38:18,713::hsm::397::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-11-26 01:38:18,714::hsm::440::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
Thread-20::DEBUG::2012-11-26 01:38:29,007::task::588::TaskManager.Task::(_updateState) Task=`74c694f9-cd0c-411d-9ed7-6b80cfbd7ce1`::moving from state init -> state preparing
Thread-20::INFO::2012-11-26 01:38:29,007::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-20::INFO::2012-11-26 01:38:29,008::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-20::DEBUG::2012-11-26 01:38:29,008::task::1172::TaskManager.Task::(prepare) Task=`74c694f9-cd0c-411d-9ed7-6b80cfbd7ce1`::finished: {}
Thread-20::DEBUG::2012-11-26 01:38:29,008::task::588::TaskManager.Task::(_updateState) Task=`74c694f9-cd0c-411d-9ed7-6b80cfbd7ce1`::moving from state preparing -> state finished
Thread-20::DEBUG::2012-11-26 01:38:29,008::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-20::DEBUG::2012-11-26 01:38:29,008::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-20::DEBUG::2012-11-26 01:38:29,008::task::978::TaskManager.Task::(_decref) Task=`74c694f9-cd0c-411d-9ed7-6b80cfbd7ce1`::ref 0 aborting False
Thread-26::DEBUG::2012-11-26 01:38:40,103::task::588::TaskManager.Task::(_updateState) Task=`4c0d93f6-7885-4c17-9db1-74f169e8e690`::moving from state init -> state preparing
Thread-26::INFO::2012-11-26 01:38:40,103::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-26::INFO::2012-11-26 01:38:40,103::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-26::DEBUG::2012-11-26 01:38:40,103::task::1172::TaskManager.Task::(prepare) Task=`4c0d93f6-7885-4c17-9db1-74f169e8e690`::finished: {}
Thread-26::DEBUG::2012-11-26 01:38:40,104::task::588::TaskManager.Task::(_updateState) Task=`4c0d93f6-7885-4c17-9db1-74f169e8e690`::moving from state preparing -> state finished
Thread-26::DEBUG::2012-11-26 01:38:40,104::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-26::DEBUG::2012-11-26 01:38:40,104::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-26::DEBUG::2012-11-26 01:38:40,104::task::978::TaskManager.Task::(_decref) Task=`4c0d93f6-7885-4c17-9db1-74f169e8e690`::ref 0 aborting False
Thread-32::DEBUG::2012-11-26 01:38:50,340::task::588::TaskManager.Task::(_updateState) Task=`f8a350d4-8308-4ce7-a3f3-3b39a359d538`::moving from state init -> state preparing
Thread-32::INFO::2012-11-26 01:38:50,340::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-32::INFO::2012-11-26 01:38:50,340::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-32::DEBUG::2012-11-26 01:38:50,340::task::1172::TaskManager.Task::(prepare) Task=`f8a350d4-8308-4ce7-a3f3-3b39a359d538`::finished: {}
Thread-32::DEBUG::2012-11-26 01:38:50,341::task::588::TaskManager.Task::(_updateState) Task=`f8a350d4-8308-4ce7-a3f3-3b39a359d538`::moving from state preparing -> state finished
Thread-32::DEBUG::2012-11-26 01:38:50,341::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-32::DEBUG::2012-11-26 01:38:50,341::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-32::DEBUG::2012-11-26 01:38:50,341::task::978::TaskManager.Task::(_decref) Task=`f8a350d4-8308-4ce7-a3f3-3b39a359d538`::ref 0 aborting False
Thread-38::DEBUG::2012-11-26 01:39:00,583::task::588::TaskManager.Task::(_updateState) Task=`282043a5-7113-44ea-88b3-365f165e2ea9`::moving from state init -> state preparing
Thread-38::INFO::2012-11-26 01:39:00,584::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-38::INFO::2012-11-26 01:39:00,584::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-38::DEBUG::2012-11-26 01:39:00,584::task::1172::TaskManager.Task::(prepare) Task=`282043a5-7113-44ea-88b3-365f165e2ea9`::finished: {}
Thread-38::DEBUG::2012-11-26 01:39:00,584::task::588::TaskManager.Task::(_updateState) Task=`282043a5-7113-44ea-88b3-365f165e2ea9`::moving from state preparing -> state finished
Thread-38::DEBUG::2012-11-26 01:39:00,584::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-38::DEBUG::2012-11-26 01:39:00,585::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-38::DEBUG::2012-11-26 01:39:00,585::task::978::TaskManager.Task::(_decref) Task=`282043a5-7113-44ea-88b3-365f165e2ea9`::ref 0 aborting False
Thread-44::DEBUG::2012-11-26 01:39:10,824::task::588::TaskManager.Task::(_updateState) Task=`a2b56266-1bb6-4e7f-8349-5f2c91e64775`::moving from state init -> state preparing
Thread-44::INFO::2012-11-26 01:39:10,824::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-44::INFO::2012-11-26 01:39:10,824::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-44::DEBUG::2012-11-26 01:39:10,824::task::1172::TaskManager.Task::(prepare) Task=`a2b56266-1bb6-4e7f-8349-5f2c91e64775`::finished: {}
Thread-44::DEBUG::2012-11-26 01:39:10,825::task::588::TaskManager.Task::(_updateState) Task=`a2b56266-1bb6-4e7f-8349-5f2c91e64775`::moving from state preparing -> state finished
Thread-44::DEBUG::2012-11-26 01:39:10,825::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-44::DEBUG::2012-11-26 01:39:10,825::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-44::DEBUG::2012-11-26 01:39:10,825::task::978::TaskManager.Task::(_decref) Task=`a2b56266-1bb6-4e7f-8349-5f2c91e64775`::ref 0 aborting False
Thread-50::DEBUG::2012-11-26 01:39:21,071::task::588::TaskManager.Task::(_updateState) Task=`62ce062a-9418-44c2-8b63-0083656d6ab6`::moving from state init -> state preparing
Thread-50::INFO::2012-11-26 01:39:21,072::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-50::INFO::2012-11-26 01:39:21,072::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-50::DEBUG::2012-11-26 01:39:21,072::task::1172::TaskManager.Task::(prepare) Task=`62ce062a-9418-44c2-8b63-0083656d6ab6`::finished: {}
Thread-50::DEBUG::2012-11-26 01:39:21,072::task::588::TaskManager.Task::(_updateState) Task=`62ce062a-9418-44c2-8b63-0083656d6ab6`::moving from state preparing -> state finished
Thread-50::DEBUG::2012-11-26 01:39:21,072::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-50::DEBUG::2012-11-26 01:39:21,072::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-50::DEBUG::2012-11-26 01:39:21,072::task::978::TaskManager.Task::(_decref) Task=`62ce062a-9418-44c2-8b63-0083656d6ab6`::ref 0 aborting False
Thread-56::DEBUG::2012-11-26 01:39:33,533::task::588::TaskManager.Task::(_updateState) Task=`5860b5d0-7db1-43fe-881a-59549b2f2c3d`::moving from state init -> state preparing
Thread-56::INFO::2012-11-26 01:39:33,534::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-56::INFO::2012-11-26 01:39:33,534::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-56::DEBUG::2012-11-26 01:39:33,534::task::1172::TaskManager.Task::(prepare) Task=`5860b5d0-7db1-43fe-881a-59549b2f2c3d`::finished: {}
Thread-56::DEBUG::2012-11-26 01:39:33,534::task::588::TaskManager.Task::(_updateState) Task=`5860b5d0-7db1-43fe-881a-59549b2f2c3d`::moving from state preparing -> state finished
Thread-56::DEBUG::2012-11-26 01:39:33,534::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-56::DEBUG::2012-11-26 01:39:33,534::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-56::DEBUG::2012-11-26 01:39:33,534::task::978::TaskManager.Task::(_decref) Task=`5860b5d0-7db1-43fe-881a-59549b2f2c3d`::ref 0 aborting False
Thread-62::DEBUG::2012-11-26 01:39:47,548::task::588::TaskManager.Task::(_updateState) Task=`397dee10-5661-40e0-a66d-8d200b8ab46a`::moving from state init -> state preparing
Thread-62::INFO::2012-11-26 01:39:47,548::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-62::INFO::2012-11-26 01:39:47,548::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-62::DEBUG::2012-11-26 01:39:47,549::task::1172::TaskManager.Task::(prepare) Task=`397dee10-5661-40e0-a66d-8d200b8ab46a`::finished: {}
Thread-62::DEBUG::2012-11-26 01:39:47,549::task::588::TaskManager.Task::(_updateState) Task=`397dee10-5661-40e0-a66d-8d200b8ab46a`::moving from state preparing -> state finished
Thread-62::DEBUG::2012-11-26 01:39:47,549::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-62::DEBUG::2012-11-26 01:39:47,549::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-62::DEBUG::2012-11-26 01:39:47,549::task::978::TaskManager.Task::(_decref) Task=`397dee10-5661-40e0-a66d-8d200b8ab46a`::ref 0 aborting False
Thread-68::DEBUG::2012-11-26 01:39:57,791::task::588::TaskManager.Task::(_updateState) Task=`6de3971e-9b24-4953-9732-b734c0cee828`::moving from state init -> state preparing
Thread-68::INFO::2012-11-26 01:39:57,791::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-68::INFO::2012-11-26 01:39:57,791::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-68::DEBUG::2012-11-26 01:39:57,791::task::1172::TaskManager.Task::(prepare) Task=`6de3971e-9b24-4953-9732-b734c0cee828`::finished: {}
Thread-68::DEBUG::2012-11-26 01:39:57,791::task::588::TaskManager.Task::(_updateState) Task=`6de3971e-9b24-4953-9732-b734c0cee828`::moving from state preparing -> state finished
Thread-68::DEBUG::2012-11-26 01:39:57,792::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-68::DEBUG::2012-11-26 01:39:57,792::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-68::DEBUG::2012-11-26 01:39:57,792::task::978::TaskManager.Task::(_decref) Task=`6de3971e-9b24-4953-9732-b734c0cee828`::ref 0 aborting False
Thread-74::DEBUG::2012-11-26 01:40:08,047::task::588::TaskManager.Task::(_updateState) Task=`eeafeee4-811c-42d9-ad7a-14f5e6b939c4`::moving from state init -> state preparing
Thread-74::INFO::2012-11-26 01:40:08,047::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-74::INFO::2012-11-26 01:40:08,047::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-74::DEBUG::2012-11-26 01:40:08,048::task::1172::TaskManager.Task::(prepare) Task=`eeafeee4-811c-42d9-ad7a-14f5e6b939c4`::finished: {}
Thread-74::DEBUG::2012-11-26 01:40:08,048::task::588::TaskManager.Task::(_updateState) Task=`eeafeee4-811c-42d9-ad7a-14f5e6b939c4`::moving from state preparing -> state finished
Thread-74::DEBUG::2012-11-26 01:40:08,048::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-74::DEBUG::2012-11-26 01:40:08,048::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-74::DEBUG::2012-11-26 01:40:08,048::task::978::TaskManager.Task::(_decref) Task=`eeafeee4-811c-42d9-ad7a-14f5e6b939c4`::ref 0 aborting False
Thread-80::DEBUG::2012-11-26 01:40:19,656::task::588::TaskManager.Task::(_updateState) Task=`31a84536-f072-4f18-af4c-7c2bc367c2c4`::moving from state init -> state preparing
Thread-80::INFO::2012-11-26 01:40:19,656::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-80::INFO::2012-11-26 01:40:19,656::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-80::DEBUG::2012-11-26 01:40:19,656::task::1172::TaskManager.Task::(prepare) Task=`31a84536-f072-4f18-af4c-7c2bc367c2c4`::finished: {}
Thread-80::DEBUG::2012-11-26 01:40:19,656::task::588::TaskManager.Task::(_updateState) Task=`31a84536-f072-4f18-af4c-7c2bc367c2c4`::moving from state preparing -> state finished
Thread-80::DEBUG::2012-11-26 01:40:19,657::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-80::DEBUG::2012-11-26 01:40:19,657::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-80::DEBUG::2012-11-26 01:40:19,657::task::978::TaskManager.Task::(_decref) Task=`31a84536-f072-4f18-af4c-7c2bc367c2c4`::ref 0 aborting False
Thread-86::DEBUG::2012-11-26 01:40:32,951::task::588::TaskManager.Task::(_updateState) Task=`b8571e71-b9fa-4564-8b97-dfec9a2aa021`::moving from state init -> state preparing
Thread-86::INFO::2012-11-26 01:40:32,952::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-86::INFO::2012-11-26 01:40:32,952::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-86::DEBUG::2012-11-26 01:40:32,952::task::1172::TaskManager.Task::(prepare) Task=`b8571e71-b9fa-4564-8b97-dfec9a2aa021`::finished: {}
Thread-86::DEBUG::2012-11-26 01:40:32,952::task::588::TaskManager.Task::(_updateState) Task=`b8571e71-b9fa-4564-8b97-dfec9a2aa021`::moving from state preparing -> state finished
Thread-86::DEBUG::2012-11-26 01:40:32,952::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-86::DEBUG::2012-11-26 01:40:32,952::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-86::DEBUG::2012-11-26 01:40:32,952::task::978::TaskManager.Task::(_decref) Task=`b8571e71-b9fa-4564-8b97-dfec9a2aa021`::ref 0 aborting False
Thread-92::DEBUG::2012-11-26 01:40:43,230::task::588::TaskManager.Task::(_updateState) Task=`e9559eb3-5a39-4363-bd6d-85980be8c175`::moving from state init -> state preparing
Thread-92::INFO::2012-11-26 01:40:43,230::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-92::INFO::2012-11-26 01:40:43,230::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-92::DEBUG::2012-11-26 01:40:43,230::task::1172::TaskManager.Task::(prepare) Task=`e9559eb3-5a39-4363-bd6d-85980be8c175`::finished: {}
Thread-92::DEBUG::2012-11-26 01:40:43,230::task::588::TaskManager.Task::(_updateState) Task=`e9559eb3-5a39-4363-bd6d-85980be8c175`::moving from state preparing -> state finished
Thread-92::DEBUG::2012-11-26 01:40:43,230::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-92::DEBUG::2012-11-26 01:40:43,231::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-92::DEBUG::2012-11-26 01:40:43,231::task::978::TaskManager.Task::(_decref) Task=`e9559eb3-5a39-4363-bd6d-85980be8c175`::ref 0 aborting False
Thread-98::DEBUG::2012-11-26 01:40:53,567::task::588::TaskManager.Task::(_updateState) Task=`1c6a8e85-e44a-4a9e-87a5-e25d98cd7f11`::moving from state init -> state preparing
Thread-98::INFO::2012-11-26 01:40:54,142::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-98::INFO::2012-11-26 01:40:54,142::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-98::DEBUG::2012-11-26 01:40:54,142::task::1172::TaskManager.Task::(prepare) Task=`1c6a8e85-e44a-4a9e-87a5-e25d98cd7f11`::finished: {}
Thread-98::DEBUG::2012-11-26 01:40:54,142::task::588::TaskManager.Task::(_updateState) Task=`1c6a8e85-e44a-4a9e-87a5-e25d98cd7f11`::moving from state preparing -> state finished
Thread-98::DEBUG::2012-11-26 01:40:54,142::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-98::DEBUG::2012-11-26 01:40:54,143::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-98::DEBUG::2012-11-26 01:40:54,143::task::978::TaskManager.Task::(_decref) Task=`1c6a8e85-e44a-4a9e-87a5-e25d98cd7f11`::ref 0 aborting False
Thread-104::DEBUG::2012-11-26 01:41:04,360::task::588::TaskManager.Task::(_updateState) Task=`ba4d98f6-abae-48df-bcac-42a198592538`::moving from state init -> state preparing
Thread-104::INFO::2012-11-26 01:41:04,360::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-104::INFO::2012-11-26 01:41:04,361::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-104::DEBUG::2012-11-26 01:41:04,361::task::1172::TaskManager.Task::(prepare) Task=`ba4d98f6-abae-48df-bcac-42a198592538`::finished: {}
Thread-104::DEBUG::2012-11-26 01:41:04,361::task::588::TaskManager.Task::(_updateState) Task=`ba4d98f6-abae-48df-bcac-42a198592538`::moving from state preparing -> state finished
Thread-104::DEBUG::2012-11-26 01:41:04,361::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-104::DEBUG::2012-11-26 01:41:04,361::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-104::DEBUG::2012-11-26 01:41:04,361::task::978::TaskManager.Task::(_decref) Task=`ba4d98f6-abae-48df-bcac-42a198592538`::ref 0 aborting False
Thread-110::DEBUG::2012-11-26 01:41:14,593::task::588::TaskManager.Task::(_updateState) Task=`7325cd3b-cba3-42a0-a0e7-92af89cab20f`::moving from state init -> state preparing
Thread-110::INFO::2012-11-26 01:41:14,593::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-110::INFO::2012-11-26 01:41:14,594::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-110::DEBUG::2012-11-26 01:41:14,594::task::1172::TaskManager.Task::(prepare) Task=`7325cd3b-cba3-42a0-a0e7-92af89cab20f`::finished: {}
Thread-110::DEBUG::2012-11-26 01:41:14,594::task::588::TaskManager.Task::(_updateState) Task=`7325cd3b-cba3-42a0-a0e7-92af89cab20f`::moving from state preparing -> state finished
Thread-110::DEBUG::2012-11-26 01:41:14,594::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-110::DEBUG::2012-11-26 01:41:14,594::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-110::DEBUG::2012-11-26 01:41:14,594::task::978::TaskManager.Task::(_decref) Task=`7325cd3b-cba3-42a0-a0e7-92af89cab20f`::ref 0 aborting False
Thread-116::DEBUG::2012-11-26 01:41:27,282::task::588::TaskManager.Task::(_updateState) Task=`b870c8d9-f727-488a-83ad-869b75901988`::moving from state init -> state preparing
Thread-116::INFO::2012-11-26 01:41:27,282::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-116::INFO::2012-11-26 01:41:27,282::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-116::DEBUG::2012-11-26 01:41:27,282::task::1172::TaskManager.Task::(prepare) Task=`b870c8d9-f727-488a-83ad-869b75901988`::finished: {}
Thread-116::DEBUG::2012-11-26 01:41:27,283::task::588::TaskManager.Task::(_updateState) Task=`b870c8d9-f727-488a-83ad-869b75901988`::moving from state preparing -> state finished
Thread-116::DEBUG::2012-11-26 01:41:27,283::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-116::DEBUG::2012-11-26 01:41:27,283::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-116::DEBUG::2012-11-26 01:41:27,283::task::978::TaskManager.Task::(_decref) Task=`b870c8d9-f727-488a-83ad-869b75901988`::ref 0 aborting False
Thread-122::DEBUG::2012-11-26 01:41:38,885::task::588::TaskManager.Task::(_updateState) Task=`4d59d462-9493-4abf-b22c-38b229b6c3a0`::moving from state init -> state preparing
Thread-122::INFO::2012-11-26 01:41:38,885::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-122::INFO::2012-11-26 01:41:38,885::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-122::DEBUG::2012-11-26 01:41:38,885::task::1172::TaskManager.Task::(prepare) Task=`4d59d462-9493-4abf-b22c-38b229b6c3a0`::finished: {}
Thread-122::DEBUG::2012-11-26 01:41:38,885::task::588::TaskManager.Task::(_updateState) Task=`4d59d462-9493-4abf-b22c-38b229b6c3a0`::moving from state preparing -> state finished
Thread-122::DEBUG::2012-11-26 01:41:38,886::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-122::DEBUG::2012-11-26 01:41:38,886::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-122::DEBUG::2012-11-26 01:41:38,886::task::978::TaskManager.Task::(_decref) Task=`4d59d462-9493-4abf-b22c-38b229b6c3a0`::ref 0 aborting False
MainThread::INFO::2012-11-26 01:41:49,549::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::DEBUG::2012-11-26 01:41:49,551::task::588::TaskManager.Task::(_updateState) Task=`a8c4b219-2b5a-47f3-8b07-7688f4e41322`::moving from state init -> state preparing
MainThread::INFO::2012-11-26 01:41:49,551::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2012-11-26 01:41:49,554::storageServer::617::ConnectionMonitor::(_monitorConnections) Monitoring stopped
MainThread::DEBUG::2012-11-26 01:41:49,578::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2012-11-26 01:41:49,578::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2012-11-26 01:41:49,578::task::1172::TaskManager.Task::(prepare) Task=`a8c4b219-2b5a-47f3-8b07-7688f4e41322`::finished: None
MainThread::DEBUG::2012-11-26 01:41:49,578::task::588::TaskManager.Task::(_updateState) Task=`a8c4b219-2b5a-47f3-8b07-7688f4e41322`::moving from state preparing -> state finished
MainThread::DEBUG::2012-11-26 01:41:49,579::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2012-11-26 01:41:49,579::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2012-11-26 01:41:49,579::task::978::TaskManager.Task::(_decref) Task=`a8c4b219-2b5a-47f3-8b07-7688f4e41322`::ref 0 aborting False
MainThread::INFO::2012-11-26 01:41:49,579::vdsm::75::vds::(run) VDSM main thread ended. Waiting for 13 other threads...
MainThread::INFO::2012-11-26 01:41:49,579::vdsm::78::vds::(run) <_MainThread(MainThread, started 140315094943552)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <Thread(libvirtEventLoop, started daemon 140314810078976)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <WorkerThread(Thread-6, started daemon 140314668939008)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <WorkerThread(Thread-5, started daemon 140314677331712)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <WorkerThread(Thread-1, started daemon 140314780411648)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <WorkerThread(Thread-10, started daemon 140314090137344)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 140314056566528)>
MainThread::INFO::2012-11-26 01:41:49,580::vdsm::78::vds::(run) <WorkerThread(Thread-3, started daemon 140314694117120)>
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <WorkerThread(Thread-2, started daemon 140314702509824)>
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <WorkerThread(Thread-7, started daemon 140314660546304)>
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <WorkerThread(Thread-9, started daemon 140314098530048)>
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <WorkerThread(Thread-8, started daemon 140314652153600)>
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <WorkerThread(Thread-4, started daemon 140314685724416)>
MainThread::INFO::2012-11-26 01:41:49,581::vmChannels::135::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2012-11-26 01:41:49,581::vdsm::78::vds::(run) <Listener(VM Channels Listener, started daemon 140313561659136)>