MainThread::INFO::2012-11-29 20:05:13,777::vdsm::88::vds::(run) I am the actual vdsm 4.10-0.43 cronus.uberbadger.co.uk (3.6.7-4.fc17.x86_64)
MainThread::DEBUG::2012-11-29 20:05:13,936::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2012-11-29 20:05:13,936::threadPool::33::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2012-11-29 20:05:13,940::fileUtils::184::fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2012-11-29 20:05:13,947::sp::359::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/45fa93a8-1761-4522-bafb-c5d3ab45f731/master` is not mounted, skipping
MainThread::DEBUG::2012-11-29 20:05:13,961::supervdsm::117::SuperVdsmProxy::(_start) Launching Super Vdsm
MainThread::DEBUG::2012-11-29 20:05:13,961::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /bin/python /usr/share/vdsm/supervdsmServer.py 9d191ddc-d7a1-4a16-b34b-255d418b43af 5086 /var/run/vdsm/svdsm.pid /var/run/vdsm/svdsm.time /var/run/vdsm/svdsm.sock 36' (cwd None)
MainThread::DEBUG::2012-11-29 20:05:14,076::supervdsmServer::332::SuperVdsm.Server::(main) Making sure I'm root
MainThread::DEBUG::2012-11-29 20:05:14,076::supervdsmServer::336::SuperVdsm.Server::(main) Parsing cmd args
MainThread::DEBUG::2012-11-29 20:05:14,076::supervdsmServer::340::SuperVdsm.Server::(main) Creating PID and TIMESTAMP files: /var/run/vdsm/svdsm.pid, /var/run/vdsm/svdsm.time
MainThread::DEBUG::2012-11-29 20:05:14,076::supervdsmServer::347::SuperVdsm.Server::(main) Cleaning old socket /var/run/vdsm/svdsm.sock
MainThread::DEBUG::2012-11-29 20:05:14,076::supervdsmServer::351::SuperVdsm.Server::(main) Setting up keep alive thread
MainThread::DEBUG::2012-11-29 20:05:14,077::supervdsmServer::359::SuperVdsm.Server::(main) Creating remote object manager
MainThread::DEBUG::2012-11-29 20:05:14,077::supervdsmServer::371::SuperVdsm.Server::(main) Started serving super vdsm object
MainThread::DEBUG::2012-11-29 20:05:15,967::supervdsm::176::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2012-11-29 20:05:15,974::multipath::106::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2012-11-29 20:05:15,974::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2012-11-29 20:05:16,011::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2012-11-29 20:05:16,011::hsm::426::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2012-11-29 20:05:16,018::hsm::458::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2012-11-29 20:05:16,018::hsm::459::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2012-11-29 20:05:16,018::hsm::461::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2012-11-29 20:05:16,020::hsm::504::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
MainThread::INFO::2012-11-29 20:05:16,022::dispatcher::95::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
Thread-12::DEBUG::2012-11-29 20:05:16,022::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:16,024::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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)
Thread-12::DEBUG::2012-11-29 20:05:16,068::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-11-29 20:05:16,068::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:16,068::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:16,069::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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-11-29 20:05:16,105::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-11-29 20:05:16,107::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:16,108::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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)
Thread-12::DEBUG::2012-11-29 20:05:16,156::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-11-29 20:05:16,160::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-12::DEBUG::2012-11-29 20:05:16,160::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-29 20:05:16,161::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12::DEBUG::2012-11-29 20:05:16,161::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-12::DEBUG::2012-11-29 20:05:16,161::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-12::DEBUG::2012-11-29 20:05:16,173::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-12::DEBUG::2012-11-29 20:05:16,174::misc::1054::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,176::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,180::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,184::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,187::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,191::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,193::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-12::DEBUG::2012-11-29 20:05:16,194::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
MainThread::INFO::2012-11-29 20:05:16,463::momIF::36::MOM::(__init__) Starting up MOM
MainThread::INFO::2012-11-29 20:05:16,465::vmChannels::140::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2012-11-29 20:05:16,468::vmChannels::128::vds::(run) Starting VM channels listener thread.
MainThread::WARNING::2012-11-29 20:05:16,472::clientIF::175::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
Thread-12::DEBUG::2012-11-29 20:05:18,198::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12::DEBUG::2012-11-29 20:05:18,215::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12::DEBUG::2012-11-29 20:05:18,215::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,216::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,216::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,216::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,217::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,217::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12::DEBUG::2012-11-29 20:05:18,217::misc::1054::SamplingMethod::(__call__) Returning last result
Thread-12::WARNING::2012-11-29 20:05:18,218::fileUtils::184::fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
Thread-14::DEBUG::2012-11-29 20:05:24,421::BindingXMLRPC::903::vds::(wrapper) client [192.168.0.2]::call getCapabilities with () {} flowID [16468359]
Thread-14::DEBUG::2012-11-29 20:05:24,957::BindingXMLRPC::910::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1353440401.0, 'version': '3.6.7'}, 'spice-server': {'release': '5.fc17', 'buildtime': 1336983054L, 'version': '0.10.1'}, 'vdsm': {'release': '0.43.gitc0bbef3.fc17', 'buildtime': 1354117528L, 'version': '4.10.2'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': 1348461894L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'mom': {'release': '1.fc17', 'buildtime': 1351785144L, 'version': '0.3.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1240 V2 @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.0.1', 'ports': ['em1.1']}, 'site1': {'iface': 'site1', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em1.10']}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['em1.1']}, 'site1': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': ['em1.10']}}, 'uuid': '3A713D00-E0F3-11E1-84D6-24BE0520852A_24:be:05:20:85:2a', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '24:be:05:20:85:2a', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '24:be:05:20:85:2a', 'speed': 1000}}, 'software_revision': '0.43', 'clusterLevels': ['3.0', '3.1', '3.2'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,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,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], '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'}}, 'software_version': '4.10', 'memSize': '32121', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {'em1.1': {'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}, 'em1.10': {'cfg': {'BRIDGE': 'site1', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.10', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', '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-29 20:05:25,993::BindingXMLRPC::903::vds::(wrapper) client [192.168.0.2]::call getCapabilities with () {} flowID [546afa97]
Thread-15::DEBUG::2012-11-29 20:05:26,015::BindingXMLRPC::910::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1353440401.0, 'version': '3.6.7'}, 'spice-server': {'release': '5.fc17', 'buildtime': 1336983054L, 'version': '0.10.1'}, 'vdsm': {'release': '0.43.gitc0bbef3.fc17', 'buildtime': 1354117528L, 'version': '4.10.2'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': 1348461894L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'mom': {'release': '1.fc17', 'buildtime': 1351785144L, 'version': '0.3.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1240 V2 @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.0.1', 'ports': ['em1.1']}, 'site1': {'iface': 'site1', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em1.10']}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['em1.1']}, 'site1': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': ['em1.10']}}, 'uuid': '3A713D00-E0F3-11E1-84D6-24BE0520852A_24:be:05:20:85:2a', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '24:be:05:20:85:2a', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '24:be:05:20:85:2a', 'speed': 1000}}, 'software_revision': '0.43', 'clusterLevels': ['3.0', '3.1', '3.2'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,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,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], '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'}}, 'software_version': '4.10', 'memSize': '32121', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {'em1.1': {'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}, 'em1.10': {'cfg': {'BRIDGE': 'site1', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.10', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', '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': '192.168.0.2'}}
Thread-16::DEBUG::2012-11-29 20:05:26,039::BindingXMLRPC::903::vds::(wrapper) client [192.168.0.2]::call getCapabilities with () {} flowID [546afa97]
Thread-16::DEBUG::2012-11-29 20:05:26,063::BindingXMLRPC::910::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31'}], 'FC': []}, 'packages2': {'kernel': {'release': '4.fc17.x86_64', 'buildtime': 1353440401.0, 'version': '3.6.7'}, 'spice-server': {'release': '5.fc17', 'buildtime': 1336983054L, 'version': '0.10.1'}, 'vdsm': {'release': '0.43.gitc0bbef3.fc17', 'buildtime': 1354117528L, 'version': '4.10.2'}, 'qemu-kvm': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'libvirt': {'release': '1.fc17', 'buildtime': 1348461894L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.fc17', 'buildtime': 1349642820L, 'version': '1.0.1'}, 'mom': {'release': '1.fc17', 'buildtime': 1351785144L, 'version': '0.3.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1240 V2 @ 3.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.0.1', 'ports': ['em1.1']}, 'site1': {'iface': 'site1', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em1.10']}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.0.4', 'cfg': {'UUID': '4e432c61-cbb0-4103-967a-16abcb59569a', 'USERCTL': 'no', 'DNS2': '8.8.4.4', 'DNS1': '8.8.8.8', 'IPADDR': '192.168.0.4', 'NETMASK': '255.255.255.0', 'GATEWAY': '192.168.0.1', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'PREFIX': '24', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes', 'IPV6INIT': 'no'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['em1.1']}, 'site1': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'USERCTL': 'no', 'VLAN': 'yes', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'site1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': ['em1.10']}}, 'uuid': '3A713D00-E0F3-11E1-84D6-24BE0520852A_24:be:05:20:85:2a', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'addr': '', 'cfg': {'DEVICE': 'em1', 'HWADDR': '24:be:05:20:85:2a', 'BOOTPROTO': 'none', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '24:be:05:20:85:2a', 'speed': 1000}}, 'software_revision': '0.43', 'clusterLevels': ['3.0', '3.1', '3.2'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,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,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:ecd5b86b4e31', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], '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'}}, 'software_version': '4.10', 'memSize': '32121', 'cpuSpeed': '1600.000', 'cpuSockets': '1', 'vlans': {'em1.1': {'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}, 'em1.10': {'cfg': {'BRIDGE': 'site1', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'BOOTPROTO': 'none', 'DEVICE': 'em1.10', 'ONBOOT': 'yes'}, 'netmask': '', 'iface': 'em1', 'addr': '', 'mtu': '1500'}}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', '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': '192.168.0.2'}}
Thread-18::DEBUG::2012-11-29 20:05:26,136::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-18::DEBUG::2012-11-29 20:05:26,136::task::568::TaskManager.Task::(_updateState) Task=`8338eaae-4b1d-442b-b630-915a0a184cd1`::moving from state init -> state preparing
Thread-18::INFO::2012-11-29 20:05:26,137::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', conList=[{'port': '', 'connection': '192.168.0.2:/home/iso', 'iqn': '', 'portal': '', 'user': '', 'protocol_version': '3', 'password': '******', 'id': '476d214f-0f08-4e47-b27d-69f37b16d506'}], options=None)
Thread-18::DEBUG::2012-11-29 20:05:26,142::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 192.168.0.2:/home/iso /rhev/data-center/mnt/192.168.0.2:_home_iso' (cwd None)
Thread-18::INFO::2012-11-29 20:05:26,253::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '476d214f-0f08-4e47-b27d-69f37b16d506'}]}
Thread-18::DEBUG::2012-11-29 20:05:26,253::task::1151::TaskManager.Task::(prepare) Task=`8338eaae-4b1d-442b-b630-915a0a184cd1`::finished: {'statuslist': [{'status': 0, 'id': '476d214f-0f08-4e47-b27d-69f37b16d506'}]}
Thread-18::DEBUG::2012-11-29 20:05:26,254::task::568::TaskManager.Task::(_updateState) Task=`8338eaae-4b1d-442b-b630-915a0a184cd1`::moving from state preparing -> state finished
Thread-18::DEBUG::2012-11-29 20:05:26,254::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2012-11-29 20:05:26,254::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18::DEBUG::2012-11-29 20:05:26,254::task::957::TaskManager.Task::(_decref) Task=`8338eaae-4b1d-442b-b630-915a0a184cd1`::ref 0 aborting False
Thread-19::DEBUG::2012-11-29 20:05:26,263::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-19::DEBUG::2012-11-29 20:05:26,264::task::568::TaskManager.Task::(_updateState) Task=`9c830edd-6be1-4a9f-a515-f72283fb8a0e`::moving from state init -> state preparing
Thread-19::INFO::2012-11-29 20:05:26,264::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', conList=[{'connection': '192.168.0.34:/share/MD0_DATA/VMs', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'e5eb0313-931a-46a2-a0ab-f7425a4b5d1d', 'port': ''}], options=None)
Thread-19::DEBUG::2012-11-29 20:05:26,272::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 192.168.0.34:/share/MD0_DATA/VMs /rhev/data-center/mnt/192.168.0.34:_share_MD0__DATA_VMs' (cwd None)
Thread-19::INFO::2012-11-29 20:05:26,307::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'e5eb0313-931a-46a2-a0ab-f7425a4b5d1d'}]}
Thread-19::DEBUG::2012-11-29 20:05:26,307::task::1151::TaskManager.Task::(prepare) Task=`9c830edd-6be1-4a9f-a515-f72283fb8a0e`::finished: {'statuslist': [{'status': 0, 'id': 'e5eb0313-931a-46a2-a0ab-f7425a4b5d1d'}]}
Thread-19::DEBUG::2012-11-29 20:05:26,308::task::568::TaskManager.Task::(_updateState) Task=`9c830edd-6be1-4a9f-a515-f72283fb8a0e`::moving from state preparing -> state finished
Thread-19::DEBUG::2012-11-29 20:05:26,308::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2012-11-29 20:05:26,308::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::DEBUG::2012-11-29 20:05:26,308::task::957::TaskManager.Task::(_decref) Task=`9c830edd-6be1-4a9f-a515-f72283fb8a0e`::ref 0 aborting False
Thread-20::DEBUG::2012-11-29 20:05:26,323::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-20::DEBUG::2012-11-29 20:05:26,324::task::568::TaskManager.Task::(_updateState) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::moving from state init -> state preparing
Thread-20::INFO::2012-11-29 20:05:26,324::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', hostID=2, scsiKey='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', msdUUID='68d8b0e2-c348-4cfe-a896-08c62d491dfb', masterVersion=3, options=None)
Thread-20::DEBUG::2012-11-29 20:05:26,325::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`4492744e-78de-4ed2-be7c-9529eca7a3b7`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-20::DEBUG::2012-11-29 20:05:26,325::resourceManager::487::ResourceManager::(registerResource) Trying to register resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' for lock type 'exclusive'
Thread-20::DEBUG::2012-11-29 20:05:26,325::resourceManager::530::ResourceManager::(registerResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free. Now locking as 'exclusive' (1 active user)
Thread-20::DEBUG::2012-11-29 20:05:26,326::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`4492744e-78de-4ed2-be7c-9529eca7a3b7`::Granted request
Thread-20::INFO::2012-11-29 20:05:26,326::sp::628::Storage.StoragePool::(connect) Connect host #2 to the storage pool f1b40ecc-b6a9-44e7-92cb-0fdf445e3175 with master domain: 68d8b0e2-c348-4cfe-a896-08c62d491dfb (ver = 3)
Thread-20::DEBUG::2012-11-29 20:05:26,327::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-20::DEBUG::2012-11-29 20:05:26,327::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-20::DEBUG::2012-11-29 20:05:26,327::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-20::DEBUG::2012-11-29 20:05:26,328::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-20::DEBUG::2012-11-29 20:05:26,328::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-20::DEBUG::2012-11-29 20:05:26,340::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-20::DEBUG::2012-11-29 20:05:26,341::misc::1054::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,343::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,346::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,349::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,351::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,354::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,357::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-20::DEBUG::2012-11-29 20:05:26,359::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-20::DEBUG::2012-11-29 20:05:28,362::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/multipath' (cwd None)
Thread-20::DEBUG::2012-11-29 20:05:28,378::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-20::DEBUG::2012-11-29 20:05:28,378::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,379::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,379::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,379::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,380::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,380::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,380::misc::1054::SamplingMethod::(__call__) Returning last result
Thread-20::DEBUG::2012-11-29 20:05:28,381::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,383::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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 68d8b0e2-c348-4cfe-a896-08c62d491dfb' (cwd None)
Thread-20::DEBUG::2012-11-29 20:05:28,437::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found\n'; <rc> = 5
Thread-20::WARNING::2012-11-29 20:05:28,438::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found']
Thread-20::DEBUG::2012-11-29 20:05:28,439::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-20::DEBUG::2012-11-29 20:05:28,744::resourceManager::540::ResourceManager::(releaseResource) Trying to release resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-20::DEBUG::2012-11-29 20:05:28,745::resourceManager::556::ResourceManager::(releaseResource) Released resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' (0 active users)
Thread-20::DEBUG::2012-11-29 20:05:28,745::resourceManager::561::ResourceManager::(releaseResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free, finding out if anyone is waiting for it.
Thread-20::DEBUG::2012-11-29 20:05:28,745::resourceManager::568::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', Clearing records.
Thread-20::ERROR::2012-11-29 20:05:28,746::task::833::TaskManager.Task::(_setError) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::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 918, in connectStoragePool
    masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 965, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 644, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1174, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1518, in getMasterDomain
    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'
Thread-20::DEBUG::2012-11-29 20:05:28,749::task::852::TaskManager.Task::(_run) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::Task._run: 16b1724d-4609-4a33-8874-56b79ba3cdbf ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 2, 'f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', '68d8b0e2-c348-4cfe-a896-08c62d491dfb', 3) {} failed - stopping task
Thread-20::DEBUG::2012-11-29 20:05:28,749::task::1177::TaskManager.Task::(stop) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::stopping in state preparing (force False)
Thread-20::DEBUG::2012-11-29 20:05:28,749::task::957::TaskManager.Task::(_decref) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::ref 1 aborting True
Thread-20::INFO::2012-11-29 20:05:28,749::task::1134::TaskManager.Task::(prepare) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::aborting: Task is aborted: 'Cannot find master domain' - code 304
Thread-20::DEBUG::2012-11-29 20:05:28,749::task::1139::TaskManager.Task::(prepare) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::Prepare: aborted: Cannot find master domain
Thread-20::DEBUG::2012-11-29 20:05:28,750::task::957::TaskManager.Task::(_decref) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::ref 0 aborting True
Thread-20::DEBUG::2012-11-29 20:05:28,750::task::892::TaskManager.Task::(_doAbort) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::Task._doAbort: force False
Thread-20::DEBUG::2012-11-29 20:05:28,750::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-20::DEBUG::2012-11-29 20:05:28,750::task::568::TaskManager.Task::(_updateState) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::moving from state preparing -> state aborting
Thread-20::DEBUG::2012-11-29 20:05:28,750::task::523::TaskManager.Task::(__state_aborting) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::_aborting: recover policy none
Thread-20::DEBUG::2012-11-29 20:05:28,751::task::568::TaskManager.Task::(_updateState) Task=`16b1724d-4609-4a33-8874-56b79ba3cdbf`::moving from state aborting -> state failed
Thread-20::DEBUG::2012-11-29 20:05:28,751::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-20::DEBUG::2012-11-29 20:05:28,751::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-20::ERROR::2012-11-29 20:05:28,751::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'", 'code': 304}}
Thread-24::DEBUG::2012-11-29 20:05:32,800::task::568::TaskManager.Task::(_updateState) Task=`b09fc337-9a1e-438e-b3b3-25bc63056747`::moving from state init -> state preparing
Thread-24::INFO::2012-11-29 20:05:32,800::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-24::INFO::2012-11-29 20:05:32,800::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-24::DEBUG::2012-11-29 20:05:32,800::task::1151::TaskManager.Task::(prepare) Task=`b09fc337-9a1e-438e-b3b3-25bc63056747`::finished: {}
Thread-24::DEBUG::2012-11-29 20:05:32,801::task::568::TaskManager.Task::(_updateState) Task=`b09fc337-9a1e-438e-b3b3-25bc63056747`::moving from state preparing -> state finished
Thread-24::DEBUG::2012-11-29 20:05:32,801::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-24::DEBUG::2012-11-29 20:05:32,801::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-24::DEBUG::2012-11-29 20:05:32,801::task::957::TaskManager.Task::(_decref) Task=`b09fc337-9a1e-438e-b3b3-25bc63056747`::ref 0 aborting False
Thread-28::DEBUG::2012-11-29 20:05:38,048::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-28::DEBUG::2012-11-29 20:05:38,049::task::568::TaskManager.Task::(_updateState) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::moving from state init -> state preparing
Thread-28::INFO::2012-11-29 20:05:38,049::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', options=None)
Thread-28::ERROR::2012-11-29 20:05:38,049::task::833::TaskManager.Task::(_setError) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::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 597, in getSpmStatus
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 310, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)
Thread-28::DEBUG::2012-11-29 20:05:38,050::task::852::TaskManager.Task::(_run) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::Task._run: c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',) {} failed - stopping task
Thread-28::DEBUG::2012-11-29 20:05:38,050::task::1177::TaskManager.Task::(stop) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::stopping in state preparing (force False)
Thread-28::DEBUG::2012-11-29 20:05:38,050::task::957::TaskManager.Task::(_decref) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::ref 1 aborting True
Thread-28::INFO::2012-11-29 20:05:38,050::task::1134::TaskManager.Task::(prepare) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-28::DEBUG::2012-11-29 20:05:38,050::task::1139::TaskManager.Task::(prepare) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::Prepare: aborted: Unknown pool id, pool not connected
Thread-28::DEBUG::2012-11-29 20:05:38,050::task::957::TaskManager.Task::(_decref) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::ref 0 aborting True
Thread-28::DEBUG::2012-11-29 20:05:38,051::task::892::TaskManager.Task::(_doAbort) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::Task._doAbort: force False
Thread-28::DEBUG::2012-11-29 20:05:38,051::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-28::DEBUG::2012-11-29 20:05:38,051::task::568::TaskManager.Task::(_updateState) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::moving from state preparing -> state aborting
Thread-28::DEBUG::2012-11-29 20:05:38,051::task::523::TaskManager.Task::(__state_aborting) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::_aborting: recover policy none
Thread-28::DEBUG::2012-11-29 20:05:38,051::task::568::TaskManager.Task::(_updateState) Task=`c0cb6d5c-e97b-4b07-b7e7-27870a94d1e9`::moving from state aborting -> state failed
Thread-28::DEBUG::2012-11-29 20:05:38,051::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-28::DEBUG::2012-11-29 20:05:38,051::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-28::ERROR::2012-11-29 20:05:38,051::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)", 'code': 309}}
Thread-29::DEBUG::2012-11-29 20:05:38,065::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-29::DEBUG::2012-11-29 20:05:38,065::task::568::TaskManager.Task::(_updateState) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::moving from state init -> state preparing
Thread-29::INFO::2012-11-29 20:05:38,066::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', hostID=2, scsiKey='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', msdUUID='68d8b0e2-c348-4cfe-a896-08c62d491dfb', masterVersion=3, options=None)
Thread-29::DEBUG::2012-11-29 20:05:38,066::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`8d8d289b-8269-42f7-bd41-126219b1380e`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-29::DEBUG::2012-11-29 20:05:38,066::resourceManager::487::ResourceManager::(registerResource) Trying to register resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' for lock type 'exclusive'
Thread-29::DEBUG::2012-11-29 20:05:38,067::resourceManager::530::ResourceManager::(registerResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free. Now locking as 'exclusive' (1 active user)
Thread-29::DEBUG::2012-11-29 20:05:38,067::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`8d8d289b-8269-42f7-bd41-126219b1380e`::Granted request
Thread-29::INFO::2012-11-29 20:05:38,067::sp::628::Storage.StoragePool::(connect) Connect host #2 to the storage pool f1b40ecc-b6a9-44e7-92cb-0fdf445e3175 with master domain: 68d8b0e2-c348-4cfe-a896-08c62d491dfb (ver = 3)
Thread-29::DEBUG::2012-11-29 20:05:38,068::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-29::DEBUG::2012-11-29 20:05:38,068::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-29::DEBUG::2012-11-29 20:05:38,068::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-29::DEBUG::2012-11-29 20:05:38,068::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-29::DEBUG::2012-11-29 20:05:38,069::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-29::DEBUG::2012-11-29 20:05:38,081::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-29::DEBUG::2012-11-29 20:05:38,081::misc::1054::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,084::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,086::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,089::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,091::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,093::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,096::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-29::DEBUG::2012-11-29 20:05:38,098::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-29::DEBUG::2012-11-29 20:05:40,101::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/multipath' (cwd None)
Thread-29::DEBUG::2012-11-29 20:05:40,118::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-29::DEBUG::2012-11-29 20:05:40,119::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,119::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,119::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,120::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,120::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,120::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,121::misc::1054::SamplingMethod::(__call__) Returning last result
Thread-29::DEBUG::2012-11-29 20:05:40,121::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,123::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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 68d8b0e2-c348-4cfe-a896-08c62d491dfb' (cwd None)
Thread-29::DEBUG::2012-11-29 20:05:40,175::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found\n'; <rc> = 5
Thread-29::WARNING::2012-11-29 20:05:40,176::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found']
Thread-29::DEBUG::2012-11-29 20:05:40,177::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-29::DEBUG::2012-11-29 20:05:40,183::resourceManager::540::ResourceManager::(releaseResource) Trying to release resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-29::DEBUG::2012-11-29 20:05:40,184::resourceManager::556::ResourceManager::(releaseResource) Released resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' (0 active users)
Thread-29::DEBUG::2012-11-29 20:05:40,184::resourceManager::561::ResourceManager::(releaseResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free, finding out if anyone is waiting for it.
Thread-29::DEBUG::2012-11-29 20:05:40,184::resourceManager::568::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', Clearing records.
Thread-29::ERROR::2012-11-29 20:05:40,184::task::833::TaskManager.Task::(_setError) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::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 918, in connectStoragePool
    masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 965, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 644, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1174, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1518, in getMasterDomain
    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'
Thread-29::DEBUG::2012-11-29 20:05:40,185::task::852::TaskManager.Task::(_run) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::Task._run: ac49d100-ec3b-4333-96c9-6c6464225690 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 2, 'f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', '68d8b0e2-c348-4cfe-a896-08c62d491dfb', 3) {} failed - stopping task
Thread-29::DEBUG::2012-11-29 20:05:40,185::task::1177::TaskManager.Task::(stop) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::stopping in state preparing (force False)
Thread-29::DEBUG::2012-11-29 20:05:40,185::task::957::TaskManager.Task::(_decref) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::ref 1 aborting True
Thread-29::INFO::2012-11-29 20:05:40,186::task::1134::TaskManager.Task::(prepare) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::aborting: Task is aborted: 'Cannot find master domain' - code 304
Thread-29::DEBUG::2012-11-29 20:05:40,186::task::1139::TaskManager.Task::(prepare) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::Prepare: aborted: Cannot find master domain
Thread-29::DEBUG::2012-11-29 20:05:40,186::task::957::TaskManager.Task::(_decref) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::ref 0 aborting True
Thread-29::DEBUG::2012-11-29 20:05:40,186::task::892::TaskManager.Task::(_doAbort) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::Task._doAbort: force False
Thread-29::DEBUG::2012-11-29 20:05:40,187::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-29::DEBUG::2012-11-29 20:05:40,187::task::568::TaskManager.Task::(_updateState) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::moving from state preparing -> state aborting
Thread-29::DEBUG::2012-11-29 20:05:40,187::task::523::TaskManager.Task::(__state_aborting) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::_aborting: recover policy none
Thread-29::DEBUG::2012-11-29 20:05:40,187::task::568::TaskManager.Task::(_updateState) Task=`ac49d100-ec3b-4333-96c9-6c6464225690`::moving from state aborting -> state failed
Thread-29::DEBUG::2012-11-29 20:05:40,187::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-29::DEBUG::2012-11-29 20:05:40,188::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-29::ERROR::2012-11-29 20:05:40,188::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'", 'code': 304}}
Thread-34::DEBUG::2012-11-29 20:05:42,862::task::568::TaskManager.Task::(_updateState) Task=`45a2e3ea-fd12-4102-a013-abe87d2c1233`::moving from state init -> state preparing
Thread-34::INFO::2012-11-29 20:05:42,863::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-34::INFO::2012-11-29 20:05:42,863::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-34::DEBUG::2012-11-29 20:05:42,863::task::1151::TaskManager.Task::(prepare) Task=`45a2e3ea-fd12-4102-a013-abe87d2c1233`::finished: {}
Thread-34::DEBUG::2012-11-29 20:05:42,863::task::568::TaskManager.Task::(_updateState) Task=`45a2e3ea-fd12-4102-a013-abe87d2c1233`::moving from state preparing -> state finished
Thread-34::DEBUG::2012-11-29 20:05:42,864::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-34::DEBUG::2012-11-29 20:05:42,864::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-34::DEBUG::2012-11-29 20:05:42,864::task::957::TaskManager.Task::(_decref) Task=`45a2e3ea-fd12-4102-a013-abe87d2c1233`::ref 0 aborting False
Thread-39::DEBUG::2012-11-29 20:05:50,261::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-39::DEBUG::2012-11-29 20:05:50,261::task::568::TaskManager.Task::(_updateState) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::moving from state init -> state preparing
Thread-39::INFO::2012-11-29 20:05:50,261::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', options=None)
Thread-39::ERROR::2012-11-29 20:05:50,261::task::833::TaskManager.Task::(_setError) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::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 597, in getSpmStatus
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 310, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::852::TaskManager.Task::(_run) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::Task._run: ddd2a06e-27ff-4b1a-a6de-61d9bb995458 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',) {} failed - stopping task
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::1177::TaskManager.Task::(stop) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::stopping in state preparing (force False)
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::957::TaskManager.Task::(_decref) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::ref 1 aborting True
Thread-39::INFO::2012-11-29 20:05:50,262::task::1134::TaskManager.Task::(prepare) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::1139::TaskManager.Task::(prepare) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::Prepare: aborted: Unknown pool id, pool not connected
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::957::TaskManager.Task::(_decref) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::ref 0 aborting True
Thread-39::DEBUG::2012-11-29 20:05:50,262::task::892::TaskManager.Task::(_doAbort) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::Task._doAbort: force False
Thread-39::DEBUG::2012-11-29 20:05:50,262::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39::DEBUG::2012-11-29 20:05:50,263::task::568::TaskManager.Task::(_updateState) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::moving from state preparing -> state aborting
Thread-39::DEBUG::2012-11-29 20:05:50,263::task::523::TaskManager.Task::(__state_aborting) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::_aborting: recover policy none
Thread-39::DEBUG::2012-11-29 20:05:50,263::task::568::TaskManager.Task::(_updateState) Task=`ddd2a06e-27ff-4b1a-a6de-61d9bb995458`::moving from state aborting -> state failed
Thread-39::DEBUG::2012-11-29 20:05:50,263::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39::DEBUG::2012-11-29 20:05:50,263::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39::ERROR::2012-11-29 20:05:50,263::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)", 'code': 309}}
Thread-40::DEBUG::2012-11-29 20:05:50,276::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-40::DEBUG::2012-11-29 20:05:50,276::task::568::TaskManager.Task::(_updateState) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::moving from state init -> state preparing
Thread-40::INFO::2012-11-29 20:05:50,276::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', hostID=2, scsiKey='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', msdUUID='68d8b0e2-c348-4cfe-a896-08c62d491dfb', masterVersion=3, options=None)
Thread-40::DEBUG::2012-11-29 20:05:50,277::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`d3557a52-f5ae-4010-8e3c-f6087a8d332a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-40::DEBUG::2012-11-29 20:05:50,277::resourceManager::487::ResourceManager::(registerResource) Trying to register resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' for lock type 'exclusive'
Thread-40::DEBUG::2012-11-29 20:05:50,277::resourceManager::530::ResourceManager::(registerResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free. Now locking as 'exclusive' (1 active user)
Thread-40::DEBUG::2012-11-29 20:05:50,278::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`d3557a52-f5ae-4010-8e3c-f6087a8d332a`::Granted request
Thread-40::INFO::2012-11-29 20:05:50,278::sp::628::Storage.StoragePool::(connect) Connect host #2 to the storage pool f1b40ecc-b6a9-44e7-92cb-0fdf445e3175 with master domain: 68d8b0e2-c348-4cfe-a896-08c62d491dfb (ver = 3)
Thread-40::DEBUG::2012-11-29 20:05:50,279::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-40::DEBUG::2012-11-29 20:05:50,279::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-40::DEBUG::2012-11-29 20:05:50,279::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-40::DEBUG::2012-11-29 20:05:50,279::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-40::DEBUG::2012-11-29 20:05:50,279::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-40::DEBUG::2012-11-29 20:05:50,292::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-40::DEBUG::2012-11-29 20:05:50,292::misc::1054::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,295::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,297::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,300::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,302::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,305::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,307::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-40::DEBUG::2012-11-29 20:05:50,310::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-40::DEBUG::2012-11-29 20:05:52,313::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/multipath' (cwd None)
Thread-40::DEBUG::2012-11-29 20:05:52,328::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-40::DEBUG::2012-11-29 20:05:52,328::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,329::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,329::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,329::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,330::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,330::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,330::misc::1054::SamplingMethod::(__call__) Returning last result
Thread-40::DEBUG::2012-11-29 20:05:52,331::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,332::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2%\\", \\"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 68d8b0e2-c348-4cfe-a896-08c62d491dfb' (cwd None)
Thread-40::DEBUG::2012-11-29 20:05:52,379::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found\n'; <rc> = 5
Thread-40::WARNING::2012-11-29 20:05:52,381::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "68d8b0e2-c348-4cfe-a896-08c62d491dfb" not found']
Thread-40::DEBUG::2012-11-29 20:05:52,381::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-40::DEBUG::2012-11-29 20:05:52,388::resourceManager::540::ResourceManager::(releaseResource) Trying to release resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-40::DEBUG::2012-11-29 20:05:52,388::resourceManager::556::ResourceManager::(releaseResource) Released resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' (0 active users)
Thread-40::DEBUG::2012-11-29 20:05:52,389::resourceManager::561::ResourceManager::(releaseResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free, finding out if anyone is waiting for it.
Thread-40::DEBUG::2012-11-29 20:05:52,389::resourceManager::568::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', Clearing records.
Thread-40::ERROR::2012-11-29 20:05:52,389::task::833::TaskManager.Task::(_setError) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::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 918, in connectStoragePool
    masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 965, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 644, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1174, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1518, in getMasterDomain
    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'
Thread-40::DEBUG::2012-11-29 20:05:52,390::task::852::TaskManager.Task::(_run) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::Task._run: dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 2, 'f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', '68d8b0e2-c348-4cfe-a896-08c62d491dfb', 3) {} failed - stopping task
Thread-40::DEBUG::2012-11-29 20:05:52,390::task::1177::TaskManager.Task::(stop) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::stopping in state preparing (force False)
Thread-40::DEBUG::2012-11-29 20:05:52,390::task::957::TaskManager.Task::(_decref) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::ref 1 aborting True
Thread-40::INFO::2012-11-29 20:05:52,391::task::1134::TaskManager.Task::(prepare) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::aborting: Task is aborted: 'Cannot find master domain' - code 304
Thread-40::DEBUG::2012-11-29 20:05:52,391::task::1139::TaskManager.Task::(prepare) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::Prepare: aborted: Cannot find master domain
Thread-40::DEBUG::2012-11-29 20:05:52,391::task::957::TaskManager.Task::(_decref) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::ref 0 aborting True
Thread-40::DEBUG::2012-11-29 20:05:52,391::task::892::TaskManager.Task::(_doAbort) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::Task._doAbort: force False
Thread-40::DEBUG::2012-11-29 20:05:52,391::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-40::DEBUG::2012-11-29 20:05:52,392::task::568::TaskManager.Task::(_updateState) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::moving from state preparing -> state aborting
Thread-40::DEBUG::2012-11-29 20:05:52,392::task::523::TaskManager.Task::(__state_aborting) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::_aborting: recover policy none
Thread-40::DEBUG::2012-11-29 20:05:52,392::task::568::TaskManager.Task::(_updateState) Task=`dbdd92a7-dcff-4a0e-8c9e-1e4af82cb240`::moving from state aborting -> state failed
Thread-40::DEBUG::2012-11-29 20:05:52,392::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-40::DEBUG::2012-11-29 20:05:52,393::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-40::ERROR::2012-11-29 20:05:52,393::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175, msdUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb'", 'code': 304}}
Thread-44::DEBUG::2012-11-29 20:05:52,924::task::568::TaskManager.Task::(_updateState) Task=`7637e417-7dbb-4d73-bcf5-c5b48f39eda8`::moving from state init -> state preparing
Thread-44::INFO::2012-11-29 20:05:52,924::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-44::INFO::2012-11-29 20:05:52,924::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-44::DEBUG::2012-11-29 20:05:52,924::task::1151::TaskManager.Task::(prepare) Task=`7637e417-7dbb-4d73-bcf5-c5b48f39eda8`::finished: {}
Thread-44::DEBUG::2012-11-29 20:05:52,925::task::568::TaskManager.Task::(_updateState) Task=`7637e417-7dbb-4d73-bcf5-c5b48f39eda8`::moving from state preparing -> state finished
Thread-44::DEBUG::2012-11-29 20:05:52,925::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-44::DEBUG::2012-11-29 20:05:52,925::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-44::DEBUG::2012-11-29 20:05:52,925::task::957::TaskManager.Task::(_decref) Task=`7637e417-7dbb-4d73-bcf5-c5b48f39eda8`::ref 0 aborting False
Thread-47::DEBUG::2012-11-29 20:05:55,279::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-47::DEBUG::2012-11-29 20:05:55,279::task::568::TaskManager.Task::(_updateState) Task=`f5042b42-be0d-4afc-8440-56df9667e04c`::moving from state init -> state preparing
Thread-47::INFO::2012-11-29 20:05:55,280::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', conList=[{'connection': '192.168.0.34', 'iqn': 'iqn.2004-04.com.qnap:ts-859proplus:iscsi.test.cc902e', 'portal': '1', 'user': '', 'password': '******', 'id': '820de6c7-9c74-43b4-9aaf-90cd69ea45f0', 'port': '3260'}], options=None)
Thread-47::DEBUG::2012-11-29 20:05:55,280::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2004-04.com.qnap:ts-859proplus:iscsi.test.cc902e -I default -p 192.168.0.34:3260 --op=new' (cwd None)
Thread-47::DEBUG::2012-11-29 20:05:55,295::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-47::DEBUG::2012-11-29 20:05:55,296::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2004-04.com.qnap:ts-859proplus:iscsi.test.cc902e -I default -p 192.168.0.34:3260 -l' (cwd None)
Thread-47::DEBUG::2012-11-29 20:05:55,825::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-47::DEBUG::2012-11-29 20:05:55,826::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2004-04.com.qnap:ts-859proplus:iscsi.test.cc902e -I default -p 192.168.0.34:3260 -n node.startup -v manual --op=update' (cwd None)
Thread-47::DEBUG::2012-11-29 20:05:55,842::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-47::INFO::2012-11-29 20:05:55,843::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '820de6c7-9c74-43b4-9aaf-90cd69ea45f0'}]}
Thread-47::DEBUG::2012-11-29 20:05:55,843::task::1151::TaskManager.Task::(prepare) Task=`f5042b42-be0d-4afc-8440-56df9667e04c`::finished: {'statuslist': [{'status': 0, 'id': '820de6c7-9c74-43b4-9aaf-90cd69ea45f0'}]}
Thread-47::DEBUG::2012-11-29 20:05:55,843::task::568::TaskManager.Task::(_updateState) Task=`f5042b42-be0d-4afc-8440-56df9667e04c`::moving from state preparing -> state finished
Thread-47::DEBUG::2012-11-29 20:05:55,844::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-47::DEBUG::2012-11-29 20:05:55,844::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-47::DEBUG::2012-11-29 20:05:55,844::task::957::TaskManager.Task::(_decref) Task=`f5042b42-be0d-4afc-8440-56df9667e04c`::ref 0 aborting False
Thread-48::DEBUG::2012-11-29 20:05:55,853::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-48::DEBUG::2012-11-29 20:05:55,854::task::568::TaskManager.Task::(_updateState) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::moving from state init -> state preparing
Thread-48::INFO::2012-11-29 20:05:55,854::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', options=None)
Thread-48::ERROR::2012-11-29 20:05:55,855::task::833::TaskManager.Task::(_setError) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::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 597, in getSpmStatus
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 310, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)
Thread-48::DEBUG::2012-11-29 20:05:55,855::task::852::TaskManager.Task::(_run) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::Task._run: e0d3796e-c708-4244-b82b-eb107c303ab7 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',) {} failed - stopping task
Thread-48::DEBUG::2012-11-29 20:05:55,855::task::1177::TaskManager.Task::(stop) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::stopping in state preparing (force False)
Thread-48::DEBUG::2012-11-29 20:05:55,856::task::957::TaskManager.Task::(_decref) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::ref 1 aborting True
Thread-48::INFO::2012-11-29 20:05:55,856::task::1134::TaskManager.Task::(prepare) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-48::DEBUG::2012-11-29 20:05:55,856::task::1139::TaskManager.Task::(prepare) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::Prepare: aborted: Unknown pool id, pool not connected
Thread-48::DEBUG::2012-11-29 20:05:55,856::task::957::TaskManager.Task::(_decref) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::ref 0 aborting True
Thread-48::DEBUG::2012-11-29 20:05:55,856::task::892::TaskManager.Task::(_doAbort) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::Task._doAbort: force False
Thread-48::DEBUG::2012-11-29 20:05:55,857::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-48::DEBUG::2012-11-29 20:05:55,857::task::568::TaskManager.Task::(_updateState) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::moving from state preparing -> state aborting
Thread-48::DEBUG::2012-11-29 20:05:55,857::task::523::TaskManager.Task::(__state_aborting) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::_aborting: recover policy none
Thread-48::DEBUG::2012-11-29 20:05:55,857::task::568::TaskManager.Task::(_updateState) Task=`e0d3796e-c708-4244-b82b-eb107c303ab7`::moving from state aborting -> state failed
Thread-48::DEBUG::2012-11-29 20:05:55,857::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-48::DEBUG::2012-11-29 20:05:55,858::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-48::ERROR::2012-11-29 20:05:55,858::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)", 'code': 309}}
Thread-49::DEBUG::2012-11-29 20:05:55,871::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-49::DEBUG::2012-11-29 20:05:55,871::task::568::TaskManager.Task::(_updateState) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::moving from state init -> state preparing
Thread-49::INFO::2012-11-29 20:05:55,872::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', hostID=2, scsiKey='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', msdUUID='68d8b0e2-c348-4cfe-a896-08c62d491dfb', masterVersion=3, options=None)
Thread-49::DEBUG::2012-11-29 20:05:55,872::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`0e6b2bfc-c8d5-4657-9ba5-2553e64121c1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-49::DEBUG::2012-11-29 20:05:55,872::resourceManager::487::ResourceManager::(registerResource) Trying to register resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' for lock type 'exclusive'
Thread-49::DEBUG::2012-11-29 20:05:55,872::resourceManager::530::ResourceManager::(registerResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free. Now locking as 'exclusive' (1 active user)
Thread-49::DEBUG::2012-11-29 20:05:55,873::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`0e6b2bfc-c8d5-4657-9ba5-2553e64121c1`::Granted request
Thread-49::INFO::2012-11-29 20:05:55,873::sp::628::Storage.StoragePool::(connect) Connect host #2 to the storage pool f1b40ecc-b6a9-44e7-92cb-0fdf445e3175 with master domain: 68d8b0e2-c348-4cfe-a896-08c62d491dfb (ver = 3)
Thread-49::DEBUG::2012-11-29 20:05:55,873::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-49::DEBUG::2012-11-29 20:05:55,874::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-49::DEBUG::2012-11-29 20:05:55,874::misc::1044::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-49::DEBUG::2012-11-29 20:05:55,874::misc::1046::SamplingMethod::(__call__) Got in to sampling method
Thread-49::DEBUG::2012-11-29 20:05:55,874::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:55,890::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:55,891::misc::1054::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,893::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,896::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,898::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,901::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,904::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,906::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,909::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None)
MainProcess|Thread-49::DEBUG::2012-11-29 20:05:55,911::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-49::DEBUG::2012-11-29 20:05:57,915::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/multipath' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:57,937::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:57,938::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,938::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,939::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,939::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,939::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,939::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,940::misc::1054::SamplingMethod::(__call__) Returning last result
Thread-49::DEBUG::2012-11-29 20:05:57,940::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:57,942::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"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 68d8b0e2-c348-4cfe-a896-08c62d491dfb' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,014::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,016::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,017::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
Thread-49::DEBUG::2012-11-29 20:05:58,018::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 68d8b0e2-c348-4cfe-a896-08c62d491dfb/metadata' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,257::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,258::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,258::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,258::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/68d8b0e2-c348-4cfe-a896-08c62d491dfb/metadata count=1' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,265::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000434217 s, 4.7 MB/s\n'; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,265::misc::316::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000434217 s, 4.7 MB/s'], size: 2048
Thread-49::DEBUG::2012-11-29 20:05:58,266::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
Thread-49::WARNING::2012-11-29 20:05:58,266::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-49::DEBUG::2012-11-29 20:05:58,266::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
Thread-49::DEBUG::2012-11-29 20:05:58,267::lvm::483::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,267::lvm::485::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,267::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,268::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,268::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,269::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"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 68d8b0e2-c348-4cfe-a896-08c62d491dfb' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,334::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,336::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,337::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VERSION=2', u'PV0=pv:36001405c2f5e9d2d3be7d41a8db27dd6,uuid:b62d1B-zFVl-LKrH-fekH-vprs-znOZ-IF6jJy,pestart:0,pecount:4093,mapoffset:0', 'TYPE=ISCSI', 'LOGBLKSIZE=512', 'SDUUID=68d8b0e2-c348-4cfe-a896-08c62d491dfb', 'LEASERETRIES=3', 'LOCKRENEWALINTERVALSEC=5', 'LOCKPOLICY=', 'PHYBLKSIZE=512', 'VGUUID=q7sGQ7-1G03-s9mh-dIyx-NSmo-P0zk-23c3Ad', 'DESCRIPTION=512gb2', 'CLASS=Data', 'POOL_UUID=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 'IOOPTIMEOUTSEC=10', 'LEASETIMESEC=60', 'MASTER_VERSION=4', 'ROLE=Master', 'POOL_DESCRIPTION=UB1', u'POOL_DOMAINS=afec8026-ccac-4366-bb4b-2150d8731e4c:Active,c2b01420-fc73-4ccc-a560-3e1c5aa28a9f:Active,45fa93a8-1761-4522-bafb-c5d3ab45f731:Attached,68d8b0e2-c348-4cfe-a896-08c62d491dfb:Active', 'POOL_SPM_LVER=541', '_SHA_CKSUM=d54ce32f30c8040449f2a91ccc6e115e35894a5e', 'POOL_SPM_ID=-1']
Thread-49::DEBUG::2012-11-29 20:05:58,338::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 68d8b0e2-c348-4cfe-a896-08c62d491dfb/ids' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,458::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,458::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,458::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,459::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 68d8b0e2-c348-4cfe-a896-08c62d491dfb/leases' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,566::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,567::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,568::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,569::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 68d8b0e2-c348-4cfe-a896-08c62d491dfb/inbox 68d8b0e2-c348-4cfe-a896-08c62d491dfb/outbox 68d8b0e2-c348-4cfe-a896-08c62d491dfb/master' (cwd None)
Thread-49::DEBUG::2012-11-29 20:05:58,747::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,747::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,748::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,748::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,749::misc::83::Storage.Misc.excCmd::(<lambda>) '/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%3500a075102fe7dc2|360014058db25f73da5b6d491dd89a4d5|36001405c2f5e9d2d3be7d41a8db27dd6%\\", \\"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)
Thread-49::DEBUG::2012-11-29 20:05:58,825::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-49::DEBUG::2012-11-29 20:05:58,826::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
Thread-49::DEBUG::2012-11-29 20:05:58,827::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '68d8b0e2-c348-4cfe-a896-08c62d491dfb_imageNS'
Thread-49::DEBUG::2012-11-29 20:05:58,827::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '68d8b0e2-c348-4cfe-a896-08c62d491dfb_volumeNS'
Thread-49::DEBUG::2012-11-29 20:05:58,828::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '68d8b0e2-c348-4cfe-a896-08c62d491dfb_lvmActivationNS'
Thread-49::ERROR::2012-11-29 20:05:58,828::sp::1532::Storage.StoragePool::(getMasterDomain) Requested master domain 68d8b0e2-c348-4cfe-a896-08c62d491dfb does not have expected version 3 it is version 4
Thread-49::DEBUG::2012-11-29 20:05:58,829::resourceManager::540::ResourceManager::(releaseResource) Trying to release resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-49::DEBUG::2012-11-29 20:05:58,829::resourceManager::556::ResourceManager::(releaseResource) Released resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' (0 active users)
Thread-49::DEBUG::2012-11-29 20:05:58,829::resourceManager::561::ResourceManager::(releaseResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free, finding out if anyone is waiting for it.
Thread-49::DEBUG::2012-11-29 20:05:58,830::resourceManager::568::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', Clearing records.
Thread-49::ERROR::2012-11-29 20:05:58,830::task::833::TaskManager.Task::(_setError) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::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 918, in connectStoragePool
    masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 965, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 644, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1174, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1533, in getMasterDomain
    raise se.StoragePoolWrongMaster(self.spUUID, msdUUID)
StoragePoolWrongMaster: Wrong Master domain or its version: 'SD=68d8b0e2-c348-4cfe-a896-08c62d491dfb, pool=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-49::DEBUG::2012-11-29 20:05:58,831::task::852::TaskManager.Task::(_run) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::Task._run: d523bdb9-479e-493d-8b83-37349bf6f88f ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 2, 'f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', '68d8b0e2-c348-4cfe-a896-08c62d491dfb', 3) {} failed - stopping task
Thread-49::DEBUG::2012-11-29 20:05:58,831::task::1177::TaskManager.Task::(stop) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::stopping in state preparing (force False)
Thread-49::DEBUG::2012-11-29 20:05:58,831::task::957::TaskManager.Task::(_decref) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::ref 1 aborting True
Thread-49::INFO::2012-11-29 20:05:58,831::task::1134::TaskManager.Task::(prepare) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::aborting: Task is aborted: 'Wrong Master domain or its version' - code 324
Thread-49::DEBUG::2012-11-29 20:05:58,832::task::1139::TaskManager.Task::(prepare) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::Prepare: aborted: Wrong Master domain or its version
Thread-49::DEBUG::2012-11-29 20:05:58,832::task::957::TaskManager.Task::(_decref) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::ref 0 aborting True
Thread-49::DEBUG::2012-11-29 20:05:58,832::task::892::TaskManager.Task::(_doAbort) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::Task._doAbort: force False
Thread-49::DEBUG::2012-11-29 20:05:58,832::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-49::DEBUG::2012-11-29 20:05:58,833::task::568::TaskManager.Task::(_updateState) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::moving from state preparing -> state aborting
Thread-49::DEBUG::2012-11-29 20:05:58,833::task::523::TaskManager.Task::(__state_aborting) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::_aborting: recover policy none
Thread-49::DEBUG::2012-11-29 20:05:58,833::task::568::TaskManager.Task::(_updateState) Task=`d523bdb9-479e-493d-8b83-37349bf6f88f`::moving from state aborting -> state failed
Thread-49::DEBUG::2012-11-29 20:05:58,833::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-49::DEBUG::2012-11-29 20:05:58,834::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-49::ERROR::2012-11-29 20:05:58,834::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Wrong Master domain or its version: 'SD=68d8b0e2-c348-4cfe-a896-08c62d491dfb, pool=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'", 'code': 324}}
Thread-53::DEBUG::2012-11-29 20:06:02,470::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-53::DEBUG::2012-11-29 20:06:02,471::task::568::TaskManager.Task::(_updateState) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::moving from state init -> state preparing
Thread-53::INFO::2012-11-29 20:06:02,471::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', options=None)
Thread-53::ERROR::2012-11-29 20:06:02,471::task::833::TaskManager.Task::(_setError) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::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 597, in getSpmStatus
    pool = self.getPool(spUUID)
  File "/usr/share/vdsm/storage/hsm.py", line 310, in getPool
    raise se.StoragePoolUnknown(spUUID)
StoragePoolUnknown: Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::852::TaskManager.Task::(_run) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::Task._run: d5f089a6-7a43-4198-aa98-f51217d286d6 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',) {} failed - stopping task
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::1177::TaskManager.Task::(stop) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::stopping in state preparing (force False)
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::957::TaskManager.Task::(_decref) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::ref 1 aborting True
Thread-53::INFO::2012-11-29 20:06:02,472::task::1134::TaskManager.Task::(prepare) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::1139::TaskManager.Task::(prepare) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::Prepare: aborted: Unknown pool id, pool not connected
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::957::TaskManager.Task::(_decref) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::ref 0 aborting True
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::892::TaskManager.Task::(_doAbort) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::Task._doAbort: force False
Thread-53::DEBUG::2012-11-29 20:06:02,472::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-53::DEBUG::2012-11-29 20:06:02,472::task::568::TaskManager.Task::(_updateState) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::moving from state preparing -> state aborting
Thread-53::DEBUG::2012-11-29 20:06:02,473::task::523::TaskManager.Task::(__state_aborting) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::_aborting: recover policy none
Thread-53::DEBUG::2012-11-29 20:06:02,473::task::568::TaskManager.Task::(_updateState) Task=`d5f089a6-7a43-4198-aa98-f51217d286d6`::moving from state aborting -> state failed
Thread-53::DEBUG::2012-11-29 20:06:02,473::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-53::DEBUG::2012-11-29 20:06:02,473::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-53::ERROR::2012-11-29 20:06:02,473::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175',)", 'code': 309}}
Thread-54::DEBUG::2012-11-29 20:06:02,487::BindingXMLRPC::161::vds::(wrapper) [192.168.0.2]
Thread-54::DEBUG::2012-11-29 20:06:02,487::task::568::TaskManager.Task::(_updateState) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::moving from state init -> state preparing
Thread-54::INFO::2012-11-29 20:06:02,488::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', hostID=2, scsiKey='f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', msdUUID='68d8b0e2-c348-4cfe-a896-08c62d491dfb', masterVersion=3, options=None)
Thread-54::DEBUG::2012-11-29 20:06:02,488::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`8d229dcf-fd1c-4650-87aa-5ff7e6d1ecb1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
Thread-54::DEBUG::2012-11-29 20:06:02,489::resourceManager::487::ResourceManager::(registerResource) Trying to register resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' for lock type 'exclusive'
Thread-54::DEBUG::2012-11-29 20:06:02,489::resourceManager::530::ResourceManager::(registerResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free. Now locking as 'exclusive' (1 active user)
Thread-54::DEBUG::2012-11-29 20:06:02,489::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175`ReqID=`8d229dcf-fd1c-4650-87aa-5ff7e6d1ecb1`::Granted request
Thread-54::INFO::2012-11-29 20:06:02,491::sp::628::Storage.StoragePool::(connect) Connect host #2 to the storage pool f1b40ecc-b6a9-44e7-92cb-0fdf445e3175 with master domain: 68d8b0e2-c348-4cfe-a896-08c62d491dfb (ver = 3)
Thread-54::ERROR::2012-11-29 20:06:02,491::sp::1532::Storage.StoragePool::(getMasterDomain) Requested master domain 68d8b0e2-c348-4cfe-a896-08c62d491dfb does not have expected version 3 it is version 4
Thread-54::DEBUG::2012-11-29 20:06:02,491::resourceManager::540::ResourceManager::(releaseResource) Trying to release resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-54::DEBUG::2012-11-29 20:06:02,492::resourceManager::556::ResourceManager::(releaseResource) Released resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' (0 active users)
Thread-54::DEBUG::2012-11-29 20:06:02,492::resourceManager::561::ResourceManager::(releaseResource) Resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175' is free, finding out if anyone is waiting for it.
Thread-54::DEBUG::2012-11-29 20:06:02,492::resourceManager::568::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', Clearing records.
Thread-54::ERROR::2012-11-29 20:06:02,492::task::833::TaskManager.Task::(_setError) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::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 918, in connectStoragePool
    masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 965, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 644, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1174, in __rebuild
    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1533, in getMasterDomain
    raise se.StoragePoolWrongMaster(self.spUUID, msdUUID)
StoragePoolWrongMaster: Wrong Master domain or its version: 'SD=68d8b0e2-c348-4cfe-a896-08c62d491dfb, pool=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'
Thread-54::DEBUG::2012-11-29 20:06:02,492::task::852::TaskManager.Task::(_run) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::Task._run: 05f9ada4-f6df-4d2d-8329-3df9f56c1205 ('f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', 2, 'f1b40ecc-b6a9-44e7-92cb-0fdf445e3175', '68d8b0e2-c348-4cfe-a896-08c62d491dfb', 3) {} failed - stopping task
Thread-54::DEBUG::2012-11-29 20:06:02,492::task::1177::TaskManager.Task::(stop) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::stopping in state preparing (force False)
Thread-54::DEBUG::2012-11-29 20:06:02,492::task::957::TaskManager.Task::(_decref) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::ref 1 aborting True
Thread-54::INFO::2012-11-29 20:06:02,493::task::1134::TaskManager.Task::(prepare) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::aborting: Task is aborted: 'Wrong Master domain or its version' - code 324
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::1139::TaskManager.Task::(prepare) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::Prepare: aborted: Wrong Master domain or its version
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::957::TaskManager.Task::(_decref) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::ref 0 aborting True
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::892::TaskManager.Task::(_doAbort) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::Task._doAbort: force False
Thread-54::DEBUG::2012-11-29 20:06:02,493::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::568::TaskManager.Task::(_updateState) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::moving from state preparing -> state aborting
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::523::TaskManager.Task::(__state_aborting) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::_aborting: recover policy none
Thread-54::DEBUG::2012-11-29 20:06:02,493::task::568::TaskManager.Task::(_updateState) Task=`05f9ada4-f6df-4d2d-8329-3df9f56c1205`::moving from state aborting -> state failed
Thread-54::DEBUG::2012-11-29 20:06:02,493::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-54::DEBUG::2012-11-29 20:06:02,493::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-54::ERROR::2012-11-29 20:06:02,493::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Wrong Master domain or its version: 'SD=68d8b0e2-c348-4cfe-a896-08c62d491dfb, pool=f1b40ecc-b6a9-44e7-92cb-0fdf445e3175'", 'code': 324}}
Thread-55::DEBUG::2012-11-29 20:06:03,022::task::568::TaskManager.Task::(_updateState) Task=`4878498d-3f03-4e48-9f8a-b7fadaa205ff`::moving from state init -> state preparing
Thread-55::INFO::2012-11-29 20:06:03,022::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-55::INFO::2012-11-29 20:06:03,022::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-55::DEBUG::2012-11-29 20:06:03,022::task::1151::TaskManager.Task::(prepare) Task=`4878498d-3f03-4e48-9f8a-b7fadaa205ff`::finished: {}
Thread-55::DEBUG::2012-11-29 20:06:03,023::task::568::TaskManager.Task::(_updateState) Task=`4878498d-3f03-4e48-9f8a-b7fadaa205ff`::moving from state preparing -> state finished
Thread-55::DEBUG::2012-11-29 20:06:03,023::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-55::DEBUG::2012-11-29 20:06:03,023::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-55::DEBUG::2012-11-29 20:06:03,023::task::957::TaskManager.Task::(_decref) Task=`4878498d-3f03-4e48-9f8a-b7fadaa205ff`::ref 0 aborting False
MainThread::INFO::2012-11-29 20:06:12,075::vmChannels::136::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2012-11-29 20:06:12,076::momIF::56::MOM::(stop) Shutting down MOM
MainThread::DEBUG::2012-11-29 20:06:12,077::task::568::TaskManager.Task::(_updateState) Task=`77f8ab91-b7ed-4ab1-9dbd-52b380103578`::moving from state init -> state preparing
MainThread::INFO::2012-11-29 20:06:12,077::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2012-11-29 20:06:12,078::storageServer::674::ConnectionMonitor::(_monitorConnections) Monitoring stopped
MainThread::DEBUG::2012-11-29 20:06:12,086::sp::359::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/45fa93a8-1761-4522-bafb-c5d3ab45f731/master` is not mounted, skipping
MainThread::DEBUG::2012-11-29 20:06:12,099::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2012-11-29 20:06:12,099::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2012-11-29 20:06:12,100::task::1151::TaskManager.Task::(prepare) Task=`77f8ab91-b7ed-4ab1-9dbd-52b380103578`::finished: None
MainThread::DEBUG::2012-11-29 20:06:12,100::task::568::TaskManager.Task::(_updateState) Task=`77f8ab91-b7ed-4ab1-9dbd-52b380103578`::moving from state preparing -> state finished
MainThread::DEBUG::2012-11-29 20:06:12,100::resourceManager::812::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2012-11-29 20:06:12,100::resourceManager::847::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2012-11-29 20:06:12,100::task::957::TaskManager.Task::(_decref) Task=`77f8ab91-b7ed-4ab1-9dbd-52b380103578`::ref 0 aborting False
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::94::vds::(run) VDSM main thread ended. Waiting for 16 other threads...
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <Thread(libvirtEventLoop, started daemon 140333134817024)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <WorkerThread(Thread-6, started daemon 140332620576512)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140332033349376)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <GuestManager(GuestManager, started daemon 140332041742080)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <HostMonitor(HostMonitor, started daemon 140332050134784)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <WorkerThread(Thread-9, started daemon 140332595398400)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <WorkerThread(Thread-8, started daemon 140332603791104)>
MainThread::INFO::2012-11-29 20:06:12,100::vdsm::98::vds::(run) <WorkerThread(Thread-7, started daemon 140332612183808)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-10, started daemon 140332587005696)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-1, started daemon 140332999030528)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <_MainThread(MainThread, started 140333359740736)>
MainThread::INFO::2012-11-29 20:06:12,101::vmChannels::136::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <Listener(VM Channels Listener, started daemon 140332058527488)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-5, started daemon 140332965459712)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-4, started daemon 140332973852416)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-2, started daemon 140332990637824)>
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <WorkerThread(Thread-3, started daemon 140332982245120)>
MainThread::INFO::2012-11-29 20:06:12,101::momIF::56::MOM::(stop) Shutting down MOM
MainThread::INFO::2012-11-29 20:06:12,101::vdsm::98::vds::(run) <MomThread(MOM, started 140332075312896)>