Greetings.

This post is related to my previous post (http://lists.ovirt.org/pipermail/users/2013-April/013912.html) but with some more investigation and findings.

When trying to activate my host/node it goes back to non-operational since it's unable to attach the master storage domain.

A few snippet from the log (whole log attached):

Thread-12399::ERROR::2013-04-22 11:02:17,627::sp::1519::Storage.StoragePool::(getMasterDomain) Requested master domain ea5643f7-f41f-4c44-a27f-f31240cd0f19 does not have expected version 110 it is version 1
Thread-12399::INFO::2013-04-22 11:02:17,630::task::1134::TaskManager.Task::(prepare) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::aborting: Task is aborted: 'Wrong Master domain or its version' - code 324
Thread-12399::DEBUG::2013-04-22 11:02:17,630::task::1139::TaskManager.Task::(prepare) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::Prepare: aborted: Wrong Master domain or its version

Not sure if  "does not have expected version 110 it is version 1" is a red herring or if this is actual problem. I get the following output from vdsClient, where no version seem to match versions from the log.

vdsClient -s 0 getStorageDomainInfo ea5643f7-f41f-4c44-a27f-f31240cd0f19
        uuid = ea5643f7-f41f-4c44-a27f-f31240cd0f19
        vguuid = 5Qox85-NQCz-pyVM-aFRN-KJ2P-jB1T-IiETQr
        lver = -1
        state = OK
        version = 3
        role = Master
        pool = ['dae1ba5e-548a-473e-94b6-7d08d3a6229a']
        spm_id = -1
        type = ISCSI
        class = Data
        master_ver = 0
        name = hinken

Found these that seem somewhat similar:
https://bugzilla.redhat.com/show_bug.cgi?id=784038
http://lists.ovirt.org/pipermail/users/2012-December/010982.html


My whole site is dead now due to this, so any help to the resolve the issue would be greatly appreciated.

With kind regards
Jonas

vdsm.log

Thread-12388::DEBUG::2013-04-22 11:02:09,292::BindingXMLRPC::913::vds::(wrapper) client [46.22.124.43]::call getCapabilities with () {}
Thread-12388::DEBUG::2013-04-22 11:02:09,349::BindingXMLRPC::920::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:a07da5fa539'}], 'FC': []}, 'packages2': {'kernel': {'release': '205.fc18.x86_64', 'buildtime': 1361736602.0, 'version': '3.7.9'}, 'spice-server': {'release': '3.fc18', 'buildtime': 1358784016L, 'version': '0.12.2'}, 'vdsm': {'release': '9.fc18', 'buildtime': 1362046220L, 'version': '4.10.3'}, 'qemu-kvm': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'libvirt': {'release': '1.fc18', 'buildtime': 1359405439L, 'version': '0.10.2.3'}, 'qemu-img': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'mom': {'release': '1.fc18', 'buildtime': 1349470214L, 'version': '0.3.0'}}, 'cpuModel': 'AMD Opteron(TM) Processor 6276', 'hooks': {}, 'cpuSockets': '4', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networ!
 ks': {'ovi
rtmgmt': {'iface': 'ovirtmgmt', 'addr': '46.22.124.37', 'cfg': {'IPADDR': '46.22.124.37', 'PEERDNS': 'no', 'GATEWAY': '46.22.124.36', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.224', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.224', 'stp': 'off', 'bridged': True, 'gateway': '46.22.124.36', 'ports': ['em1']}, 'san': {'iface': 'san', 'addr': '192.168.43.11', 'cfg': {'IPADDR': '192.168.43.11', 'PEERDNS': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'san', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em2']}, 'vminternet': {'iface': 'vminternet', 'addr': '', 'cfg': {'PEERDNS': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'vminternet', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu'!
 : '1500', 
'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em4']}}, 'bridges': {'ovirtmgmt': {'addr': '46.22.124.37', 'cfg': {'IPADDR': '46.22.124.37', 'PEERDNS': 'no', 'GATEWAY': '46.22.124.36', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.224', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.224', 'stp': 'off', 'ports': ['em1']}, 'san': {'addr': '192.168.43.11', 'cfg': {'IPADDR': '192.168.43.11', 'PEERDNS': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'san', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['em2']}, 'vminternet': {'addr': '', 'cfg': {'PEERDNS': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'vminternet', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', '!
 ports': ['
em4']}}, 'uuid': '4C4C4544-0042-4710-8030-B3C04F37354A', 'lastClientIface': 'ovirtmgmt', 'nics': {'em4': {'addr': '', 'cfg': {'BRIDGE': 'vminternet', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:20', 'STP': 'no', 'DEVICE': 'em4', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:20', 'speed': 100}, 'em1': {'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:1a', 'STP': 'no', 'DEVICE': 'em1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1a', 'speed': 1000}, 'em3': {'addr': '', 'cfg': {'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:1e', 'STP': 'no', 'DEVICE': 'em3', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1e', 'speed': 0}, 'em2': {'addr': '', 'cfg': {'BRIDGE': 'san', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'MTU': '9000', 'HWADDR': 'd0:67:e5:f9:2e:1c', 'STP': 'no', 'DEVICE': 'em2', 'ONBOOT': 'yes'!
 }, 'mtu': 
'9000', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1c', 'speed': 1000}}, 'software_revision': '9', '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,mmx,fxsr,sse,sse2,ht,syscall,nx,mmxext,fxsr_opt,pdpe1gb,rdtscp,lm,constant_tsc,rep_good,nopl,nonstop_tsc,extd_apicid,amd_dcm,aperfmperf,pni,pclmulqdq,monitor,ssse3,cx16,sse4_1,sse4_2,popcnt,aes,xsave,avx,lahf_lm,cmp_legacy,svm,extapic,cr8_legacy,abm,sse4a,misalignsse,3dnowprefetch,osvw,ibs,xop,skinit,wdt,lwp,fma4,nodeid_msr,topoext,perfctr_core,arat,cpb,hw_pstate,npt,lbrv,svm_lock,nrip_save,tsc_scale,vmcb_clean,flushbyasid,decodeassists,pausefilter,pfthreshold,model_Opteron_G3,model_Opteron_G1,model_Opteron_G4,model_Opteron_G2', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:a07da5fa539', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 's!
 laves': []
, 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.10', 'memSize': '64210', 'cpuSpeed': '2299.953', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '32', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', 'cpuThreads': '32', 'emulatedMachines': [u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem'!
 : {'releas
e': '20120228.fc18', 'version': '2.6.1', 'name': 'oVirt Node'}, 'lastClient': '46.22.124.43'}}
Thread-12389::DEBUG::2013-04-22 11:02:09,364::BindingXMLRPC::913::vds::(wrapper) client [46.22.124.43]::call getHardwareInfo with () {}
Thread-12389::DEBUG::2013-04-22 11:02:09,365::BindingXMLRPC::920::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'PowerEdge R715', 'systemSerialNumber': '3BG075J', 'systemFamily': 'Not Specified', 'systemVersion': 'Not Specified', 'systemUUID': '4C4C4544-0042-4710-8030-B3C04F37354A', 'systemManufacturer': 'Dell Inc.'}}
Thread-12390::DEBUG::2013-04-22 11:02:11,238::BindingXMLRPC::913::vds::(wrapper) client [46.22.124.43]::call getCapabilities with () {}
Thread-12390::DEBUG::2013-04-22 11:02:11,296::BindingXMLRPC::920::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:a07da5fa539'}], 'FC': []}, 'packages2': {'kernel': {'release': '205.fc18.x86_64', 'buildtime': 1361736602.0, 'version': '3.7.9'}, 'spice-server': {'release': '3.fc18', 'buildtime': 1358784016L, 'version': '0.12.2'}, 'vdsm': {'release': '9.fc18', 'buildtime': 1362046220L, 'version': '4.10.3'}, 'qemu-kvm': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'libvirt': {'release': '1.fc18', 'buildtime': 1359405439L, 'version': '0.10.2.3'}, 'qemu-img': {'release': '6.fc18', 'buildtime': 1359843954L, 'version': '1.2.2'}, 'mom': {'release': '1.fc18', 'buildtime': 1349470214L, 'version': '0.3.0'}}, 'cpuModel': 'AMD Opteron(TM) Processor 6276', 'hooks': {}, 'cpuSockets': '4', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networ!
 ks': {'ovi
rtmgmt': {'iface': 'ovirtmgmt', 'addr': '46.22.124.37', 'cfg': {'IPADDR': '46.22.124.37', 'PEERDNS': 'no', 'GATEWAY': '46.22.124.36', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.224', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.224', 'stp': 'off', 'bridged': True, 'gateway': '46.22.124.36', 'ports': ['em1']}, 'san': {'iface': 'san', 'addr': '192.168.43.11', 'cfg': {'IPADDR': '192.168.43.11', 'PEERDNS': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'san', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em2']}, 'vminternet': {'iface': 'vminternet', 'addr': '', 'cfg': {'PEERDNS': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'vminternet', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu'!
 : '1500', 
'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em4']}}, 'bridges': {'ovirtmgmt': {'addr': '46.22.124.37', 'cfg': {'IPADDR': '46.22.124.37', 'PEERDNS': 'no', 'GATEWAY': '46.22.124.36', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.224', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.224', 'stp': 'off', 'ports': ['em1']}, 'san': {'addr': '192.168.43.11', 'cfg': {'IPADDR': '192.168.43.11', 'PEERDNS': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'san', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'ports': ['em2']}, 'vminternet': {'addr': '', 'cfg': {'PEERDNS': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'vminternet', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', '!
 ports': ['
em4']}}, 'uuid': '4C4C4544-0042-4710-8030-B3C04F37354A', 'lastClientIface': 'ovirtmgmt', 'nics': {'em4': {'addr': '', 'cfg': {'BRIDGE': 'vminternet', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:20', 'STP': 'no', 'DEVICE': 'em4', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:20', 'speed': 100}, 'em1': {'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:1a', 'STP': 'no', 'DEVICE': 'em1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1a', 'speed': 1000}, 'em3': {'addr': '', 'cfg': {'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'HWADDR': 'd0:67:e5:f9:2e:1e', 'STP': 'no', 'DEVICE': 'em3', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1e', 'speed': 0}, 'em2': {'addr': '', 'cfg': {'BRIDGE': 'san', 'NM_CONTROLLED': 'no', 'PEERDNS': 'no', 'MTU': '9000', 'HWADDR': 'd0:67:e5:f9:2e:1c', 'STP': 'no', 'DEVICE': 'em2', 'ONBOOT': 'yes'!
 }, 'mtu': 
'9000', 'netmask': '', 'hwaddr': 'd0:67:e5:f9:2e:1c', 'speed': 1000}}, 'software_revision': '9', '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,mmx,fxsr,sse,sse2,ht,syscall,nx,mmxext,fxsr_opt,pdpe1gb,rdtscp,lm,constant_tsc,rep_good,nopl,nonstop_tsc,extd_apicid,amd_dcm,aperfmperf,pni,pclmulqdq,monitor,ssse3,cx16,sse4_1,sse4_2,popcnt,aes,xsave,avx,lahf_lm,cmp_legacy,svm,extapic,cr8_legacy,abm,sse4a,misalignsse,3dnowprefetch,osvw,ibs,xop,skinit,wdt,lwp,fma4,nodeid_msr,topoext,perfctr_core,arat,cpb,hw_pstate,npt,lbrv,svm_lock,nrip_save,tsc_scale,vmcb_clean,flushbyasid,decodeassists,pausefilter,pfthreshold,model_Opteron_G3,model_Opteron_G1,model_Opteron_G4,model_Opteron_G2', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:a07da5fa539', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1'], 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 's!
 laves': []
, 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.10', 'memSize': '64210', 'cpuSpeed': '2299.953', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '32', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '', 'cpuThreads': '32', 'emulatedMachines': [u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-1.2', u'none', u'pc', u'pc-1.1', u'pc-1.0', u'pc-0.15', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem'!
 : {'releas
e': '20120228.fc18', 'version': '2.6.1', 'name': 'oVirt Node'}, 'lastClient': '46.22.124.43'}}
Thread-12391::DEBUG::2013-04-22 11:02:11,306::BindingXMLRPC::913::vds::(wrapper) client [46.22.124.43]::call getHardwareInfo with () {}
Thread-12391::DEBUG::2013-04-22 11:02:11,307::BindingXMLRPC::920::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'PowerEdge R715', 'systemSerialNumber': '3BG075J', 'systemFamily': 'Not Specified', 'systemVersion': 'Not Specified', 'systemUUID': '4C4C4544-0042-4710-8030-B3C04F37354A', 'systemManufacturer': 'Dell Inc.'}}
Thread-12393::DEBUG::2013-04-22 11:02:11,366::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12393::DEBUG::2013-04-22 11:02:11,367::task::568::TaskManager.Task::(_updateState) Task=`bf358e1a-079c-4d29-8a9b-99cd5267d4f8`::moving from state init -> state preparing
Thread-12393::INFO::2013-04-22 11:02:11,367::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=3, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10', 'iqn': 'iqn.2012-02.se.elementary:ovirt', 'portal': '1', 'user': '', 'password': '******', 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4', 'port': '3260'}], options=None)
Thread-12393::INFO::2013-04-22 11:02:11,368::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4'}]}
Thread-12393::DEBUG::2013-04-22 11:02:11,368::task::1151::TaskManager.Task::(prepare) Task=`bf358e1a-079c-4d29-8a9b-99cd5267d4f8`::finished: {'statuslist': [{'status': 0, 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4'}]}
Thread-12393::DEBUG::2013-04-22 11:02:11,368::task::568::TaskManager.Task::(_updateState) Task=`bf358e1a-079c-4d29-8a9b-99cd5267d4f8`::moving from state preparing -> state finished
Thread-12393::DEBUG::2013-04-22 11:02:11,368::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12393::DEBUG::2013-04-22 11:02:11,368::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12393::DEBUG::2013-04-22 11:02:11,368::task::957::TaskManager.Task::(_decref) Task=`bf358e1a-079c-4d29-8a9b-99cd5267d4f8`::ref 0 aborting False
Thread-12394::DEBUG::2013-04-22 11:02:11,378::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12394::DEBUG::2013-04-22 11:02:11,379::task::568::TaskManager.Task::(_updateState) Task=`e6d93206-9c45-4326-b1f5-bc74775605a1`::moving from state init -> state preparing
Thread-12394::INFO::2013-04-22 11:02:11,379::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10:/storage/ovirt/nfs/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be', 'port': ''}], options=None)
Thread-12394::INFO::2013-04-22 11:02:11,379::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be'}]}
Thread-12394::DEBUG::2013-04-22 11:02:11,379::task::1151::TaskManager.Task::(prepare) Task=`e6d93206-9c45-4326-b1f5-bc74775605a1`::finished: {'statuslist': [{'status': 0, 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be'}]}
Thread-12394::DEBUG::2013-04-22 11:02:11,379::task::568::TaskManager.Task::(_updateState) Task=`e6d93206-9c45-4326-b1f5-bc74775605a1`::moving from state preparing -> state finished
Thread-12394::DEBUG::2013-04-22 11:02:11,380::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12394::DEBUG::2013-04-22 11:02:11,380::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12394::DEBUG::2013-04-22 11:02:11,380::task::957::TaskManager.Task::(_decref) Task=`e6d93206-9c45-4326-b1f5-bc74775605a1`::ref 0 aborting False
Thread-12395::DEBUG::2013-04-22 11:02:11,387::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12395::DEBUG::2013-04-22 11:02:11,387::task::568::TaskManager.Task::(_updateState) Task=`5348f964-3322-4250-a78a-d35e682664dd`::moving from state init -> state preparing
Thread-12395::INFO::2013-04-22 11:02:11,388::logUtils::41::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10:/storage/ovirt/nfs/export_domain', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba', 'port': ''}], options=None)
Thread-12395::INFO::2013-04-22 11:02:11,388::logUtils::44::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba'}]}
Thread-12395::DEBUG::2013-04-22 11:02:11,388::task::1151::TaskManager.Task::(prepare) Task=`5348f964-3322-4250-a78a-d35e682664dd`::finished: {'statuslist': [{'status': 0, 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba'}]}
Thread-12395::DEBUG::2013-04-22 11:02:11,388::task::568::TaskManager.Task::(_updateState) Task=`5348f964-3322-4250-a78a-d35e682664dd`::moving from state preparing -> state finished
Thread-12395::DEBUG::2013-04-22 11:02:11,388::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12395::DEBUG::2013-04-22 11:02:11,388::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12395::DEBUG::2013-04-22 11:02:11,389::task::957::TaskManager.Task::(_decref) Task=`5348f964-3322-4250-a78a-d35e682664dd`::ref 0 aborting False
Thread-12396::DEBUG::2013-04-22 11:02:11,396::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12396::DEBUG::2013-04-22 11:02:11,396::task::568::TaskManager.Task::(_updateState) Task=`f5d1e7c3-a014-4d63-983b-6dc088a56f49`::moving from state init -> state preparing
Thread-12396::INFO::2013-04-22 11:02:11,397::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10', 'iqn': 'iqn.2012-02.se.elementary:ovirt', 'portal': '1', 'user': '', 'password': '******', 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4', 'port': '3260'}], options=None)
Thread-12396::DEBUG::2013-04-22 11:02:11,397::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-02.se.elementary:ovirt -I default -p 192.168.43.10:3260 --op=new' (cwd None)
Thread-12396::DEBUG::2013-04-22 11:02:11,420::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12396::DEBUG::2013-04-22 11:02:11,421::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-02.se.elementary:ovirt -I default -p 192.168.43.10:3260 -l' (cwd None)
Thread-12396::DEBUG::2013-04-22 11:02:11,441::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12396::DEBUG::2013-04-22 11:02:11,442::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-02.se.elementary:ovirt -I default -p 192.168.43.10:3260 -n node.startup -v manual --op=update' (cwd None)
Thread-12396::DEBUG::2013-04-22 11:02:11,460::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12396::INFO::2013-04-22 11:02:11,460::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4'}]}
Thread-12396::DEBUG::2013-04-22 11:02:11,461::task::1151::TaskManager.Task::(prepare) Task=`f5d1e7c3-a014-4d63-983b-6dc088a56f49`::finished: {'statuslist': [{'status': 0, 'id': '906d9ac3-4ea0-4c5c-bb74-207f768412c4'}]}
Thread-12396::DEBUG::2013-04-22 11:02:11,461::task::568::TaskManager.Task::(_updateState) Task=`f5d1e7c3-a014-4d63-983b-6dc088a56f49`::moving from state preparing -> state finished
Thread-12396::DEBUG::2013-04-22 11:02:11,461::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12396::DEBUG::2013-04-22 11:02:11,461::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12396::DEBUG::2013-04-22 11:02:11,462::task::957::TaskManager.Task::(_decref) Task=`f5d1e7c3-a014-4d63-983b-6dc088a56f49`::ref 0 aborting False
Thread-12397::DEBUG::2013-04-22 11:02:11,470::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12397::DEBUG::2013-04-22 11:02:11,470::task::568::TaskManager.Task::(_updateState) Task=`768743d8-d35d-4a1d-b861-b8ef0d74000c`::moving from state init -> state preparing
Thread-12397::INFO::2013-04-22 11:02:11,471::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10:/storage/ovirt/nfs/iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be', 'port': ''}], options=None)
Thread-12397::INFO::2013-04-22 11:02:12,695::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be'}]}
Thread-12397::DEBUG::2013-04-22 11:02:12,696::task::1151::TaskManager.Task::(prepare) Task=`768743d8-d35d-4a1d-b861-b8ef0d74000c`::finished: {'statuslist': [{'status': 0, 'id': '480ce9bb-4299-43f8-9fe0-8fbac71e54be'}]}
Thread-12397::DEBUG::2013-04-22 11:02:12,696::task::568::TaskManager.Task::(_updateState) Task=`768743d8-d35d-4a1d-b861-b8ef0d74000c`::moving from state preparing -> state finished
Thread-12397::DEBUG::2013-04-22 11:02:12,696::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12397::DEBUG::2013-04-22 11:02:12,696::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12397::DEBUG::2013-04-22 11:02:12,696::task::957::TaskManager.Task::(_decref) Task=`768743d8-d35d-4a1d-b861-b8ef0d74000c`::ref 0 aborting False
Thread-12398::DEBUG::2013-04-22 11:02:12,705::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12398::DEBUG::2013-04-22 11:02:12,705::task::568::TaskManager.Task::(_updateState) Task=`cd8323a6-b1fe-4fc3-a457-c352bb0712f7`::moving from state init -> state preparing
Thread-12398::INFO::2013-04-22 11:02:12,706::logUtils::41::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', conList=[{'connection': '192.168.43.10:/storage/ovirt/nfs/export_domain', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba', 'port': ''}], options=None)
Thread-12398::INFO::2013-04-22 11:02:13,902::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba'}]}
Thread-12398::DEBUG::2013-04-22 11:02:13,903::task::1151::TaskManager.Task::(prepare) Task=`cd8323a6-b1fe-4fc3-a457-c352bb0712f7`::finished: {'statuslist': [{'status': 0, 'id': 'cbec69e2-884b-4904-89ec-4b947e1f33ba'}]}
Thread-12398::DEBUG::2013-04-22 11:02:13,903::task::568::TaskManager.Task::(_updateState) Task=`cd8323a6-b1fe-4fc3-a457-c352bb0712f7`::moving from state preparing -> state finished
Thread-12398::DEBUG::2013-04-22 11:02:13,903::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12398::DEBUG::2013-04-22 11:02:13,903::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12398::DEBUG::2013-04-22 11:02:13,903::task::957::TaskManager.Task::(_decref) Task=`cd8323a6-b1fe-4fc3-a457-c352bb0712f7`::ref 0 aborting False
Thread-12399::DEBUG::2013-04-22 11:02:13,917::BindingXMLRPC::161::vds::(wrapper) [46.22.124.43]
Thread-12399::DEBUG::2013-04-22 11:02:13,917::task::568::TaskManager.Task::(_updateState) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::moving from state init -> state preparing
Thread-12399::INFO::2013-04-22 11:02:13,918::logUtils::41::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='dae1ba5e-548a-473e-94b6-7d08d3a6229a', hostID=1, scsiKey='dae1ba5e-548a-473e-94b6-7d08d3a6229a', msdUUID='ea5643f7-f41f-4c44-a27f-f31240cd0f19', masterVersion=110, options=None)
Thread-12399::DEBUG::2013-04-22 11:02:13,918::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a`ReqID=`15473924-edce-43f6-a4dc-04b7fa1aff61`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__'
Thread-12399::DEBUG::2013-04-22 11:02:13,918::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a' for lock type 'exclusive'
Thread-12399::DEBUG::2013-04-22 11:02:13,919::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a' is free. Now locking as 'exclusive' (1 active user)
Thread-12399::DEBUG::2013-04-22 11:02:13,919::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a`ReqID=`15473924-edce-43f6-a4dc-04b7fa1aff61`::Granted request
Thread-12399::INFO::2013-04-22 11:02:13,920::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool dae1ba5e-548a-473e-94b6-7d08d3a6229a with master domain: ea5643f7-f41f-4c44-a27f-f31240cd0f19 (ver = 110)
Thread-12399::DEBUG::2013-04-22 11:02:13,920::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,921::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,921::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,921::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,921::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,922::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:13,922::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-12399::DEBUG::2013-04-22 11:02:13,922::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-12399::DEBUG::2013-04-22 11:02:13,922::misc::1054::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-12399::DEBUG::2013-04-22 11:02:13,923::misc::1056::SamplingMethod::(__call__) Got in to sampling method
Thread-12399::DEBUG::2013-04-22 11:02:13,923::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-12399::DEBUG::2013-04-22 11:02:13,947::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:13,948::misc::1064::SamplingMethod::(__call__) Returning last result
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,950::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,955::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,959::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,964::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,968::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,972::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,976::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,980::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host7/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,985::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host8/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,989::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd of=/sys/class/scsi_host/host10/scan' (cwd None)
MainProcess|Thread-12399::DEBUG::2013-04-22 11:02:13,993::iscsi::402::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
Thread-12399::DEBUG::2013-04-22 11:02:15,997::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-12399::DEBUG::2013-04-22 11:02:16,048::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:16,048::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,049::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,049::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,049::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,049::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,050::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,050::misc::1064::SamplingMethod::(__call__) Returning last result
Thread-12399::DEBUG::2013-04-22 11:02:16,050::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,057::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00020001|1IET_00020002|1IET_00020003|3500000e019ee26e0|3500000e019ee27f0|3500000e019ee2830|3500000e019efff80|3600508e000000000fdc993aef946ac0f%\\", \\"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 ea5643f7-f41f-4c44-a27f-f31240cd0f19' (cwd None)
Thread-12399::DEBUG::2013-04-22 11:02:16,243::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:16,245::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:16,245::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
Thread-12399::DEBUG::2013-04-22 11:02:17,380::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/dd iflag=direct skip=0 bs=2048 if=/dev/ea5643f7-f41f-4c44-a27f-f31240cd0f19/metadata count=1' (cwd None)
Thread-12399::DEBUG::2013-04-22 11:02:17,390::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000642052 s, 3.2 MB/s\n'; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:17,390::misc::325::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000642052 s, 3.2 MB/s'], size: 2048
Thread-12399::DEBUG::2013-04-22 11:02:17,390::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
Thread-12399::WARNING::2013-04-22 11:02:17,391::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-12399::DEBUG::2013-04-22 11:02:17,392::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
Thread-12399::DEBUG::2013-04-22 11:02:17,392::lvm::483::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,393::lvm::485::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,393::lvm::493::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,393::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,394::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,394::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00020001|1IET_00020002|1IET_00020003|3500000e019ee26e0|3500000e019ee27f0|3500000e019ee2830|3500000e019efff80|3600508e000000000fdc993aef946ac0f%\\", \\"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 ea5643f7-f41f-4c44-a27f-f31240cd0f19' (cwd None)
Thread-12399::DEBUG::2013-04-22 11:02:17,504::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:17,506::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,507::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['PHYBLKSIZE=4096', 'SDUUID=ea5643f7-f41f-4c44-a27f-f31240cd0f19', 'VERSION=3', 'TYPE=ISCSI', u'PV0=pv:1IET_00020001,uuid:0RBLsc-FB0t-RA6I-d12o-jtUx-lIx3-eQwv8Z,pestart:0,pecount:1951,mapoffset:0', 'LOGBLKSIZE=512', 'LEASERETRIES=3', 'DESCRIPTION=hinken', 'LOCKRENEWALINTERVALSEC=5', 'LOCKPOLICY=', 'VGUUID=5Qox85-NQCz-pyVM-aFRN-KJ2P-jB1T-IiETQr', 'CLASS=Data', 'LEASETIMESEC=60', 'IOOPTIMEOUTSEC=10', 'MASTER_VERSION=1', 'ROLE=Master', 'POOL_DESCRIPTION=Elementary', 'POOL_UUID=dae1ba5e-548a-473e-94b6-7d08d3a6229a', 'POOL_SPM_ID=1', u'POOL_DOMAINS=ea5643f7-f41f-4c44-a27f-f31240cd0f19:Active,c5c68e94-14c6-4b29-8f83-2daa680dc6c0:Active,fecb861a-5cf6-4f1e-8bfe-b7a71e122c2f:Active,9f296bdb-2903-4e8c-a019-f10bc3ae4d17:Active,c7452b13-e72e-4ce8-83e1-79c22f76dabf:Active', 'POOL_SPM_LVER=12', '_SHA_CKSUM=0924d492075d543bc008063efa0cd0239f60920e']
Thread-12399::DEBUG::2013-04-22 11:02:17,508::lvm::334::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
Thread-12399::DEBUG::2013-04-22 11:02:17,508::misc::84::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1IET_00020001|1IET_00020002|1IET_00020003|3500000e019ee26e0|3500000e019ee27f0|3500000e019ee2830|3500000e019efff80|3600508e000000000fdc993aef946ac0f%\\", \\"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-12399::DEBUG::2013-04-22 11:02:17,624::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
Thread-12399::DEBUG::2013-04-22 11:02:17,625::lvm::359::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
Thread-12399::WARNING::2013-04-22 11:02:17,626::sd::361::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ea5643f7-f41f-4c44-a27f-f31240cd0f19_imageNS already registered
Thread-12399::WARNING::2013-04-22 11:02:17,626::sd::369::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ea5643f7-f41f-4c44-a27f-f31240cd0f19_volumeNS already registered
Thread-12399::WARNING::2013-04-22 11:02:17,626::blockSD::432::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ea5643f7-f41f-4c44-a27f-f31240cd0f19_lvmActivationNS already registered
Thread-12399::ERROR::2013-04-22 11:02:17,627::sp::1519::Storage.StoragePool::(getMasterDomain) Requested master domain ea5643f7-f41f-4c44-a27f-f31240cd0f19 does not have expected version 110 it is version 1
Thread-12399::DEBUG::2013-04-22 11:02:17,627::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a'
Thread-12399::DEBUG::2013-04-22 11:02:17,628::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a' (0 active users)
Thread-12399::DEBUG::2013-04-22 11:02:17,628::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a' is free, finding out if anyone is waiting for it.
Thread-12399::DEBUG::2013-04-22 11:02:17,628::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.dae1ba5e-548a-473e-94b6-7d08d3a6229a', Clearing records.
Thread-12399::ERROR::2013-04-22 11:02:17,628::task::833::TaskManager.Task::(_setError) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 840, in _run
  File "/usr/share/vdsm/logUtils.py", line 42, in wrapper
  File "/usr/share/vdsm/storage/hsm.py", line 926, in connectStoragePool
  File "/usr/share/vdsm/storage/hsm.py", line 973, in _connectStoragePool
  File "/usr/share/vdsm/storage/sp.py", line 642, in connect
  File "/usr/share/vdsm/storage/sp.py", line 1166, in __rebuild
  File "/usr/share/vdsm/storage/sp.py", line 1520, in getMasterDomain
StoragePoolWrongMaster: Wrong Master domain or its version: 'SD=ea5643f7-f41f-4c44-a27f-f31240cd0f19, pool=dae1ba5e-548a-473e-94b6-7d08d3a6229a'
Thread-12399::DEBUG::2013-04-22 11:02:17,629::task::852::TaskManager.Task::(_run) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::Task._run: 086e8dc5-7bbd-499e-a12d-736cb14fe79b ('dae1ba5e-548a-473e-94b6-7d08d3a6229a', 1, 'dae1ba5e-548a-473e-94b6-7d08d3a6229a', 'ea5643f7-f41f-4c44-a27f-f31240cd0f19', 110) {} failed - stopping task
Thread-12399::DEBUG::2013-04-22 11:02:17,629::task::1177::TaskManager.Task::(stop) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::stopping in state preparing (force False)
Thread-12399::DEBUG::2013-04-22 11:02:17,630::task::957::TaskManager.Task::(_decref) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::ref 1 aborting True
Thread-12399::INFO::2013-04-22 11:02:17,630::task::1134::TaskManager.Task::(prepare) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::aborting: Task is aborted: 'Wrong Master domain or its version' - code 324
Thread-12399::DEBUG::2013-04-22 11:02:17,630::task::1139::TaskManager.Task::(prepare) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::Prepare: aborted: Wrong Master domain or its version
Thread-12399::DEBUG::2013-04-22 11:02:17,630::task::957::TaskManager.Task::(_decref) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::ref 0 aborting True
Thread-12399::DEBUG::2013-04-22 11:02:17,630::task::892::TaskManager.Task::(_doAbort) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::Task._doAbort: force False
Thread-12399::DEBUG::2013-04-22 11:02:17,631::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12399::DEBUG::2013-04-22 11:02:17,631::task::568::TaskManager.Task::(_updateState) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::moving from state preparing -> state aborting
Thread-12399::DEBUG::2013-04-22 11:02:17,631::task::523::TaskManager.Task::(__state_aborting) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::_aborting: recover policy none
Thread-12399::DEBUG::2013-04-22 11:02:17,631::task::568::TaskManager.Task::(_updateState) Task=`086e8dc5-7bbd-499e-a12d-736cb14fe79b`::moving from state aborting -> state failed
Thread-12399::DEBUG::2013-04-22 11:02:17,631::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-12399::DEBUG::2013-04-22 11:02:17,632::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-12399::ERROR::2013-04-22 11:02:17,632::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Wrong Master domain or its version: 'SD=ea5643f7-f41f-4c44-a27f-f31240cd0f19, pool=dae1ba5e-548a-473e-94b6-7d08d3a6229a'", 'code': 324}}