Attachment 874545 Details for Bug 1076603 – vdsm log

vdsm log

vdsm.log (text/plain), 172.44 KB, created by John Taylor on 2014-03-14 17:21:18 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: John Taylor

Created: 2014-03-14 17:21:18 UTC

Size: 172.44 KB

patch

obsolete

>MainThread::INFO::2014-03-13 22:06:58,958::vdsm::119::vds::(run) (PID: 1527) I am the actual vdsm 4.14.5-0.fc19 vm4.corp.sgstool.com (3.13.5-103.fc19.x86_64)
>MainThread::WARNING::2014-03-13 22:06:58,972::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-03-13 22:06:58,982::sp::380::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/ac418af8-1cbe-4671-9fd1-00237fd0f115/master` is not mounted, skipping
>MainThread::DEBUG::2014-03-13 22:06:59,403::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-03-13 22:06:59,404::hsm::423::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-03-13 22:06:59,442::hsm::423::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-03-13 22:06:59,443::hsm::447::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-03-13 22:06:59,448::hsm::479::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-03-13 22:06:59,448::hsm::480::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-03-13 22:06:59,448::hsm::482::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-03-13 22:06:59,450::hsm::525::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-03-13 22:06:59,451::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>MainThread::INFO::2014-03-13 22:06:59,453::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-03-13 22:06:59,453::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-03-13 22:06:59,560::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::INFO::2014-03-13 22:06:59,624::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x204fef0>>)
>storageRefresh::DEBUG::2014-03-13 22:06:59,624::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>MainThread::INFO::2014-03-13 22:06:59,625::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>storageRefresh::DEBUG::2014-03-13 22:06:59,629::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>MainThread::INFO::2014-03-13 22:06:59,641::momIF::47::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-03-13 22:06:59,652::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-03-13 22:06:59,655::vmChannels::170::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-03-13 22:06:59,693::libvirtconnection::145::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-03-13 22:06:59,697::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-03-13 22:06:59,699::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>MainThread::WARNING::2014-03-13 22:06:59,698::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
>storageRefresh::DEBUG::2014-03-13 22:06:59,741::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-03-13 22:06:59,774::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>storageRefresh::DEBUG::2014-03-13 22:06:59,822::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-03-13 22:06:59,857::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>storageRefresh::DEBUG::2014-03-13 22:06:59,903::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::WARNING::2014-03-13 22:06:59,909::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
>storageRefresh::DEBUG::2014-03-13 22:06:59,911::hsm::391::Storage.HSM::(storageRefresh) HSM is ready
>Thread-13::DEBUG::2014-03-13 22:11:01,481::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getCapabilities with () {} flowID [37fa2aa6]
>Thread-13::DEBUG::2014-03-13 22:11:01,589::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:01,604::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:01,625::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:01,639::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:01,643::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.218' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:01,656::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:01,659::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.6' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:01,672::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:01,675::utils::642::root::(execCmd) '/sbin/ip -d link show dev em2.217' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:01,689::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:02,307::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad'}], 'FC': []}, 'packages2': {'kernel': {'release': '103.fc19.x86_64', 'buildtime': 1393890396.0, 'version': '3.13.5'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1394448589L, 'version': '4.14.5'}, 'qemu-kvm': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5345  @ 2.33GHz', 'hooks': {}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '192.168.1.6', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.1']}, 'storage218': {'iface': u'em1.218', 'addr': '172.17.218.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em1.218', 'ipv6gateway': '::', 'gateway': ''}, 'dmz': {'iface': 'dmz', 'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.6']}, 'storage217': {'iface': u'em2.217', 'addr': '172.17.217.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em2.217', 'ipv6gateway': '::', 'gateway': '172.17.217.5'}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '192.168.1.6', 'ports': ['em1.1']}, ';vdsmdummy;': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'dmz': {'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['em1.6']}}, 'uuid': '33393935-3234-5553-4537-31304E415A30', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:f8', 'cfg': {'NM_CONTROLLED': 'no', 'MTU': '1500', 'HWADDR': '00:1a:4b:dd:21:f8', 'BOOTPROTO': 'none', 'DEVICE': 'em1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'speed': 1000, 'mtu': '1500'}, 'em2': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:ee', 'cfg': {'DEVICE': 'em2', 'HWADDR': '00:1a:4b:dd:21:ee', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '0', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4'], '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,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,lahf_lm,dtherm,tpr_shadow,model_Conroe,model_coreduo,model_core2duo,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '8a:28:9f:fd:0a:a7', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '14031', 'cpuSpeed': '2333.206', 'version_name': 'Snow Man', 'vlans': {'em1.6': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'dmz', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.6', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 6, 'mtu': '1500'}, 'em2.217': {'netmask': '255.255.255.0', 'iface': 'em2', 'addr': '172.17.217.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.217.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em2.217', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'vlanid': 217, 'mtu': '1500'}, 'em1.1': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 1, 'mtu': '1500'}, 'em1.218': {'netmask': '255.255.255.0', 'iface': 'em1', 'addr': '172.17.218.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.218.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em1.218', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 218, 'mtu': '1500'}}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'pc-q35-1.4', u'pc-q35-1.5', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'pc-i440fx-1.4', u'pc-i440fx-1.5', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '192.168.1.44'}}
>Thread-13::DEBUG::2014-03-13 22:11:02,418::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getHardwareInfo with () {} flowID [37fa2aa6]
>Thread-13::DEBUG::2014-03-13 22:11:02,564::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL360 G5', 'systemSerialNumber': 'USE710NAZ0', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '33393935-3234-5553-4537-31304e415a30', 'systemManufacturer': 'HP'}}
>Thread-13::DEBUG::2014-03-13 22:11:04,262::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getCapabilities with () {}
>Thread-13::DEBUG::2014-03-13 22:11:04,264::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,276::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,295::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,307::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,311::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.218' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,323::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,325::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.6' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,337::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,341::utils::642::root::(execCmd) '/sbin/ip -d link show dev em2.217' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,353::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,364::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad'}], 'FC': []}, 'packages2': {'kernel': {'release': '103.fc19.x86_64', 'buildtime': 1393890396.0, 'version': '3.13.5'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1394448589L, 'version': '4.14.5'}, 'qemu-kvm': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5345  @ 2.33GHz', 'hooks': {}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '192.168.1.6', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.1']}, 'storage218': {'iface': u'em1.218', 'addr': '172.17.218.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em1.218', 'ipv6gateway': '::', 'gateway': ''}, 'dmz': {'iface': 'dmz', 'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.6']}, 'storage217': {'iface': u'em2.217', 'addr': '172.17.217.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em2.217', 'ipv6gateway': '::', 'gateway': '172.17.217.5'}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '192.168.1.6', 'ports': ['em1.1']}, ';vdsmdummy;': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'dmz': {'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['em1.6']}}, 'uuid': '33393935-3234-5553-4537-31304E415A30', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:f8', 'cfg': {'NM_CONTROLLED': 'no', 'MTU': '1500', 'HWADDR': '00:1a:4b:dd:21:f8', 'BOOTPROTO': 'none', 'DEVICE': 'em1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'speed': 1000, 'mtu': '1500'}, 'em2': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:ee', 'cfg': {'DEVICE': 'em2', 'HWADDR': '00:1a:4b:dd:21:ee', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '0', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4'], '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,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,lahf_lm,dtherm,tpr_shadow,model_Conroe,model_coreduo,model_core2duo,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '8a:28:9f:fd:0a:a7', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '14031', 'cpuSpeed': '2333.206', 'version_name': 'Snow Man', 'vlans': {'em1.6': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'dmz', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.6', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 6, 'mtu': '1500'}, 'em2.217': {'netmask': '255.255.255.0', 'iface': 'em2', 'addr': '172.17.217.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.217.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em2.217', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'vlanid': 217, 'mtu': '1500'}, 'em1.1': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 1, 'mtu': '1500'}, 'em1.218': {'netmask': '255.255.255.0', 'iface': 'em1', 'addr': '172.17.218.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.218.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em1.218', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 218, 'mtu': '1500'}}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'pc-q35-1.4', u'pc-q35-1.5', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'pc-i440fx-1.4', u'pc-i440fx-1.5', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '192.168.1.44'}}
>Thread-13::DEBUG::2014-03-13 22:11:04,406::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-03-13 22:11:04,407::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL360 G5', 'systemSerialNumber': 'USE710NAZ0', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '33393935-3234-5553-4537-31304e415a30', 'systemManufacturer': 'HP'}}
>Thread-13::DEBUG::2014-03-13 22:11:04,443::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getCapabilities with () {}
>Thread-13::DEBUG::2014-03-13 22:11:04,454::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,469::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,494::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,507::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,511::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.218' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,524::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,526::utils::642::root::(execCmd) '/sbin/ip -d link show dev em1.6' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,539::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,543::utils::642::root::(execCmd) '/sbin/ip -d link show dev em2.217' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:04,555::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:04,565::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad'}], 'FC': []}, 'packages2': {'kernel': {'release': '103.fc19.x86_64', 'buildtime': 1393890396.0, 'version': '3.13.5'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1394448589L, 'version': '4.14.5'}, 'qemu-kvm': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '2.fc19', 'buildtime': 1384762225L, 'version': '1.6.1'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5345  @ 2.33GHz', 'hooks': {}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '192.168.1.6', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.1']}, 'storage218': {'iface': u'em1.218', 'addr': '172.17.218.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em1.218', 'ipv6gateway': '::', 'gateway': ''}, 'dmz': {'iface': 'dmz', 'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['em1.6']}, 'storage217': {'iface': u'em2.217', 'addr': '172.17.217.44', 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'em2.217', 'ipv6gateway': '::', 'gateway': '172.17.217.5'}}, 'bridges': {'ovirtmgmt': {'addr': '192.168.1.44', 'cfg': {'IPV6_AUTOCONF': 'yes', 'IPV6INIT': 'yes', 'IPADDR': '192.168.1.44', 'GATEWAY': '192.168.1.6', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '255.255.255.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '192.168.1.6', 'ports': ['em1.1']}, ';vdsmdummy;': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'dmz': {'addr': '', 'cfg': {'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'dmz', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['em1.6']}}, 'uuid': '33393935-3234-5553-4537-31304E415A30', 'lastClientIface': 'ovirtmgmt', 'nics': {'em1': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:f8', 'cfg': {'NM_CONTROLLED': 'no', 'MTU': '1500', 'HWADDR': '00:1a:4b:dd:21:f8', 'BOOTPROTO': 'none', 'DEVICE': 'em1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'speed': 1000, 'mtu': '1500'}, 'em2': {'netmask': '', 'addr': '', 'hwaddr': '00:1a:4b:dd:21:ee', 'cfg': {'DEVICE': 'em2', 'HWADDR': '00:1a:4b:dd:21:ee', 'ONBOOT': 'yes', 'NM_CONTROLLED': 'no'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '0', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4'], '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,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,lahf_lm,dtherm,tpr_shadow,model_Conroe,model_coreduo,model_core2duo,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:d515f9b0f7ad', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '8a:28:9f:fd:0a:a7', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '14031', 'cpuSpeed': '2333.206', 'version_name': 'Snow Man', 'vlans': {'em1.6': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'dmz', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.6', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 6, 'mtu': '1500'}, 'em2.217': {'netmask': '255.255.255.0', 'iface': 'em2', 'addr': '172.17.217.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.217.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em2.217', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21ee/64'], 'vlanid': 217, 'mtu': '1500'}, 'em1.1': {'netmask': '', 'iface': 'em1', 'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'VLAN': 'yes', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'em1.1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 1, 'mtu': '1500'}, 'em1.218': {'netmask': '255.255.255.0', 'iface': 'em1', 'addr': '172.17.218.44', 'cfg': {'VLAN': 'yes', 'IPADDR': '172.17.218.44', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'em1.218', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::21a:4bff:fedd:21f8/64'], 'vlanid': 218, 'mtu': '1500'}}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'pc-q35-1.4', u'pc-q35-1.5', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'pc-i440fx-1.4', u'pc-i440fx-1.5', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '192.168.1.44'}}
>Thread-13::DEBUG::2014-03-13 22:11:04,590::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-03-13 22:11:04,591::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL360 G5', 'systemSerialNumber': 'USE710NAZ0', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '33393935-3234-5553-4537-31304e415a30', 'systemManufacturer': 'HP'}}
>Thread-13::DEBUG::2014-03-13 22:11:04,722::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [4d23f520]
>Thread-13::INFO::2014-03-13 22:11:04,724::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000002-0002-0002-0002-000000000002', conList=[{'connection': 'vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd0989a6c-2e10-41de-a050-a7dc8ea9853d', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-03-13 22:11:04,738::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4 /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:05,241::hsm::2317::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4
>Thread-13::DEBUG::2014-03-13 22:11:05,244::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('9410073b-7811-4eea-b834-9fe3c8cf523b',)
>Thread-13::DEBUG::2014-03-13 22:11:05,244::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {9410073b-7811-4eea-b834-9fe3c8cf523b: storage.nfsSD.findDomain}
>Thread-13::INFO::2014-03-13 22:11:05,244::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'd0989a6c-2e10-41de-a050-a7dc8ea9853d'}]}
>Thread-13::DEBUG::2014-03-13 22:11:05,276::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:05,279::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='00000002-0002-0002-0002-000000000002', hostID=1, msdUUID='9410073b-7811-4eea-b834-9fe3c8cf523b', masterVersion=14, domainsMap=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:05,282::sp::133::Storage.StoragePool::(setBackend) updating pool 00000002-0002-0002-0002-000000000002 backend from type NoneType instance 0x329f58bf00 to type StoragePoolDiskBackend instance 0x7fa88c3be4d0
>Thread-13::INFO::2014-03-13 22:11:05,283::sp::618::Storage.StoragePool::(connect) Connect host #1 to the storage pool 00000002-0002-0002-0002-000000000002 with master domain: 9410073b-7811-4eea-b834-9fe3c8cf523b (ver = 14)
>Thread-13::DEBUG::2014-03-13 22:11:05,284::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-13::DEBUG::2014-03-13 22:11:05,285::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:05,312::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:05,338::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:05,554::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-13::DEBUG::2014-03-13 22:11:05,750::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:11:05,763::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=105baa8d6098477ea25c38db05155da26d58e755']
>Thread-13::DEBUG::2014-03-13 22:11:05,766::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-13::DEBUG::2014-03-13 22:11:05,767::sp::1366::Storage.StoragePool::(setMasterDomain) Master domain 9410073b-7811-4eea-b834-9fe3c8cf523b verified, version 14
>Thread-13::DEBUG::2014-03-13 22:11:05,779::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=105baa8d6098477ea25c38db05155da26d58e755']
>Thread-13::INFO::2014-03-13 22:11:05,779::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-13::DEBUG::2014-03-13 22:11:05,781::sp::1395::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `00000002-0002-0002-0002-000000000002` started monitoring domain `9410073b-7811-4eea-b834-9fe3c8cf523b`
>Thread-16::DEBUG::2014-03-13 22:11:05,780::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-13::DEBUG::2014-03-13 22:11:05,809::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=105baa8d6098477ea25c38db05155da26d58e755']
>Thread-13::DEBUG::2014-03-13 22:11:05,812::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:11:05,858::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-13::INFO::2014-03-13 22:11:05,864::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b to /rhev/data-center/00000002-0002-0002-0002-000000000002/9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-13::INFO::2014-03-13 22:11:05,864::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b to /rhev/data-center/00000002-0002-0002-0002-000000000002/mastersd
>Thread-13::INFO::2014-03-13 22:11:05,867::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>Thread-13::INFO::2014-03-13 22:11:05,877::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:11:05,878::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '0.1', 'valid': True}}
>Thread-13::DEBUG::2014-03-13 22:11:05,912::BindingXMLRPC::1067::vds::(wrapper) client [192.168.1.44]::call setMOMPolicyParameters with ({'balloonEnabled': False, 'ksmEnabled': True},) {} flowID [4d23f520]
>Thread-13::DEBUG::2014-03-13 22:11:05,987::BindingXMLRPC::1074::vds::(wrapper) return setMOMPolicyParameters with {'status': {'message': 'Done', 'code': 0}}
>Thread-16::DEBUG::2014-03-13 22:11:06,007::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:11:06,025::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n577 bytes (577 B) copied, 0.000383381 s, 1.5 MB/s\n'; <rc> = 0
>Thread-16::DEBUG::2014-03-13 22:11:06,032::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 9410073b-7811-4eea-b834-9fe3c8cf523b changed its status to Valid
>Thread-19::DEBUG::2014-03-13 22:11:06,033::misc::884::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-19::DEBUG::2014-03-13 22:11:06,034::misc::894::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-19::DEBUG::2014-03-13 22:11:06,036::misc::904::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-20::INFO::2014-03-13 22:11:06,039::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-13::DEBUG::2014-03-13 22:11:07,752::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:07,754::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:11:07,771::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}}
>Thread-13::DEBUG::2014-03-13 22:11:07,805::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:07,805::logUtils::44::dispatcher::(wrapper) Run and protect: spmStart(spUUID='00000002-0002-0002-0002-000000000002', prevID=-1, prevLVER='-1', maxHostID=250, domVersion='3', options=None)
>Thread-13::INFO::2014-03-13 22:11:07,807::logUtils::47::dispatcher::(wrapper) Run and protect: spmStart, Return response: None
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:07,825::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=105baa8d6098477ea25c38db05155da26d58e755']
>Thread-13::DEBUG::2014-03-13 22:11:08,819::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:08,820::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:08,821::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:09,828::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:09,829::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:09,829::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:10,835::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:10,836::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:10,836::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:11,845::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:11,846::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:11,846::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:12,853::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:12,853::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:12,854::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:13,998::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:13,999::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:13,999::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:15,005::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:15,006::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:15,006::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:16,011::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:16,012::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:16,021::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-16::DEBUG::2014-03-13 22:11:16,051::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:11:16,064::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n577 bytes (577 B) copied, 0.000306782 s, 1.9 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:17,027::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:17,028::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:17,029::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:18,034::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:18,035::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:18,035::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:19,041::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:19,042::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:19,042::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:20,047::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:20,048::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:20,048::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:21,054::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:21,055::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:21,062::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::INFO::2014-03-13 22:11:21,327::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:11:21,327::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000383381', 'lastCheck': '15.3', 'valid': True}}
>Thread-13::DEBUG::2014-03-13 22:11:22,068::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:22,069::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:22,069::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:23,075::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:23,076::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:23,076::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:24,083::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:24,084::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:24,084::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:25,089::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:25,090::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:25,090::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:26,096::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:26,097::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:26,097::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:27,103::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:27,104::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:27,104::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,898::sp::266::Storage.StoragePool::(startSpm) spm lock acquired successfully
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,910::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=105baa8d6098477ea25c38db05155da26d58e755']
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,911::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,911::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,911::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=774e76f485c77e0e404142ccd1de0b1472a17050']
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,915::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>265565e8-187f-4c7b-9197-eaeb2743fabb::INFO::2014-03-13 22:11:27,916::sp::431::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `9410073b-7811-4eea-b834-9fe3c8cf523b`
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,924::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,926::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,937::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=774e76f485c77e0e404142ccd1de0b1472a17050']
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,939::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>265565e8-187f-4c7b-9197-eaeb2743fabb::INFO::2014-03-13 22:11:27,939::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9410073b-7811-4eea-b834-9fe3c8cf523b_imageNS already registered
>265565e8-187f-4c7b-9197-eaeb2743fabb::INFO::2014-03-13 22:11:27,939::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9410073b-7811-4eea-b834-9fe3c8cf523b_volumeNS already registered
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,940::sp::436::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,951::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=774e76f485c77e0e404142ccd1de0b1472a17050']
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,951::sp::443::Storage.StoragePool::(_upgradePool) Registering with state change event
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,951::sp::446::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,952::sd::623::Storage.StorageDomain::(createMasterTree) creating vms dir: /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/master/vms
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,953::sd::626::Storage.StorageDomain::(createMasterTree) creating task dir: /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/master/tasks
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,965::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=774e76f485c77e0e404142ccd1de0b1472a17050']
>265565e8-187f-4c7b-9197-eaeb2743fabb::DEBUG::2014-03-13 22:11:27,966::sp::326::Storage.StoragePool::(startSpm) ended.
>Thread-13::DEBUG::2014-03-13 22:11:28,109::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:28,110::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:28,110::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': '265565e8-187f-4c7b-9197-eaeb2743fabb'}}
>Thread-13::DEBUG::2014-03-13 22:11:28,117::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:28,118::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:11:28,135::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-13::DEBUG::2014-03-13 22:11:28,145::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:28,145::logUtils::44::dispatcher::(wrapper) Run and protect: clearTask(taskID='265565e8-187f-4c7b-9197-eaeb2743fabb', spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:28,146::logUtils::47::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-23::DEBUG::2014-03-13 22:11:28,192::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:11:28,193::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:11:28,200::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:11:28,260::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:28,261::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksInfo(spUUID=None, options=None)
>Thread-13::INFO::2014-03-13 22:11:28,261::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksInfo, Return response: {'allTasksInfo': {}}
>Thread-13::INFO::2014-03-13 22:11:36,496::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:11:36,496::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000306782', 'lastCheck': '8.6', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:11:37,868::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:11:37,882::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000374018 s, 1.5 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:38,258::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:38,259::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:11:38,276::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:11:38,285::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:11:38,287::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:11:38,296::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:11:47,909::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:11:47,922::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000410569 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:48,335::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:48,340::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:11:48,357::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:11:48,362::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:11:48,363::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:11:48,369::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:11:51,603::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:11:51,603::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000410569', 'lastCheck': '3.7', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:11:57,942::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:11:57,955::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000406246 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:11:58,405::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:11:58,406::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:11:58,424::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:11:58,434::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:11:58,434::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:11:58,443::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:12:04,876::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:04,877::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-13::DEBUG::2014-03-13 22:12:04,878::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-13::DEBUG::2014-03-13 22:12:04,878::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:04,904::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:04,930::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:04,933::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:04,972::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:04,982::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:05,016::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = "  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Please enter a physical volume path\n  Run `pvcreate --help' for more information.\n"; <rc> = 3
>Thread-13::DEBUG::2014-03-13 22:12:05,017::lvm::859::Storage.LVM::(testPVCreate) rc: 3, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Please enter a physical volume path', "  Run `pvcreate --help' for more information."], unusedDevs: set([]), usedDevs: set([])
>Thread-13::INFO::2014-03-13 22:12:05,017::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': []}
>Thread-13::INFO::2014-03-13 22:12:06,714::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:12:06,714::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000406246', 'lastCheck': '8.8', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:12:07,980::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:07,993::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000366884 s, 1.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:08,481::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:08,482::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:08,499::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:08,505::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:08,506::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:08,515::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:12:11,503::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:11,504::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '172.17.217.1', 'password': '******', 'port': '3260', 'user': ''}, options=None)
>Thread-13::DEBUG::2014-03-13 22:12:11,504::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 172.17.217.1:3260 --op=new' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:11,536::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:11,537::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 172.17.217.1:3260 --discover' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:11,684::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:11,685::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 172.17.217.1:3260 --op=delete' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:12:11,712::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::INFO::2014-03-13 22:12:11,713::logUtils::47::dispatcher::(wrapper) Run and protect: discoverSendTargets, Return response: {'fullTargets': ['172.17.217.1:3260,1 iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', '172.17.218.3:3260,2 iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', '172.17.218.1:3260,3 iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', '172.17.218.2:3260,4 iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652'], 'targets': ['iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652']}
>Thread-16::DEBUG::2014-03-13 22:12:18,018::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:18,031::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000403387 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:18,548::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:18,549::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:18,567::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:18,572::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:18,573::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:18,579::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:12:21,813::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:12:21,814::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000403387', 'lastCheck': '3.8', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:12:28,050::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:28,064::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000413728 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:28,615::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:28,616::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:28,634::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:28,640::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:28,641::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:28,650::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:12:37,111::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:12:37,111::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000413728', 'lastCheck': '9.0', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:12:38,090::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:38,103::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000390841 s, 1.5 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:38,688::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:38,689::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:38,707::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:38,713::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:38,714::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:38,723::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:12:48,125::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:48,139::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000456245 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:48,759::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:48,760::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:48,778::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:48,784::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:48,785::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:48,794::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:12:52,214::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:12:52,214::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000456245', 'lastCheck': '4.1', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:12:58,158::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:12:58,172::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000389812 s, 1.5 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:12:58,831::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:12:58,832::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:12:58,849::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:12:58,856::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:12:58,859::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:12:58,884::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:13:07,336::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:13:07,336::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000389812', 'lastCheck': '9.2', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:13:08,198::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:08,210::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000330111 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:08,918::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:08,919::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:08,937::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:08,943::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:08,944::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:08,953::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:13:18,231::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:18,244::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000349748 s, 1.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:19,034::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:19,035::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:19,060::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:19,066::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:19,067::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:19,076::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:13:22,436::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:13:22,437::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000349748', 'lastCheck': '4.2', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:13:28,271::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:28,285::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000425134 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:29,118::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:29,123::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:29,142::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:29,148::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:29,149::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:29,159::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:13:37,539::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:13:37,540::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000425134', 'lastCheck': '9.3', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:13:38,312::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:38,325::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000371222 s, 1.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:39,194::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:39,195::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:39,212::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:39,218::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:39,218::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:39,225::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:13:48,348::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:48,362::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000478723 s, 1.2 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:49,258::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:49,259::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:49,276::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:49,282::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:49,283::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:49,293::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:13:52,665::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:13:52,665::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000478723', 'lastCheck': '4.3', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:13:58,387::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:13:58,400::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.0003522 s, 1.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:13:59,333::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:13:59,334::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:13:59,351::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:13:59,357::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:13:59,358::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:13:59,367::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:14:07,765::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:14:07,766::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0003522', 'lastCheck': '9.4', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:14:08,427::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:08,439::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000324222 s, 1.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:09,403::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:09,404::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:09,421::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:09,427::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:09,427::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:09,434::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:14:18,460::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:18,473::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000377576 s, 1.5 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:19,468::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:19,469::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:19,487::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:19,493::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:19,493::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:19,503::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:14:22,869::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:14:22,870::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000377576', 'lastCheck': '4.4', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:14:28,500::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:28,513::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000434238 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:29,537::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:29,538::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:29,555::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:29,561::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:29,562::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:29,570::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:14:34,818::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [6e6b9f18]
>Thread-13::INFO::2014-03-13 22:14:34,819::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '172.17.217.1', 'iqn': 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'portal': '0', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': '3260'}], options=None)
>Thread-13::DEBUG::2014-03-13 22:14:34,820::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 --op=new' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:34,852::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:34,853::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 -l' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:35,445::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:35,446::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 -n node.startup -v manual --op=update' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:35,473::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:35,475::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:35,523::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:35,524::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-13::DEBUG::2014-03-13 22:14:35,524::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {9410073b-7811-4eea-b834-9fe3c8cf523b: storage.nfsSD.findDomain}
>Thread-13::INFO::2014-03-13 22:14:35,524::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-13::DEBUG::2014-03-13 22:14:35,742::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:35,743::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-13::DEBUG::2014-03-13 22:14:35,744::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-13::DEBUG::2014-03-13 22:14:35,744::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:35,815::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:36,075::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:36,079::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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-13::DEBUG::2014-03-13 22:14:36,128::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:36,229::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/3600000e00d1100000011265200040000' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:14:36,275::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t initialize physical volume "/dev/mapper/3600000e00d1100000011265200040000" of volume group "2a846501-110c-4a1d-9d54-ecd44729e70b" without -ff\n'; <rc> = 5
>Thread-13::DEBUG::2014-03-13 22:14:36,276::lvm::859::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Can\'t initialize physical volume "/dev/mapper/3600000e00d1100000011265200040000" of volume group "2a846501-110c-4a1d-9d54-ecd44729e70b" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/3600000e00d1100000011265200040000'])
>Thread-13::INFO::2014-03-13 22:14:36,277::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'FUJITSU', 'capacity': '107374182400', 'fwrev': '0000', 'vgUUID': 'Q5D9qc-ax1P-7fO1-8X5l-TRcL-5ls1-2fpPbE', 'pathlist': [{'initiatorname': 'default', 'connection': '172.17.217.1', 'iqn': 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'portal': '1', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sda', 'type': 'iSCSI', 'state': 'active', 'lun': '0'}], 'devtype': 'iSCSI', 'physicalblocksize': '512', 'pvUUID': 'KqaYC2-i7uW-3rYL-bxTg-boD2-rMp6-AIL7uf', 'serial': 'SFUJITSU_ETERNUS_DXL_112652', 'GUID': '3600000e00d1100000011265200040000', 'productID': 'ETERNUS_DXL'}]}
>Thread-13::INFO::2014-03-13 22:14:37,969::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:14:37,970::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000434238', 'lastCheck': '9.5', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:14:38,541::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:38,554::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000347988 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:39,607::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:39,608::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:39,626::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:39,631::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:39,632::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:39,638::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:14:48,576::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:48,589::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000431475 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:49,672::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:49,673::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:49,690::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:49,696::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:49,696::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:49,705::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:14:53,071::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:14:53,072::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000431475', 'lastCheck': '4.5', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:14:58,615::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:14:58,628::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000405601 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:14:59,737::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:14:59,738::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:14:59,755::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:14:59,760::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:14:59,761::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:14:59,770::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:15:08,170::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:15:08,170::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000405601', 'lastCheck': '9.5', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:15:08,654::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:08,667::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000453132 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:09,804::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:15:09,805::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:15:09,823::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:15:09,829::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:15:09,829::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:09,836::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:15:18,347::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [6055bbac]
>Thread-13::INFO::2014-03-13 22:15:18,348::logUtils::44::dispatcher::(wrapper) Run and protect: createVG(vgname='6a35276e-e0ea-453f-9da8-983ccec65247', devlist=['3600000e00d1100000011265200040000'], force=True, options=None)
>Thread-13::DEBUG::2014-03-13 22:15:18,350::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " -y -ff --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/3600000e00d1100000011265200040000' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,527::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: Forcing physical volume creation on /dev/mapper/3600000e00d1100000011265200040000 of volume group "2a846501-110c-4a1d-9d54-ecd44729e70b"\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:18,529::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --metadataignore n /dev/mapper/3600000e00d1100000011265200040000' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,591::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:18,592::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --physicalextentsize 128m --addtag RHAT_storage_domain_UNREADY 6a35276e-e0ea-453f-9da8-983ccec65247 /dev/mapper/3600000e00d1100000011265200040000' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:18,695::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,709::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-03-13 22:15:18,715::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000331089 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:18,719::lvm::930::Storage.LVM::(createVG) Cache after createvg {'6a35276e-e0ea-453f-9da8-983ccec65247': Stub(name='6a35276e-e0ea-453f-9da8-983ccec65247', stale=True)}
>Thread-13::DEBUG::2014-03-13 22:15:18,726::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,770::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::INFO::2014-03-13 22:15:18,772::logUtils::47::dispatcher::(wrapper) Run and protect: createVG, Return response: {'uuid': 'aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ'}
>Thread-13::DEBUG::2014-03-13 22:15:18,783::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [6055bbac]
>Thread-13::INFO::2014-03-13 22:15:18,784::logUtils::44::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=3, sdUUID='6a35276e-e0ea-453f-9da8-983ccec65247', domainName='test4', typeSpecificArg='aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', domClass=1, domVersion='3', options=None)
>Thread-13::ERROR::2014-03-13 22:15:18,784::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 6a35276e-e0ea-453f-9da8-983ccec65247
>Thread-13::ERROR::2014-03-13 22:15:18,785::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 6a35276e-e0ea-453f-9da8-983ccec65247
>Thread-13::ERROR::2014-03-13 22:15:18,791::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 6a35276e-e0ea-453f-9da8-983ccec65247 not found
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
>    dom = findMethod(sdUUID)
>  File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
>    raise se.StorageDomainDoesNotExist(sdUUID)
>StorageDomainDoesNotExist: Storage domain does not exist: ('6a35276e-e0ea-453f-9da8-983ccec65247',)
>Thread-13::INFO::2014-03-13 22:15:18,800::blockSD::492::Storage.StorageDomain::(create) sdUUID=6a35276e-e0ea-453f-9da8-983ccec65247 domainName=test4 domClass=1 vgUUID=aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ storageType=3 version=3
>Thread-13::DEBUG::2014-03-13 22:15:18,801::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,845::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:18,848::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:18,890::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:18,891::lvm::461::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-13::INFO::2014-03-13 22:15:18,892::blockSD::476::Storage.StorageDomain::(metaSize) size 512 MB (metaratio 262144)
>Thread-13::DEBUG::2014-03-13 22:15:18,892::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 512m --name metadata 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,012::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,014::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,060::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,062::lvm::461::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-13::DEBUG::2014-03-13 22:15:19,063::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,105::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::INFO::2014-03-13 22:15:19,107::blockSD::665::Storage.StorageDomain::(getMetaDataMapping) Create: SORT MAPPING: ['/dev/mapper/3600000e00d1100000011265200040000']
>Thread-13::DEBUG::2014-03-13 22:15:19,108::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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 /dev/mapper/3600000e00d1100000011265200040000' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,155::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,157::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 2048m --name leases 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,274::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,276::lvm::1079::Storage.Misc.excCmd::(createLV) '/usr/bin/sudo -n /usr/bin/chown vdsm:qemu /dev/6a35276e-e0ea-453f-9da8-983ccec65247/leases' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,301::lvm::1079::Storage.Misc.excCmd::(createLV) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,303::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 8m --name ids 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,420::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,422::lvm::1079::Storage.Misc.excCmd::(createLV) '/usr/bin/sudo -n /usr/bin/chown vdsm:qemu /dev/6a35276e-e0ea-453f-9da8-983ccec65247/ids' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,446::lvm::1079::Storage.Misc.excCmd::(createLV) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,447::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 16m --name inbox 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,565::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,568::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 16m --name outbox 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,687::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,690::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvcreate --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --contiguous n --size 1024m --name master 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,830::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: This metadata update is NOT backed up\n  WARNING: This metadata update is NOT backed up\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,832::lvm::1079::Storage.Misc.excCmd::(createLV) '/usr/bin/sudo -n /usr/bin/chown vdsm:qemu /dev/6a35276e-e0ea-453f-9da8-983ccec65247/master' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:19,856::lvm::1079::Storage.Misc.excCmd::(createLV) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:19,857::blockSD::1352::Storage.Misc.excCmd::(_createVMSfs) '/usr/bin/sudo -n /usr/sbin/mkfs -q -j -E nodiscard /dev/6a35276e-e0ea-453f-9da8-983ccec65247/master' (cwd None)
>Thread-24::DEBUG::2014-03-13 22:15:19,876::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-24::INFO::2014-03-13 22:15:19,878::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-24::INFO::2014-03-13 22:15:19,896::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:15:19,901::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:15:19,902::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:19,912::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::DEBUG::2014-03-13 22:15:20,417::blockSD::1352::Storage.Misc.excCmd::(_createVMSfs) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:20,418::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available n 6a35276e-e0ea-453f-9da8-983ccec65247/master' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:20,477::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:20,487::blockSD::544::Storage.Misc.excCmd::(create) '/usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/dd if=/dev/zero of=/dev/6a35276e-e0ea-453f-9da8-983ccec65247/metadata bs=1048576 seek=0 skip=0 conv=notrunc count=40 oflag=direct' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:20,958::blockSD::544::Storage.Misc.excCmd::(create) SUCCESS: <err> = '40+0 records in\n40+0 records out\n41943040 bytes (42 MB) copied, 0.443423 s, 94.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:20,959::misc::287::Storage.Misc::(validateDDBytes) err: ['40+0 records in', '40+0 records out', '41943040 bytes (42 MB) copied, 0.443423 s, 94.6 MB/s'], size: 41943040
>Thread-13::DEBUG::2014-03-13 22:15:20,967::blockSD::546::Storage.Misc.excCmd::(create) '/usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/dd if=/dev/zero of=/dev/6a35276e-e0ea-453f-9da8-983ccec65247/inbox bs=1024000 seek=0 skip=0 conv=notrunc count=1 oflag=direct' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:20,992::blockSD::546::Storage.Misc.excCmd::(create) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0110368 s, 92.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:20,993::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '1024000 bytes (1.0 MB) copied, 0.0110368 s, 92.8 MB/s'], size: 1024000
>Thread-13::DEBUG::2014-03-13 22:15:21,001::blockSD::548::Storage.Misc.excCmd::(create) '/usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/dd if=/dev/zero of=/dev/6a35276e-e0ea-453f-9da8-983ccec65247/outbox bs=1024000 seek=0 skip=0 conv=notrunc count=1 oflag=direct' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,029::blockSD::548::Storage.Misc.excCmd::(create) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0109849 s, 93.2 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,030::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '1024000 bytes (1.0 MB) copied, 0.0109849 s, 93.2 MB/s'], size: 1024000
>Thread-13::DEBUG::2014-03-13 22:15:21,030::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:15:21,031::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,081::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,085::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,128::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,132::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=[]
>Thread-13::WARNING::2014-03-13 22:15:21,132::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-13::DEBUG::2014-03-13 22:15:21,132::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-13::DEBUG::2014-03-13 22:15:21,141::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-13::DEBUG::2014-03-13 22:15:21,142::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (VGTagMetadataRW)=['CLASS=Data', 'DESCRIPTION=test4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'LOGBLKSIZE=512', 'PHYBLKSIZE=512', 'POOL_UUID=', 'PV0=pv:3600000e00d1100000011265200040000,uuid:YET5f0-Khir-Zy25-iUt0-yCXz-Mn0l-Hf3TOb,pestart:0,pecount:797,mapoffset:0', 'ROLE=Regular', 'SDUUID=6a35276e-e0ea-453f-9da8-983ccec65247', 'TYPE=ISCSI', 'VERSION=3', 'VGUUID=aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', '_SHA_CKSUM=e353107d997517fbcf7a5ee83f0265da2cec49b0']
>Thread-13::DEBUG::2014-03-13 22:15:21,144::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,187::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,191::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --addtag MDT_PV0=pv:3600000e00d1100000011265200040000&44&uuid:YET5f0-Khir-Zy25-iUt0-yCXz-Mn0l-Hf3TOb&44&pestart:0&44&pecount:797&44&mapoffset:0 --addtag MDT_LEASETIMESEC=60 --addtag MDT_POOL_UUID= --addtag MDT_TYPE=ISCSI --addtag MDT__SHA_CKSUM=e353107d997517fbcf7a5ee83f0265da2cec49b0 --addtag MDT_LOGBLKSIZE=512 --addtag MDT_LEASERETRIES=3 --addtag MDT_IOOPTIMEOUTSEC=10 --addtag MDT_LOCKRENEWALINTERVALSEC=5 --addtag MDT_ROLE=Regular --addtag MDT_PHYBLKSIZE=512 --addtag MDT_VGUUID=aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ --addtag MDT_CLASS=Data --addtag MDT_DESCRIPTION=test4 --addtag MDT_LOCKPOLICY= --addtag MDT_SDUUID=6a35276e-e0ea-453f-9da8-983ccec65247 --addtag MDT_VERSION=3 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,278::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,279::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-13::DEBUG::2014-03-13 22:15:21,280::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --deltag RHAT_storage_domain_UNREADY --addtag RHAT_storage_domain 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,375::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,376::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:15:21,383::blockSD::336::Storage.Misc.excCmd::(readlines) '/usr/bin/dd iflag=direct skip=0 bs=2048 if=/dev/6a35276e-e0ea-453f-9da8-983ccec65247/metadata count=1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,396::blockSD::336::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000539097 s, 3.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,397::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000539097 s, 3.8 MB/s'], size: 2048
>Thread-13::DEBUG::2014-03-13 22:15:21,397::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-13::WARNING::2014-03-13 22:15:21,397::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-13::DEBUG::2014-03-13 22:15:21,397::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:15:21,399::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,442::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,445::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=[u'PV0=pv:3600000e00d1100000011265200040000,uuid:YET5f0-Khir-Zy25-iUt0-yCXz-Mn0l-Hf3TOb,pestart:0,pecount:797,mapoffset:0', 'LEASETIMESEC=60', 'POOL_UUID=', 'TYPE=ISCSI', '_SHA_CKSUM=e353107d997517fbcf7a5ee83f0265da2cec49b0', 'LOGBLKSIZE=512', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'ROLE=Regular', 'PHYBLKSIZE=512', 'VGUUID=aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', 'CLASS=Data', 'DESCRIPTION=test4', 'LOCKPOLICY=', 'SDUUID=6a35276e-e0ea-453f-9da8-983ccec65247', 'VERSION=3']
>Thread-13::DEBUG::2014-03-13 22:15:21,446::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 6a35276e-e0ea-453f-9da8-983ccec65247/master' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,548::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,576::sd::424::Storage.StorageDomain::(initSPMlease) lease initialized successfully
>Thread-13::DEBUG::2014-03-13 22:15:21,577::hsm::2636::Storage.HSM::(createStorageDomain) knownSDs: {9410073b-7811-4eea-b834-9fe3c8cf523b: storage.nfsSD.findDomain, 6a35276e-e0ea-453f-9da8-983ccec65247: storage.blockSD.findDomain}
>Thread-13::INFO::2014-03-13 22:15:21,577::logUtils::47::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
>Thread-13::DEBUG::2014-03-13 22:15:21,592::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [6055bbac]
>Thread-13::INFO::2014-03-13 22:15:21,593::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='6a35276e-e0ea-453f-9da8-983ccec65247', options=None)
>Thread-13::DEBUG::2014-03-13 22:15:21,597::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:15:21,605::blockSD::336::Storage.Misc.excCmd::(readlines) '/usr/bin/dd iflag=direct skip=0 bs=2048 if=/dev/6a35276e-e0ea-453f-9da8-983ccec65247/metadata count=1' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,619::blockSD::336::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.00040459 s, 5.1 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:21,619::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.00040459 s, 5.1 MB/s'], size: 2048
>Thread-13::DEBUG::2014-03-13 22:15:21,620::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-13::WARNING::2014-03-13 22:15:21,620::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-13::DEBUG::2014-03-13 22:15:21,620::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-13::DEBUG::2014-03-13 22:15:21,621::lvm::295::Storage.Misc.excCmd::(cmd) '/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 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600000e00d1100000011265200040000|\', \'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,lv_count,pv_count,pv_name 6a35276e-e0ea-453f-9da8-983ccec65247' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:21,665::lvm::295::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::INFO::2014-03-13 22:15:21,667::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': '134217728', 'mdathreshold': True, 'mdavalid': True, 'diskfree': '102810779648', 'disktotal': '106971529216', 'mdafree': '67104768'}}
>Thread-13::DEBUG::2014-03-13 22:15:21,710::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [6055bbac]
>Thread-13::INFO::2014-03-13 22:15:21,711::logUtils::44::dispatcher::(wrapper) Run and protect: getVGInfo(vgUUID='aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', options=None)
>Thread-13::INFO::2014-03-13 22:15:21,812::logUtils::47::dispatcher::(wrapper) Run and protect: getVGInfo, Return response: {'info': {'state': 'OK', 'vgsize': '106971529216', 'name': '6a35276e-e0ea-453f-9da8-983ccec65247', 'vgfree': '102810779648', 'vgUUID': 'aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', 'pvlist': [{'vendorID': 'FUJITSU', 'capacity': '106971529216', 'fwrev': '0000', 'vgUUID': 'aSrL5M-SyWm-qxlX-GWMW-syeu-ci0t-93OQqJ', 'pathlist': [{'connection': '172.17.217.1', 'iqn': 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'portal': '1', 'port': '3260', 'initiatorname': 'default'}], 'pathstatus': [{'physdev': 'sda', 'type': 'iSCSI', 'state': 'active', 'lun': '0'}], 'devtype': 'iSCSI', 'pvUUID': 'YET5f0-Khir-Zy25-iUt0-yCXz-Mn0l-Hf3TOb', 'serial': 'SFUJITSU_ETERNUS_DXL_112652', 'GUID': '3600000e00d1100000011265200040000', 'devcapacity': '107374182400', 'productID': 'ETERNUS_DXL'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-13::DEBUG::2014-03-13 22:15:22,562::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [155297ad]
>Thread-13::INFO::2014-03-13 22:15:22,563::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '172.17.217.1', 'iqn': 'iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652', 'portal': '1', 'user': '', 'password': '******', 'id': '0182065a-2612-40cc-9ea5-cd41edc5212c', 'port': '3260'}], options=None)
>Thread-13::DEBUG::2014-03-13 22:15:22,564::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 --op=new' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:22,593::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:22,593::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 -l' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:22,620::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: default: 1 session requested, but 1 already present.\niscsiadm: Could not log into all portals\n'; <rc> = 15
>Thread-13::DEBUG::2014-03-13 22:15:22,621::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m iface' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:22,721::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:22,722::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 -u' (cwd None)
>Thread-13::DEBUG::2014-03-13 22:15:23,255::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:23,256::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2000-09.com.fujitsu:storage-system.eternus-dxl:00046652 -I default -p 172.17.217.1:3260 --op=delete' (cwd None)
>Thread-24::INFO::2014-03-13 22:15:23,273::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-24::INFO::2014-03-13 22:15:23,273::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000331089', 'lastCheck': '4.5', 'valid': True}}
>Thread-13::DEBUG::2014-03-13 22:15:23,283::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::ERROR::2014-03-13 22:15:23,284::hsm::2378::Storage.HSM::(connectStorageServer) Could not connect to storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 2375, in connectStorageServer
>    conObj.connect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 359, in connect
>    iscsi.addIscsiNode(self._iface, self._target, self._cred)
>  File "/usr/share/vdsm/storage/iscsi.py", line 157, in addIscsiNode
>    iscsiadm.node_login(iface.name, portalStr, targetName)
>  File "/usr/share/vdsm/storage/iscsiadm.py", line 295, in node_login
>    raise IscsiNodeError(rc, out, err)
>IscsiNodeError: (15, [], ['iscsiadm: default: 1 session requested, but 1 already present.', 'iscsiadm: Could not log into all portals'])
>Thread-13::DEBUG::2014-03-13 22:15:23,336::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {9410073b-7811-4eea-b834-9fe3c8cf523b: storage.nfsSD.findDomain, 6a35276e-e0ea-453f-9da8-983ccec65247: storage.blockSD.findDomain}
>Thread-13::INFO::2014-03-13 22:15:23,336::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 465, 'id': '0182065a-2612-40cc-9ea5-cd41edc5212c'}]}
>Thread-23::DEBUG::2014-03-13 22:15:23,401::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44] flowID [155297ad]
>Thread-23::INFO::2014-03-13 22:15:23,402::logUtils::44::dispatcher::(wrapper) Run and protect: attachStorageDomain(sdUUID='6a35276e-e0ea-453f-9da8-983ccec65247', spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:23,405::sp::860::Storage.StoragePool::(attachSD) sdUUID=6a35276e-e0ea-453f-9da8-983ccec65247 spUUID=00000002-0002-0002-0002-000000000002
>Thread-23::ERROR::2014-03-13 22:15:24,415::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('6a35276e-e0ea-453f-9da8-983ccec65247', SanlockException(5, 'Sanlock lockspace add failure', 'Input/output error'))", 'code': 661}}
>Thread-16::DEBUG::2014-03-13 22:15:28,763::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:28,776::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000427668 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:29,948::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:15:29,949::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:15:29,967::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:15:29,973::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:15:29,974::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:29,983::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:15:38,383::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:15:38,384::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000427668', 'lastCheck': '9.6', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:15:38,802::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:38,815::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000424572 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:40,018::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:15:40,019::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:15:40,045::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:15:40,050::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:15:40,050::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:40,057::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-16::DEBUG::2014-03-13 22:15:48,836::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:48,849::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000342162 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:15:50,091::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:15:50,092::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:15:50,109::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:15:50,115::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:15:50,116::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:15:50,125::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:15:53,484::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:15:53,485::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000342162', 'lastCheck': '4.6', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:15:58,874::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:15:58,888::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n576 bytes (576 B) copied, 0.000393901 s, 1.5 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-03-13 22:16:00,160::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-13::INFO::2014-03-13 22:16:00,161::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-13::INFO::2014-03-13 22:16:00,179::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 3L}}
>Thread-23::DEBUG::2014-03-13 22:16:00,184::BindingXMLRPC::251::vds::(wrapper) client [192.168.1.44]
>Thread-23::INFO::2014-03-13 22:16:00,185::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000002', options=None)
>Thread-23::INFO::2014-03-13 22:16:00,194::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '9410073b-7811-4eea-b834-9fe3c8cf523b:Active,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached,553b4e8f-bfea-4183-94ac-04389180771c:Attached', 'master_uuid': '9410073b-7811-4eea-b834-9fe3c8cf523b', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 14}, 'dominfo': {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'status': 'Active', 'diskfree': '364472434688', 'isoprefix': '', 'alerts': [], 'disktotal': '581292261376', 'version': 3}, 'a2176c22-3565-4a5e-a20c-5f40d85020f3': {'status': 'Attached', 'isoprefix': '', 'alerts': []}, '553b4e8f-bfea-4183-94ac-04389180771c': {'status': 'Attached', 'isoprefix': '', 'alerts': []}}}
>Thread-13::INFO::2014-03-13 22:16:08,585::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-03-13 22:16:08,585::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9410073b-7811-4eea-b834-9fe3c8cf523b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000393901', 'lastCheck': '9.7', 'valid': True}}
>Thread-16::DEBUG::2014-03-13 22:16:08,892::domainMonitor::192::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-16::DEBUG::2014-03-13 22:16:08,893::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-16::DEBUG::2014-03-13 22:16:08,894::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:16:08,921::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-16::DEBUG::2014-03-13 22:16:08,947::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-03-13 22:16:08,960::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b
>Thread-16::DEBUG::2014-03-13 22:16:08,962::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-16::DEBUG::2014-03-13 22:16:08,974::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmfs1vm4', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=14', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=9410073b-7811-4eea-b834-9fe3c8cf523b:Active,553b4e8f-bfea-4183-94ac-04389180771c:Attached,a2176c22-3565-4a5e-a20c-5f40d85020f3:Attached', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000002', 'REMOTE_PATH=vmfs1.corp.sgstool.com:/mnt/virtimages1/ovirt-vm4', 'ROLE=Master', 'SDUUID=9410073b-7811-4eea-b834-9fe3c8cf523b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=774e76f485c77e0e404142ccd1de0b1472a17050']
>Thread-16::DEBUG::2014-03-13 22:16:08,976::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-16::INFO::2014-03-13 22:16:08,977::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9410073b-7811-4eea-b834-9fe3c8cf523b_imageNS already registered
>Thread-16::INFO::2014-03-13 22:16:08,977::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 9410073b-7811-4eea-b834-9fe3c8cf523b_volumeNS already registered
>Thread-16::DEBUG::2014-03-13 22:16:08,997::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/vmfs1.corp.sgstool.com:_mnt_virtimages1_ovirt-vm4/9410073b-7811-4eea-b834-9fe3c8cf523b/dom_md/metadata bs=4096 count=1' (cwd None)

Actions: View

Attachments on bug 1076603: 874545