MainThread::INFO::2012-05-11 14:46:01,783::vdsm::70::vds::(run) I am the actual vdsm 4.9-0
MainThread::DEBUG::2012-05-11 14:46:01,937::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-05-11 14:46:01,937::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2012-05-11 14:46:01,953::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/kill -9 28103' (cwd None)
MainThread::DEBUG::2012-05-11 14:46:01,962::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'kill 28103: No such process\n'; <rc> = 1
MainThread::DEBUG::2012-05-11 14:46:01,963::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm
MainThread::DEBUG::2012-05-11 14:46:01,963::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 23250a38-2722-40cf-9ade-f8a7c1d41ba8 9290' (cwd None)
MainThread::DEBUG::2012-05-11 14:46:02,109::supervdsmServer::261::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-05-11 14:46:02,109::supervdsmServer::265::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-05-11 14:46:02,109::supervdsmServer::268::SuperVdsm.Server::(main) Creating PID file
MainThread::DEBUG::2012-05-11 14:46:02,110::supervdsmServer::272::SuperVdsm.Server::(main) Cleaning old socket
MainThread::DEBUG::2012-05-11 14:46:02,110::supervdsmServer::276::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-05-11 14:46:02,110::supervdsmServer::282::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-05-11 14:46:02,111::supervdsmServer::293::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-05-11 14:46:03,969::supervdsm::113::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-05-11 14:46:03,974::supervdsm::84::SuperVdsmProxy::(__init__) Connected to Super Vdsm
MainThread::DEBUG::2012-05-11 14:46:03,975::multipath::102::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-05-11 14:46:03,975::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-05-11 14:46:03,986::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-11 14:46:03,987::lvm::335::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-11 14:46:03,988::__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-05-11 14:46:04,006::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-05-11 14:46:04,006::lvm::358::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-11 14:46:04,006::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
MainThread::DEBUG::2012-05-11 14:46:04,007::__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-05-11 14:46:04,021::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
MainThread::DEBUG::2012-05-11 14:46:04,021::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
MainThread::DEBUG::2012-05-11 14:46:04,022::__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-05-11 14:46:04,035::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
Thread-12::DEBUG::2012-05-11 14:46:04,036::misc::1068::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2012-05-11 14:46:04,038::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-05-11 14:46:04,038::misc::1070::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-11 14:46:04,039::misc::1068::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-05-11 14:46:04,039::misc::1070::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-05-11 14:46:04,041::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
MainThread::DEBUG::2012-05-11 14:46:04,047::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None)
Thread-12::DEBUG::2012-05-11 14:46:04,055::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-05-11 14:46:04,055::misc::1078::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2012-05-11 14:46:04,060::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
MainThread::INFO::2012-05-11 14:46:04,061::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-05-11 14:46:04,061::vmChannels::127::vds::(run) Starting VM channels listener thread.
Thread-12::DEBUG::2012-05-11 14:46:05,989::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-05-11 14:46:06,034::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-05-11 14:46:06,034::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,035::lvm::478::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,035::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,035::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,035::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,036::lvm::511::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-05-11 14:46:06,036::misc::1078::SamplingMethod::(__call__) Returning last result
Thread-12::DEBUG::2012-05-11 14:46:06,036::hsm::360::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
Thread-12::DEBUG::2012-05-11 14:46:06,037::hsm::392::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
Thread-12::DEBUG::2012-05-11 14:46:06,037::hsm::393::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/cmcd-heilig.in.hwlab:_exports_iso']
Thread-12::DEBUG::2012-05-11 14:46:06,038::hsm::395::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
Thread-12::DEBUG::2012-05-11 14:46:06,038::hsm::438::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
Thread-14::DEBUG::2012-05-11 14:46:12,314::BindingXMLRPC::864::vds::(wrapper) client [10.0.8.19]::call getCapabilities with () {} flowID [6ffec560]
Thread-14::DEBUG::2012-05-11 14:46:12,407::__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-05-11 14:46:12,423::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-11 14:46:12,424::__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-05-11 14:46:12,440::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-11 14:46:12,441::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-14::DEBUG::2012-05-11 14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-11 14:46:12,456::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-14::DEBUG::2012-05-11 14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-11 14:46:12,471::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-14::DEBUG::2012-05-11 14:46:12,487::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2012-05-11 14:46:12,693::BindingXMLRPC::870::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], 'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', 'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': {'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, 'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', 'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', 'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': {'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': '0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': '1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 Quad CPU    Q9650  @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', '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': '10.0.10.254', 'ports': ['eth0']}}, 'uuid': '295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': '00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', '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,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexpriority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', '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.9', 'cpuSpeed': '2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': 'oVirt Node'}, 'lastClient': '0.0.0.0'}}
Thread-15::DEBUG::2012-05-11 14:46:13,984::BindingXMLRPC::864::vds::(wrapper) client [10.0.8.19]::call getCapabilities with () {} flowID [51e33141]
Thread-15::DEBUG::2012-05-11 14:46:13,998::__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-05-11 14:46:14,015::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-11 14:46:14,016::__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-05-11 14:46:14,032::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-11 14:46:14,033::__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-05-11 14:46:14,048::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-11 14:46:14,048::__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-05-11 14:46:14,063::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-11 14:46:14,064::__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-05-11 14:46:14,079::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-15::DEBUG::2012-05-11 14:46:14,080::BindingXMLRPC::870::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633'}], 'FC': []}, 'packages2': {'kernel': {'release': '220.13.1.el6.x86_64', 'buildtime': 1334721394.0, 'version': '2.6.32'}, 'spice-server': {'release': '5.el6', 'buildtime': '1323304307', 'version': '0.8.2'}, 'vdsm': {'release': '0.150.git63061a9.el6', 'buildtime': '1335602535', 'version': '4.9.6'}, 'qemu-kvm': {'release': '2.209.el6_2.4', 'buildtime': '1327354003', 'version': '0.12.1.2'}, 'libvirt': {'release': '23.el6_2.8', 'buildtime': '1334928354', 'version': '0.9.4'}, 'qemu-img': {'release': '2.209.el6_2.4', 'buildtime': '1327354003', 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Core(TM)2 Quad CPU    Q9650  @ 3.00GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '10.0.10.18', 'cfg': {'IPV6INIT': 'yes', 'MTU': '1500', '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': '10.0.10.254', 'ports': ['eth0']}}, 'uuid': '295894AA-8E10-4A53-9090-002128263408_00:21:28:26:34:08', 'lastClientIface': 'ovirtmgmt', 'nics': {'eth0': {'hwaddr': '00:21:28:26:34:08', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', '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,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,sse4_1,xsave,lahf_lm,dts,tpr_shadow,vnmi,flexpriority,model_Conroe,model_Penryn', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:7d1774a24633', 'memSize': '1989', '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.9', 'cpuSpeed': '2997.678', 'cpuSockets': '1', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.2.0', u'pc', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '2.el6.centos.7', 'version': '6', 'name': 'oVirt Node'}, 'lastClient': '10.0.8.19'}}
Thread-17::DEBUG::2012-05-11 14:46:14,243::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-17::DEBUG::2012-05-11 14:46:14,244::task::588::TaskManager.Task::(_updateState) Task=`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state init -> state preparing
Thread-17::INFO::2012-05-11 14:46:14,244::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='af5bcc86-898a-11e1-9632-003048c85226', conList=[{'connection': 'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', 'port': ''}], options=None)
Thread-17::INFO::2012-05-11 14:46:14,244::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-17::DEBUG::2012-05-11 14:46:14,245::task::1172::TaskManager.Task::(prepare) Task=`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::finished: {'statuslist': [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-17::DEBUG::2012-05-11 14:46:14,245::task::588::TaskManager.Task::(_updateState) Task=`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::moving from state preparing -> state finished
Thread-17::DEBUG::2012-05-11 14:46:14,245::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-17::DEBUG::2012-05-11 14:46:14,245::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-17::DEBUG::2012-05-11 14:46:14,246::task::978::TaskManager.Task::(_decref) Task=`9bdb36c0-1acc-486f-a21b-6559a5aaefff`::ref 0 aborting False
Thread-18::DEBUG::2012-05-11 14:46:14,256::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-18::DEBUG::2012-05-11 14:46:14,256::task::588::TaskManager.Task::(_updateState) Task=`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state init -> state preparing
Thread-18::INFO::2012-05-11 14:46:14,257::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='af5bcc86-898a-11e1-9632-003048c85226', conList=[{'connection': 'cmcd-heilig.in.hwlab:/exports/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226', 'port': ''}], options=None)
Thread-18::DEBUG::2012-05-11 14:46:14,257::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 14:46:14,258::lvm::478::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-05-11 14:46:14,258::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 14:46:14,258::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-18::DEBUG::2012-05-11 14:46:14,258::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-18::DEBUG::2012-05-11 14:46:14,259::lvm::511::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-18::INFO::2012-05-11 14:46:14,259::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-18::DEBUG::2012-05-11 14:46:14,259::task::1172::TaskManager.Task::(prepare) Task=`3b868a60-fa19-4fb6-a52d-21caecc9435d`::finished: {'statuslist': [{'status': 0, 'id': 'd3f7bc58-898a-11e1-acd5-003048c85226'}]}
Thread-18::DEBUG::2012-05-11 14:46:14,259::task::588::TaskManager.Task::(_updateState) Task=`3b868a60-fa19-4fb6-a52d-21caecc9435d`::moving from state preparing -> state finished
Thread-18::DEBUG::2012-05-11 14:46:14,260::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2012-05-11 14:46:14,260::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18::DEBUG::2012-05-11 14:46:14,260::task::978::TaskManager.Task::(_decref) Task=`3b868a60-fa19-4fb6-a52d-21caecc9435d`::ref 0 aborting False
Thread-19::DEBUG::2012-05-11 14:46:14,277::BindingXMLRPC::164::vds::(wrapper) [10.0.8.19]
Thread-19::DEBUG::2012-05-11 14:46:14,278::task::588::TaskManager.Task::(_updateState) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state init -> state preparing
Thread-19::INFO::2012-05-11 14:46:14,278::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='af5bcc86-898a-11e1-9632-003048c85226', hostID=2, scsiKey='af5bcc86-898a-11e1-9632-003048c85226', msdUUID='e12a0f53-ee72-44bc-ad26-93f9b4613c6c', masterVersion=1, options=None)
Thread-19::DEBUG::2012-05-11 14:46:14,278::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=`cdef54e1-af49-4429-aecb-4d0dbf971fb5`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
Thread-19::DEBUG::2012-05-11 14:46:14,279::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' for lock type 'exclusive'
Thread-19::DEBUG::2012-05-11 14:46:14,279::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free. Now locking as 'exclusive' (1 active user)
Thread-19::DEBUG::2012-05-11 14:46:14,279::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.af5bcc86-898a-11e1-9632-003048c85226`ReqID=`cdef54e1-af49-4429-aecb-4d0dbf971fb5`::Granted request
Thread-19::INFO::2012-05-11 14:46:14,280::sp::625::Storage.StoragePool::(connect) Connect host #2 to the storage pool af5bcc86-898a-11e1-9632-003048c85226 with master domain: e12a0f53-ee72-44bc-ad26-93f9b4613c6c (ver = 1)
Thread-19::DEBUG::2012-05-11 14:46:14,280::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,280::lvm::478::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,281::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,281::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,281::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,281::lvm::511::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:14,281::misc::1068::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-19::DEBUG::2012-05-11 14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2012-05-11 14:46:14,282::misc::1068::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-19::DEBUG::2012-05-11 14:46:14,282::misc::1070::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2012-05-11 14:46:14,282::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-19::DEBUG::2012-05-11 14:46:14,293::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-19::DEBUG::2012-05-11 14:46:14,294::misc::1078::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2012-05-11 14:46:16,226::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-19::DEBUG::2012-05-11 14:46:16,308::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-19::DEBUG::2012-05-11 14:46:16,309::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,309::lvm::478::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,309::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,309::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,310::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,310::lvm::511::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,310::misc::1078::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2012-05-11 14:46:16,310::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,311::__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 e12a0f53-ee72-44bc-ad26-93f9b4613c6c' (cwd None)
Thread-19::DEBUG::2012-05-11 14:46:16,328::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found\n'; <rc> = 5
Thread-19::WARNING::2012-05-11 14:46:16,328::lvm::372::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "e12a0f53-ee72-44bc-ad26-93f9b4613c6c" not found']
Thread-19::DEBUG::2012-05-11 14:46:16,329::lvm::395::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-19::DEBUG::2012-05-11 14:46:16,833::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226'
Thread-19::DEBUG::2012-05-11 14:46:16,834::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' (0 active users)
Thread-19::DEBUG::2012-05-11 14:46:16,834::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226' is free, finding out if anyone is waiting for it.
Thread-19::DEBUG::2012-05-11 14:46:16,834::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.af5bcc86-898a-11e1-9632-003048c85226', Clearing records.
Thread-19::ERROR::2012-05-11 14:46:16,835::task::853::TaskManager.Task::(_setError) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 861, 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 815, in connectStoragePool
    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 857, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=af5bcc86-898a-11e1-9632-003048c85226, msdUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c'
Thread-19::DEBUG::2012-05-11 14:46:16,837::task::872::TaskManager.Task::(_run) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::Task._run: 5616c854-e704-4014-bb58-8ca757e8137f ('af5bcc86-898a-11e1-9632-003048c85226', 2, 'af5bcc86-898a-11e1-9632-003048c85226', 'e12a0f53-ee72-44bc-ad26-93f9b4613c6c', 1) {} failed - stopping task
Thread-19::DEBUG::2012-05-11 14:46:16,837::task::1199::TaskManager.Task::(stop) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::stopping in state preparing (force False)
Thread-19::DEBUG::2012-05-11 14:46:16,838::task::978::TaskManager.Task::(_decref) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::ref 1 aborting True
Thread-19::INFO::2012-05-11 14:46:16,838::task::1157::TaskManager.Task::(prepare) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::aborting: Task is aborted: 'Cannot find master domain' - code 304
Thread-19::DEBUG::2012-05-11 14:46:16,838::task::1162::TaskManager.Task::(prepare) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::Prepare: aborted: Cannot find master domain
Thread-19::DEBUG::2012-05-11 14:46:16,838::task::978::TaskManager.Task::(_decref) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::ref 0 aborting True
Thread-19::DEBUG::2012-05-11 14:46:16,839::task::913::TaskManager.Task::(_doAbort) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::Task._doAbort: force False
Thread-19::DEBUG::2012-05-11 14:46:16,839::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::DEBUG::2012-05-11 14:46:16,839::task::588::TaskManager.Task::(_updateState) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state preparing -> state aborting
Thread-19::DEBUG::2012-05-11 14:46:16,839::task::537::TaskManager.Task::(__state_aborting) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::_aborting: recover policy none
Thread-19::DEBUG::2012-05-11 14:46:16,839::task::588::TaskManager.Task::(_updateState) Task=`5616c854-e704-4014-bb58-8ca757e8137f`::moving from state aborting -> state failed
Thread-19::DEBUG::2012-05-11 14:46:16,840::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2012-05-11 14:46:16,840::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::ERROR::2012-05-11 14:46:16,840::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=af5bcc86-898a-11e1-9632-003048c85226, msdUUID=e12a0f53-ee72-44bc-ad26-93f9b4613c6c'", 'code': 304}}