Thread-962::DEBUG::2012-05-21 17:21:22,394::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-962::DEBUG::2012-05-21 17:21:22,394::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-962::DEBUG::2012-05-21 17:21:22,395::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-962::DEBUG::2012-05-21 17:21:22,395::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-962::INFO::2012-05-21 17:21:22,395::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-962::DEBUG::2012-05-21 17:21:22,396::task::1172::TaskManager.Task::(prepare) Task=`a7ace2df-cc77-4b1f-9acc-40e22f8a30be`::finished: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-962::DEBUG::2012-05-21 17:21:22,396::task::588::TaskManager.Task::(_updateState) Task=`a7ace2df-cc77-4b1f-9acc-40e22f8a30be`::moving from state preparing -> state finished
Thread-962::DEBUG::2012-05-21 17:21:22,396::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-962::DEBUG::2012-05-21 17:21:22,396::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-962::DEBUG::2012-05-21 17:21:22,397::task::978::TaskManager.Task::(_decref) Task=`a7ace2df-cc77-4b1f-9acc-40e22f8a30be`::ref 0 aborting False
Thread-963::DEBUG::2012-05-21 17:22:37,403::BindingXMLRPC::849::vds::(wrapper) client [192.168.131.42]::call getCapabilities with () {} flowID [15a6de5d]
Thread-963::DEBUG::2012-05-21 17:22:37,431::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-963::DEBUG::2012-05-21 17:22:37,451::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-963::DEBUG::2012-05-21 17:22:37,451::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-963::DEBUG::2012-05-21 17:22:37,470::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-963::DEBUG::2012-05-21 17:22:37,471::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-963::DEBUG::2012-05-21 17:22:37,489::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-963::DEBUG::2012-05-21 17:22:37,490::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-963::DEBUG::2012-05-21 17:22:37,508::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-963::DEBUG::2012-05-21 17:22:37,509::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-963::DEBUG::2012-05-21 17:22:37,526::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-963::DEBUG::2012-05-21 17:22:37,527::BindingXMLRPC::855::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:b4d681a351bc'}], 'FC': []}, 'packages2': {'kernel': {'release': '2.fc16.x86_64', 'buildtime': 1336461890.0, 'version': '3.3.5'}, 'spice-server': {'release': '1.fc16', 'buildtime': '1327339129', 'version': '0.10.1'}, 'vdsm': {'release': '0.229.git9fcc7a2.fc16', 'buildtime': '1337596632', 'version': '4.9.6'}, 'qemu-kvm': {'release': '17.fc16', 'buildtime': '1336368255', 'version': '1.0'}, 'libvirt': {'release': '1.fc16', 'buildtime': '1336378261', 'version': '0.9.11.3'}, 'qemu-img': {'release': '17.fc16', 'buildtime': '1336368255', 'version': '1.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '192.168.130.238', 'cfg': {'DOMAIN': 'rakurs.com', 'DNS1': '192.168.131.17', 'IPADDR': '192.168.130.238', 'GATEWAY': '192.168.131.17', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.0.0', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.0.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.131.17', 'ports': ['em1']}, 'Storage': {'addr': '172.16.0.105', 'cfg': {'IPADDR': '172.16.0.105', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'STP': 'no', 'DEVICE': 'Storage', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em2']}}, 'uuid': '49434D53-0200-9066-2500-66902500FE53_00:25:90:66:53:fe', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'hwaddr': '00:25:90:66:53:fe', 'netmask': '', 'speed': 100, 'addr': '', 'mtu': '1500'}, 'em2': {'hwaddr': '00:25:90:66:53:ff', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,arat,epb,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:b4d681a351bc', 'memSize': '36200', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': '1600.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '16', 'name': 'oVirt Node'}, 'lastClient': '192.168.131.42'}}
Thread-964::DEBUG::2012-05-21 17:22:38,478::BindingXMLRPC::849::vds::(wrapper) client [192.168.131.42]::call getCapabilities with () {} flowID [20450ec2]
Thread-964::DEBUG::2012-05-21 17:22:38,506::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-kvm' (cwd None)
Thread-964::DEBUG::2012-05-21 17:22:38,525::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-964::DEBUG::2012-05-21 17:22:38,525::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" qemu-img' (cwd None)
Thread-964::DEBUG::2012-05-21 17:22:38,545::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-964::DEBUG::2012-05-21 17:22:38,546::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" vdsm' (cwd None)
Thread-964::DEBUG::2012-05-21 17:22:38,566::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-964::DEBUG::2012-05-21 17:22:38,567::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" spice-server' (cwd None)
Thread-964::DEBUG::2012-05-21 17:22:38,588::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-964::DEBUG::2012-05-21 17:22:38,588::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/rpm -q --qf "%{NAME}\t%{VERSION}\t%{RELEASE}\t%{BUILDTIME}\n" libvirt' (cwd None)
Thread-964::DEBUG::2012-05-21 17:22:38,609::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-964::DEBUG::2012-05-21 17:22:38,610::BindingXMLRPC::855::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:b4d681a351bc'}], 'FC': []}, 'packages2': {'kernel': {'release': '2.fc16.x86_64', 'buildtime': 1336461890.0, 'version': '3.3.5'}, 'spice-server': {'release': '1.fc16', 'buildtime': '1327339129', 'version': '0.10.1'}, 'vdsm': {'release': '0.229.git9fcc7a2.fc16', 'buildtime': '1337596632', 'version': '4.9.6'}, 'qemu-kvm': {'release': '17.fc16', 'buildtime': '1336368255', 'version': '1.0'}, 'libvirt': {'release': '1.fc16', 'buildtime': '1336378261', 'version': '0.9.11.3'}, 'qemu-img': {'release': '17.fc16', 'buildtime': '1336368255', 'version': '1.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'addr': '192.168.130.238', 'cfg': {'DOMAIN': 'rakurs.com', 'DNS1': '192.168.131.17', 'IPADDR': '192.168.130.238', 'GATEWAY': '192.168.131.17', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.0.0', 'BOOTPROTO': 'none', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.0.0', 'stp': 'off', 'bridged': True, 'gateway': '192.168.131.17', 'ports': ['em1']}, 'Storage': {'addr': '172.16.0.105', 'cfg': {'IPADDR': '172.16.0.105', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'STP': 'no', 'DEVICE': 'Storage', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['em2']}}, 'uuid': '49434D53-0200-9066-2500-66902500FE53_00:25:90:66:53:fe', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'hwaddr': '00:25:90:66:53:fe', 'netmask': '', 'speed': 100, 'addr': '', 'mtu': '1500'}, 'em2': {'hwaddr': '00:25:90:66:53:ff', 'netmask': '', 'speed': 1000, 'addr': '', 'mtu': '1500'}}, 'software_revision': '0', 'management_ip': '', 'clusterLevels': ['3.0', '3.1'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,arat,epb,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_coreduo,model_Conroe', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:b4d681a351bc', 'memSize': '36200', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.9', 'cpuSpeed': '1600.000', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc', u'pc-0.15', u'pc-1.0', u'pc', u'pc-0.14', u'pc-0.13', u'pc-0.12', u'pc-0.11', u'pc-0.10', u'isapc'], 'operatingSystem': {'release': '1', 'version': '16', 'name': 'oVirt Node'}, 'lastClient': '192.168.131.42'}}
Thread-966::DEBUG::2012-05-21 17:22:38,693::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-966::DEBUG::2012-05-21 17:22:38,694::task::588::TaskManager.Task::(_updateState) Task=`adbe9b38-e927-4a70-b1db-265d62bf4fb0`::moving from state init -> state preparing
Thread-966::INFO::2012-05-21 17:22:38,694::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=3, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': '172.16.0.102', 'iqn': 'iqn.2012-01.com.rakurs:storage.kvmvm.iscsi', 'portal': '1', 'user': '', 'password': '******', 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9', 'port': '3260'}], options=None)
Thread-966::INFO::2012-05-21 17:22:38,694::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9'}]}
Thread-966::DEBUG::2012-05-21 17:22:38,695::task::1172::TaskManager.Task::(prepare) Task=`adbe9b38-e927-4a70-b1db-265d62bf4fb0`::finished: {'statuslist': [{'status': 0, 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9'}]}
Thread-966::DEBUG::2012-05-21 17:22:38,695::task::588::TaskManager.Task::(_updateState) Task=`adbe9b38-e927-4a70-b1db-265d62bf4fb0`::moving from state preparing -> state finished
Thread-966::DEBUG::2012-05-21 17:22:38,695::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-966::DEBUG::2012-05-21 17:22:38,695::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-966::DEBUG::2012-05-21 17:22:38,696::task::978::TaskManager.Task::(_decref) Task=`adbe9b38-e927-4a70-b1db-265d62bf4fb0`::ref 0 aborting False
Thread-967::DEBUG::2012-05-21 17:22:38,707::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-967::DEBUG::2012-05-21 17:22:38,708::task::588::TaskManager.Task::(_updateState) Task=`d50e3937-1ef6-42b3-a4d1-14a3d50be00c`::moving from state init -> state preparing
Thread-967::INFO::2012-05-21 17:22:38,708::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': '192.168.130.41:/var/spool/ISO', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '59613fc9-4736-478b-b49c-f31d59de09d9', 'port': ''}], options=None)
Thread-967::INFO::2012-05-21 17:22:38,708::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '59613fc9-4736-478b-b49c-f31d59de09d9'}]}
Thread-967::DEBUG::2012-05-21 17:22:38,709::task::1172::TaskManager.Task::(prepare) Task=`d50e3937-1ef6-42b3-a4d1-14a3d50be00c`::finished: {'statuslist': [{'status': 0, 'id': '59613fc9-4736-478b-b49c-f31d59de09d9'}]}
Thread-967::DEBUG::2012-05-21 17:22:38,709::task::588::TaskManager.Task::(_updateState) Task=`d50e3937-1ef6-42b3-a4d1-14a3d50be00c`::moving from state preparing -> state finished
Thread-967::DEBUG::2012-05-21 17:22:38,709::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-967::DEBUG::2012-05-21 17:22:38,709::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-967::DEBUG::2012-05-21 17:22:38,710::task::978::TaskManager.Task::(_decref) Task=`d50e3937-1ef6-42b3-a4d1-14a3d50be00c`::ref 0 aborting False
Thread-968::DEBUG::2012-05-21 17:22:38,721::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-968::DEBUG::2012-05-21 17:22:38,721::task::588::TaskManager.Task::(_updateState) Task=`6d638bc0-5889-4e68-bf05-0e35a91f053a`::moving from state init -> state preparing
Thread-968::INFO::2012-05-21 17:22:38,722::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': 'appsrv2.rakurs.com:/XenServerVM/oVIRTm', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6', 'port': ''}], options=None)
Thread-968::INFO::2012-05-21 17:22:38,722::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-968::DEBUG::2012-05-21 17:22:38,722::task::1172::TaskManager.Task::(prepare) Task=`6d638bc0-5889-4e68-bf05-0e35a91f053a`::finished: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-968::DEBUG::2012-05-21 17:22:38,723::task::588::TaskManager.Task::(_updateState) Task=`6d638bc0-5889-4e68-bf05-0e35a91f053a`::moving from state preparing -> state finished
Thread-968::DEBUG::2012-05-21 17:22:38,723::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-968::DEBUG::2012-05-21 17:22:38,723::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-968::DEBUG::2012-05-21 17:22:38,723::task::978::TaskManager.Task::(_decref) Task=`6d638bc0-5889-4e68-bf05-0e35a91f053a`::ref 0 aborting False
Thread-969::DEBUG::2012-05-21 17:22:38,736::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-969::DEBUG::2012-05-21 17:22:38,737::task::588::TaskManager.Task::(_updateState) Task=`05075d9f-ab0c-4dec-b8ce-274cc761bad6`::moving from state init -> state preparing
Thread-969::INFO::2012-05-21 17:22:38,737::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': '172.16.0.102', 'iqn': 'iqn.2012-01.com.rakurs:storage.kvmvm.iscsi', 'portal': '1', 'user': '', 'password': '******', 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9', 'port': '3260'}], options=None)
Thread-969::DEBUG::2012-05-21 17:22:38,738::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-01.com.rakurs:storage.kvmvm.iscsi -I default -p 172.16.0.102:3260 --op=new' (cwd None)
Thread-969::DEBUG::2012-05-21 17:22:38,753::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-969::DEBUG::2012-05-21 17:22:38,753::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-01.com.rakurs:storage.kvmvm.iscsi -I default -p 172.16.0.102:3260 -n node.startup -v manual --op=update' (cwd None)
Thread-969::DEBUG::2012-05-21 17:22:38,767::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-969::DEBUG::2012-05-21 17:22:38,767::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2012-01.com.rakurs:storage.kvmvm.iscsi -I default -p 172.16.0.102:3260 -l' (cwd None)
Thread-969::DEBUG::2012-05-21 17:22:39,292::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-969::DEBUG::2012-05-21 17:22:39,293::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-969::DEBUG::2012-05-21 17:22:39,293::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-969::DEBUG::2012-05-21 17:22:39,293::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-969::DEBUG::2012-05-21 17:22:39,294::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-969::DEBUG::2012-05-21 17:22:39,294::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-969::DEBUG::2012-05-21 17:22:39,294::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-969::INFO::2012-05-21 17:22:39,295::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9'}]}
Thread-969::DEBUG::2012-05-21 17:22:39,295::task::1172::TaskManager.Task::(prepare) Task=`05075d9f-ab0c-4dec-b8ce-274cc761bad6`::finished: {'statuslist': [{'status': 0, 'id': 'a70e30b9-2eed-4309-9fff-842d8be46cb9'}]}
Thread-969::DEBUG::2012-05-21 17:22:39,295::task::588::TaskManager.Task::(_updateState) Task=`05075d9f-ab0c-4dec-b8ce-274cc761bad6`::moving from state preparing -> state finished
Thread-969::DEBUG::2012-05-21 17:22:39,296::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-969::DEBUG::2012-05-21 17:22:39,296::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-969::DEBUG::2012-05-21 17:22:39,296::task::978::TaskManager.Task::(_decref) Task=`05075d9f-ab0c-4dec-b8ce-274cc761bad6`::ref 0 aborting False
Thread-970::DEBUG::2012-05-21 17:22:39,310::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-970::DEBUG::2012-05-21 17:22:39,311::task::588::TaskManager.Task::(_updateState) Task=`4c98f407-7046-48db-b80d-80f61f71a556`::moving from state init -> state preparing
Thread-970::INFO::2012-05-21 17:22:39,311::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': '192.168.130.41:/var/spool/ISO', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '59613fc9-4736-478b-b49c-f31d59de09d9', 'port': ''}], options=None)
Thread-970::DEBUG::2012-05-21 17:22:39,317::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 192.168.130.41:/var/spool/ISO /rhev/data-center/mnt/192.168.130.41:_var_spool_ISO' (cwd None)
Thread-970::DEBUG::2012-05-21 17:22:39,356::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-970::DEBUG::2012-05-21 17:22:39,357::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-970::DEBUG::2012-05-21 17:22:39,357::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-970::DEBUG::2012-05-21 17:22:39,357::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-970::DEBUG::2012-05-21 17:22:39,358::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-970::DEBUG::2012-05-21 17:22:39,358::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-970::INFO::2012-05-21 17:22:39,358::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '59613fc9-4736-478b-b49c-f31d59de09d9'}]}
Thread-970::DEBUG::2012-05-21 17:22:39,359::task::1172::TaskManager.Task::(prepare) Task=`4c98f407-7046-48db-b80d-80f61f71a556`::finished: {'statuslist': [{'status': 0, 'id': '59613fc9-4736-478b-b49c-f31d59de09d9'}]}
Thread-970::DEBUG::2012-05-21 17:22:39,359::task::588::TaskManager.Task::(_updateState) Task=`4c98f407-7046-48db-b80d-80f61f71a556`::moving from state preparing -> state finished
Thread-970::DEBUG::2012-05-21 17:22:39,359::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-970::DEBUG::2012-05-21 17:22:39,360::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-970::DEBUG::2012-05-21 17:22:39,360::task::978::TaskManager.Task::(_decref) Task=`4c98f407-7046-48db-b80d-80f61f71a556`::ref 0 aborting False
Thread-971::DEBUG::2012-05-21 17:22:39,375::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-971::DEBUG::2012-05-21 17:22:39,375::task::588::TaskManager.Task::(_updateState) Task=`7ff523b9-a8af-43cb-99c0-ef87587bc030`::moving from state init -> state preparing
Thread-971::INFO::2012-05-21 17:22:39,376::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', conList=[{'connection': 'appsrv2.rakurs.com:/XenServerVM/oVIRTm', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6', 'port': ''}], options=None)
Thread-971::DEBUG::2012-05-21 17:22:39,381::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 appsrv2.rakurs.com:/XenServerVM/oVIRTm /rhev/data-center/mnt/appsrv2.rakurs.com:_XenServerVM_oVIRTm' (cwd None)
Thread-971::DEBUG::2012-05-21 17:22:39,416::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-971::DEBUG::2012-05-21 17:22:39,416::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-971::DEBUG::2012-05-21 17:22:39,417::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-971::DEBUG::2012-05-21 17:22:39,417::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-971::DEBUG::2012-05-21 17:22:39,417::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-971::DEBUG::2012-05-21 17:22:39,418::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-971::INFO::2012-05-21 17:22:39,418::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-971::DEBUG::2012-05-21 17:22:39,418::task::1172::TaskManager.Task::(prepare) Task=`7ff523b9-a8af-43cb-99c0-ef87587bc030`::finished: {'statuslist': [{'status': 0, 'id': '7e0b58a4-b430-46e4-89d7-e2876b5f42f6'}]}
Thread-971::DEBUG::2012-05-21 17:22:39,419::task::588::TaskManager.Task::(_updateState) Task=`7ff523b9-a8af-43cb-99c0-ef87587bc030`::moving from state preparing -> state finished
Thread-971::DEBUG::2012-05-21 17:22:39,419::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-971::DEBUG::2012-05-21 17:22:39,419::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-971::DEBUG::2012-05-21 17:22:39,419::task::978::TaskManager.Task::(_decref) Task=`7ff523b9-a8af-43cb-99c0-ef87587bc030`::ref 0 aborting False
Thread-972::DEBUG::2012-05-21 17:22:39,437::BindingXMLRPC::149::vds::(wrapper) [192.168.131.42]
Thread-972::DEBUG::2012-05-21 17:22:39,437::task::588::TaskManager.Task::(_updateState) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::moving from state init -> state preparing
Thread-972::INFO::2012-05-21 17:22:39,438::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='9ca146ec-96b0-11e1-a143-000c299ab3cc', hostID=3, scsiKey='9ca146ec-96b0-11e1-a143-000c299ab3cc', msdUUID='503cb4e5-ed41-4f72-a0ee-d37c62a6d243', masterVersion=1, options=None)
Thread-972::DEBUG::2012-05-21 17:22:39,438::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc`ReqID=`89e7a250-b96b-418d-ac02-b236da6a6350`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
Thread-972::DEBUG::2012-05-21 17:22:39,439::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc' for lock type 'exclusive'
Thread-972::DEBUG::2012-05-21 17:22:39,439::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc' is free. Now locking as 'exclusive' (1 active user)
Thread-972::DEBUG::2012-05-21 17:22:39,439::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc`ReqID=`89e7a250-b96b-418d-ac02-b236da6a6350`::Granted request
Thread-972::INFO::2012-05-21 17:22:39,440::sp::625::Storage.StoragePool::(connect) Connect host #3 to the storage pool 9ca146ec-96b0-11e1-a143-000c299ab3cc with master domain: 503cb4e5-ed41-4f72-a0ee-d37c62a6d243 (ver = 1)
Thread-972::DEBUG::2012-05-21 17:22:39,441::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,441::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,441::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,442::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,442::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,442::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:39,443::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-972::DEBUG::2012-05-21 17:22:39,443::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-972::DEBUG::2012-05-21 17:22:39,443::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-972::DEBUG::2012-05-21 17:22:39,443::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-972::DEBUG::2012-05-21 17:22:39,444::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:39,462::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:39,463::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-972::DEBUG::2012-05-21 17:22:41,669::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:41,691::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:41,692::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,692::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,693::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,693::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,693::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,694::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,694::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-972::DEBUG::2012-05-21 17:22:41,694::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,697::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 503cb4e5-ed41-4f72-a0ee-d37c62a6d243' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:41,816::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:41,818::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,819::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with LvMetadataRW backend
Thread-972::DEBUG::2012-05-21 17:22:41,819::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/503cb4e5-ed41-4f72-a0ee-d37c62a6d243/metadata count=1' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:41,827::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000727079 s, 2.8 MB/s\n'; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:41,827::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000727079 s, 2.8 MB/s'], size: 2048
Thread-972::DEBUG::2012-05-21 17:22:41,828::persistentDict::226::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
Thread-972::WARNING::2012-05-21 17:22:41,828::persistentDict::248::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-972::DEBUG::2012-05-21 17:22:41,828::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with VGTagMetadataRW backend
Thread-972::DEBUG::2012-05-21 17:22:41,829::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,829::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,830::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,830::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,830::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,831::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 503cb4e5-ed41-4f72-a0ee-d37c62a6d243' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:41,913::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:41,915::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,916::persistentDict::226::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['CLASS=Data', 'VERSION=2', 'LOCKPOLICY=', 'SDUUID=503cb4e5-ed41-4f72-a0ee-d37c62a6d243', 'LOGBLKSIZE=512', 'LEASERETRIES=3', 'VGUUID=0olUf8-C92U-CSjY-VCz7-wFEK-17il-wCgrhe', 'LOCKRENEWALINTERVALSEC=5', 'PHYBLKSIZE=512', u'PV0=pv:1p_ISCSI_lun1,uuid:uTmAvH-Idzi-oobQ-Ve4J-oJD7-yTlg-fTJddc,pestart:0,pecount:5284,mapoffset:0', 'TYPE=ISCSI', 'LEASETIMESEC=60', 'IOOPTIMEOUTSEC=10', 'POOL_DESCRIPTION=Default', 'ROLE=Master', 'POOL_UUID=9ca146ec-96b0-11e1-a143-000c299ab3cc', 'MASTER_VERSION=1', 'DESCRIPTION=LUN1onKVM', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=9', '_SHA_CKSUM=1a22345376ef88cb915d312c67e11a4e57c53d06', u'POOL_DOMAINS=503cb4e5-ed41-4f72-a0ee-d37c62a6d243:Active,d2221cee-7146-4197-aecf-0dfad32b54ea:Active,6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7:Active']
Thread-972::DEBUG::2012-05-21 17:22:41,917::lvm::316::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:41,918::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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-972::DEBUG::2012-05-21 17:22:42,004::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:42,004::lvm::339::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
Thread-972::WARNING::2012-05-21 17:22:42,005::sd::298::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 503cb4e5-ed41-4f72-a0ee-d37c62a6d243_imageNS already registered
Thread-972::WARNING::2012-05-21 17:22:42,005::sd::304::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 503cb4e5-ed41-4f72-a0ee-d37c62a6d243_volumeNS already registered
Thread-972::WARNING::2012-05-21 17:22:42,006::blockSD::280::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 503cb4e5-ed41-4f72-a0ee-d37c62a6d243_lvmActivationNS already registered
Thread-972::DEBUG::2012-05-21 17:22:42,006::sp::1465::Storage.StoragePool::(getMasterDomain) Master domain 503cb4e5-ed41-4f72-a0ee-d37c62a6d243 verified, version 1
Thread-972::DEBUG::2012-05-21 17:22:42,007::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
Thread-972::DEBUG::2012-05-21 17:22:42,007::misc::1055::SamplingMethod::(__call__) Got in to sampling method
Thread-972::DEBUG::2012-05-21 17:22:42,007::lvm::464::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,008::lvm::466::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,008::lvm::475::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,008::lvm::487::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,009::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,010::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 503cb4e5-ed41-4f72-a0ee-d37c62a6d243' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:42,092::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-972::DEBUG::2012-05-21 17:22:42,094::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,095::persistentDict::226::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['CLASS=Data', 'VERSION=2', 'LOCKPOLICY=', 'SDUUID=503cb4e5-ed41-4f72-a0ee-d37c62a6d243', 'LOGBLKSIZE=512', 'LEASERETRIES=3', 'VGUUID=0olUf8-C92U-CSjY-VCz7-wFEK-17il-wCgrhe', 'LOCKRENEWALINTERVALSEC=5', 'PHYBLKSIZE=512', u'PV0=pv:1p_ISCSI_lun1,uuid:uTmAvH-Idzi-oobQ-Ve4J-oJD7-yTlg-fTJddc,pestart:0,pecount:5284,mapoffset:0', 'TYPE=ISCSI', 'LEASETIMESEC=60', 'IOOPTIMEOUTSEC=10', 'POOL_DESCRIPTION=Default', 'ROLE=Master', 'POOL_UUID=9ca146ec-96b0-11e1-a143-000c299ab3cc', 'MASTER_VERSION=1', 'DESCRIPTION=LUN1onKVM', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=9', '_SHA_CKSUM=1a22345376ef88cb915d312c67e11a4e57c53d06', u'POOL_DOMAINS=503cb4e5-ed41-4f72-a0ee-d37c62a6d243:Active,d2221cee-7146-4197-aecf-0dfad32b54ea:Active,6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7:Active']
Thread-972::DEBUG::2012-05-21 17:22:42,096::sp::1495::Storage.StoragePool::(updateMonitoringThreads) sp `9ca146ec-96b0-11e1-a143-000c299ab3cc` started monitoring domain `503cb4e5-ed41-4f72-a0ee-d37c62a6d243`
Thread-972::DEBUG::2012-05-21 17:22:42,097::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,098::__init__::1249::Storage.Misc.excCmd::(_log) u'/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%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 d2221cee-7146-4197-aecf-0dfad32b54ea' (cwd None)
Thread-973::DEBUG::2012-05-21 17:22:42,099::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " 503cb4e5-ed41-4f72-a0ee-d37c62a6d243' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:42,099::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::ERROR::2012-05-21 17:22:42,100::sdc::116::Storage.StorageDomainCache::(_findDomain) Error while looking for domain `d2221cee-7146-4197-aecf-0dfad32b54ea`
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/sdc.py", line 111, in _findDomain
    return mod.findDomain(sdUUID)
  File "/usr/share/vdsm/storage/blockSD.py", line 1064, in findDomain
    return BlockStorageDomain(BlockStorageDomain.findDomainPath(sdUUID))
  File "/usr/share/vdsm/storage/blockSD.py", line 1034, in findDomainPath
    vg = lvm.getVG(sdUUID)
  File "/usr/share/vdsm/storage/lvm.py", line 743, in getVG
    vg = _lvminfo.getVg(vgName)   #returns single VG namedtuple
  File "/usr/share/vdsm/storage/lvm.py", line 526, in getVg
    vgs = self._reloadvgs(vgName)
  File "/usr/share/vdsm/storage/lvm.py", line 350, in _reloadvgs
    rc, out, err = self.cmd(cmd)
  File "/usr/share/vdsm/storage/lvm.py", line 284, in cmd
    rc, out, err = misc.execCmd(finalCmd, sudo=True)
  File "/usr/share/vdsm/storage/misc.py", line 199, in execCmd
    p = BetterPopen(command, close_fds=True, cwd=cwd, env=env)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 46, in __init__
    stderr=PIPE)
  File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 60, in _execute_child
    cwd, env)
TypeError: All items in list must be strings
Thread-972::DEBUG::2012-05-21 17:22:42,115::fileSD::106::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.130.41:_var_spool_ISO/d2221cee-7146-4197-aecf-0dfad32b54ea
Thread-972::DEBUG::2012-05-21 17:22:42,115::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
Thread-972::DEBUG::2012-05-21 17:22:42,118::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=ISOcache', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=9ca146ec-96b0-11e1-a143-000c299ab3cc', 'REMOTE_PATH=192.168.130.41:/var/spool/ISO', 'ROLE=Regular', 'SDUUID=d2221cee-7146-4197-aecf-0dfad32b54ea', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=bcc978df649081c4eb225f4d9829bbaf5659a5bd']
Thread-972::DEBUG::2012-05-21 17:22:42,130::fileSD::347::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-972::WARNING::2012-05-21 17:22:42,130::sd::298::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace d2221cee-7146-4197-aecf-0dfad32b54ea_imageNS already registered
Thread-972::WARNING::2012-05-21 17:22:42,131::sd::304::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace d2221cee-7146-4197-aecf-0dfad32b54ea_volumeNS already registered
Thread-972::DEBUG::2012-05-21 17:22:42,131::sp::1495::Storage.StoragePool::(updateMonitoringThreads) sp `9ca146ec-96b0-11e1-a143-000c299ab3cc` started monitoring domain `d2221cee-7146-4197-aecf-0dfad32b54ea`
Thread-972::DEBUG::2012-05-21 17:22:42,132::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,136::__init__::1249::Storage.Misc.excCmd::(_log) u'/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%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:42,139::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::ERROR::2012-05-21 17:22:42,139::sdc::116::Storage.StorageDomainCache::(_findDomain) Error while looking for domain `6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7`
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/sdc.py", line 111, in _findDomain
    return mod.findDomain(sdUUID)
  File "/usr/share/vdsm/storage/blockSD.py", line 1064, in findDomain
    return BlockStorageDomain(BlockStorageDomain.findDomainPath(sdUUID))
  File "/usr/share/vdsm/storage/blockSD.py", line 1034, in findDomainPath
    vg = lvm.getVG(sdUUID)
  File "/usr/share/vdsm/storage/lvm.py", line 743, in getVG
    vg = _lvminfo.getVg(vgName)   #returns single VG namedtuple
  File "/usr/share/vdsm/storage/lvm.py", line 526, in getVg
    vgs = self._reloadvgs(vgName)
  File "/usr/share/vdsm/storage/lvm.py", line 350, in _reloadvgs
    rc, out, err = self.cmd(cmd)
  File "/usr/share/vdsm/storage/lvm.py", line 284, in cmd
    rc, out, err = misc.execCmd(finalCmd, sudo=True)
  File "/usr/share/vdsm/storage/misc.py", line 199, in execCmd
    p = BetterPopen(command, close_fds=True, cwd=cwd, env=env)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 46, in __init__
    stderr=PIPE)
  File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 60, in _execute_child
    cwd, env)
TypeError: All items in list must be strings
Thread-972::DEBUG::2012-05-21 17:22:42,147::fileSD::106::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/appsrv2.rakurs.com:_XenServerVM_oVIRTm/6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7
Thread-972::DEBUG::2012-05-21 17:22:42,148::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
Thread-972::DEBUG::2012-05-21 17:22:42,150::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Backup', 'DESCRIPTION=NFSappsrv2', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=9ca146ec-96b0-11e1-a143-000c299ab3cc', 'REMOTE_PATH=appsrv2.rakurs.com:/XenServerVM/oVIRTm', 'ROLE=Regular', 'SDUUID=6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=389c956e45e17bcc9c16371c735ba550d89c7bec']
Thread-972::DEBUG::2012-05-21 17:22:42,154::fileSD::347::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-972::WARNING::2012-05-21 17:22:42,154::sd::298::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7_imageNS already registered
Thread-972::WARNING::2012-05-21 17:22:42,154::sd::304::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7_volumeNS already registered
Thread-972::DEBUG::2012-05-21 17:22:42,155::sp::1495::Storage.StoragePool::(updateMonitoringThreads) sp `9ca146ec-96b0-11e1-a143-000c299ab3cc` started monitoring domain `6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7`
Thread-972::DEBUG::2012-05-21 17:22:42,156::misc::1063::SamplingMethod::(__call__) Returning last result
Thread-972::DEBUG::2012-05-21 17:22:42,159::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,161::__init__::1249::Storage.Misc.excCmd::(_log) u'/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%1ATA_KINGSTON_SV100S232G_50026B7221046658|1p_ISCSI_lun1%\\", \\"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 d2221cee-7146-4197-aecf-0dfad32b54ea 6c41de7b-fb85-4ef7-bc1b-a6ec2f4f41b7' (cwd None)
Thread-972::DEBUG::2012-05-21 17:22:42,162::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-972::DEBUG::2012-05-21 17:22:42,163::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc'
Thread-972::DEBUG::2012-05-21 17:22:42,163::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc' (0 active users)
Thread-972::DEBUG::2012-05-21 17:22:42,164::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc' is free, finding out if anyone is waiting for it.
Thread-972::DEBUG::2012-05-21 17:22:42,164::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9ca146ec-96b0-11e1-a143-000c299ab3cc', Clearing records.
Thread-972::ERROR::2012-05-21 17:22:42,165::task::853::TaskManager.Task::(_setError) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 861, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1132, in __rebuild
    blockDomUUIDs = [vg.name for vg in blockSD.lvm.getVGs(domUUIDs)]
  File "/usr/share/vdsm/storage/lvm.py", line 750, in getVGs
    return _lvminfo.getVgs(vgNames) #returns list
  File "/usr/share/vdsm/storage/lvm.py", line 537, in getVgs
    return [vg for vgName, vg in self._reloadvgs(vgNames).iteritems() if vgName in vgNames]
  File "/usr/share/vdsm/storage/lvm.py", line 350, in _reloadvgs
    rc, out, err = self.cmd(cmd)
  File "/usr/share/vdsm/storage/lvm.py", line 284, in cmd
    rc, out, err = misc.execCmd(finalCmd, sudo=True)
  File "/usr/share/vdsm/storage/misc.py", line 199, in execCmd
    p = BetterPopen(command, close_fds=True, cwd=cwd, env=env)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 46, in __init__
    stderr=PIPE)
  File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__
    errread, errwrite)
  File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 60, in _execute_child
    cwd, env)
TypeError: All items in list must be strings
Thread-972::DEBUG::2012-05-21 17:22:42,165::task::872::TaskManager.Task::(_run) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::Task._run: 5a00f9c5-0ced-4a88-ab46-b077ee35689b ('9ca146ec-96b0-11e1-a143-000c299ab3cc', 3, '9ca146ec-96b0-11e1-a143-000c299ab3cc', '503cb4e5-ed41-4f72-a0ee-d37c62a6d243', 1) {} failed - stopping task
Thread-972::DEBUG::2012-05-21 17:22:42,166::task::1199::TaskManager.Task::(stop) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::stopping in state preparing (force False)
Thread-972::DEBUG::2012-05-21 17:22:42,166::task::978::TaskManager.Task::(_decref) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::ref 1 aborting True
Thread-972::INFO::2012-05-21 17:22:42,167::task::1157::TaskManager.Task::(prepare) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::aborting: Task is aborted: u'All items in list must be strings' - code 100
Thread-972::DEBUG::2012-05-21 17:22:42,167::task::1162::TaskManager.Task::(prepare) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::Prepare: aborted: All items in list must be strings
Thread-972::DEBUG::2012-05-21 17:22:42,168::task::978::TaskManager.Task::(_decref) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::ref 0 aborting True
Thread-972::DEBUG::2012-05-21 17:22:42,168::task::913::TaskManager.Task::(_doAbort) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::Task._doAbort: force False
Thread-972::DEBUG::2012-05-21 17:22:42,169::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-972::DEBUG::2012-05-21 17:22:42,169::task::588::TaskManager.Task::(_updateState) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::moving from state preparing -> state aborting
Thread-972::DEBUG::2012-05-21 17:22:42,169::task::537::TaskManager.Task::(__state_aborting) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::_aborting: recover policy none
Thread-972::DEBUG::2012-05-21 17:22:42,169::task::588::TaskManager.Task::(_updateState) Task=`5a00f9c5-0ced-4a88-ab46-b077ee35689b`::moving from state aborting -> state failed
Thread-972::DEBUG::2012-05-21 17:22:42,170::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-972::DEBUG::2012-05-21 17:22:42,170::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-972::ERROR::2012-05-21 17:22:42,170::dispatcher::69::Storage.Dispatcher.Protect::(run) All items in list must be strings
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 61, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1164, in prepare
    raise self.error
TypeError: All items in list must be strings
Thread-973::DEBUG::2012-05-21 17:22:42,181::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
Thread-973::DEBUG::2012-05-21 17:22:42,181::__init__::1249::Storage.Misc.excCmd::(_log) '/bin/dd iflag=direct if=/dev/503cb4e5-ed41-4f72-a0ee-d37c62a6d243/metadata bs=4096 count=1' (cwd None)
Thread-973::DEBUG::2012-05-21 17:22:42,189::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000650039 s, 6.3 MB/s\n'; <rc> = 0