Attachment 919387 Details for Bug 1120823 – vdsm start log

vdsm start log

vdsm_start.log (text/plain), 83.55 KB, created by Markus Stockhausen on 2014-07-20 12:26:22 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Markus Stockhausen

Created: 2014-07-20 12:26:22 UTC

Size: 83.55 KB

patch

obsolete

>MainThread::INFO::2014-07-20 14:21:58,916::vdsm::119::vds::(run) (PID: 15595) I am the actual vdsm 4.14.9-0.fc20 colovn07.collogia.de (3.15.5-200.fc20.x86_64)
>MainThread::DEBUG::2014-07-20 14:21:58,917::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-20 14:21:58,918::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::WARNING::2014-07-20 14:21:58,921::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-20 14:21:59,398::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-20 14:21:59,407::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-20 14:21:59,407::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-07-20 14:21:59,434::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-20 14:21:59,434::hsm::458::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-20 14:21:59,437::hsm::490::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-20 14:21:59,437::hsm::491::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-20 14:21:59,437::hsm::493::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-20 14:21:59,438::hsm::536::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-20 14:21:59,439::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-20 14:21:59,441::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-20 14:21:59,441::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-20 14:21:59,461::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-20 14:21:59,469::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-20 14:21:59,469::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-20 14:21:59,470::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-07-20 14:21:59,489::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-20 14:21:59,489::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::DEBUG::2014-07-20 14:21:59,499::task::595::TaskManager.Task::(_updateState) Task=`e5f26d99-b148-4c63-9e11-5bce23931af3`::moving from state init -> state preparing
>MainThread::INFO::2014-07-20 14:21:59,499::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1cd5248>>)
>MainThread::INFO::2014-07-20 14:21:59,499::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-20 14:21:59,499::task::1185::TaskManager.Task::(prepare) Task=`e5f26d99-b148-4c63-9e11-5bce23931af3`::finished: None
>MainThread::DEBUG::2014-07-20 14:21:59,500::task::595::TaskManager.Task::(_updateState) Task=`e5f26d99-b148-4c63-9e11-5bce23931af3`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-20 14:21:59,500::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-20 14:21:59,500::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-20 14:21:59,500::task::990::TaskManager.Task::(_decref) Task=`e5f26d99-b148-4c63-9e11-5bce23931af3`::ref 0 aborting False
>MainThread::INFO::2014-07-20 14:21:59,508::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-20 14:21:59,514::vmChannels::191::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-20 14:21:59,539::vmChannels::174::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-20 14:21:59,539::libvirtconnection::145::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-20 14:21:59,547::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-20 14:21:59,550::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>MainThread::WARNING::2014-07-20 14:21:59,549::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
>storageRefresh::DEBUG::2014-07-20 14:21:59,550::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,550::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,551::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,552::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,552::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,552::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-20 14:21:59,552::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,553::lvm::296::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  use_lvmetad=0 }  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)
>storageRefresh::DEBUG::2014-07-20 14:21:59,586::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-20 14:21:59,590::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,595::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,607::lvm::296::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  use_lvmetad=0 }  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-07-20 14:21:59,645::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-20 14:21:59,648::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,656::lvm::296::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  use_lvmetad=0 }  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-07-20 14:21:59,689::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-20 14:21:59,692::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-20 14:21:59,698::lvm::296::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  use_lvmetad=0 }  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-07-20 14:21:59,725::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-20 14:21:59,727::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::WARNING::2014-07-20 14:21:59,728::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
>storageRefresh::DEBUG::2014-07-20 14:21:59,729::hsm::393::Storage.HSM::(storageRefresh) HSM is ready
>Thread-13::DEBUG::2014-07-20 14:23:08,450::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call getCapabilities with () {} flowID [54db931a]
>Thread-13::DEBUG::2014-07-20 14:23:08,512::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:08,519::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:08,630::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:7df62fdc4a0'}], 'FC': []}, 'packages2': {'kernel': {'release': '200.fc20.x86_64', 'buildtime': 1405345208.0, 'version': '3.15.5'}, 'spice-server': {'release': '2.fc20', 'buildtime': 1400513316L, 'version': '0.12.5'}, 'vdsm': {'release': '0.fc20', 'buildtime': 1402349469L, 'version': '4.14.9'}, 'qemu-kvm': {'release': '6.fc20', 'buildtime': 1401585599L, 'version': '1.6.2'}, 'libvirt': {'release': '2.fc20', 'buildtime': 1400540444L, 'version': '1.1.3.5'}, 'qemu-img': {'release': '6.fc20', 'buildtime': 1401585599L, 'version': '1.6.2'}, 'mom': {'release': '1.fc20', 'buildtime': 1403118323L, 'version': '0.4.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           L5630  @ 2.13GHz', 'hooks': {'before_vm_start': {'collogia.py': {'md5': '6c6cc61fffc0e9a7ab7d47e84a3422f3'}}, 'before_vdsm_start': {'network.sh': {'md5': '4fd4a6587e86eb836e9abbd98bbd2c1e'}}}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'NAS2': {'iface': 'NAS2', 'addr': '10.2.1.247', 'cfg': {'DEFROUTE': 'no', 'IPADDR': '10.2.1.247', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'NAS2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34f/64'], 'gateway': '', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'mtu': '9000', 'ipv6gateway': '::', 'ports': ['p5p2']}, 'VDMZ1': {'iface': 'VDMZ1', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VDMZ1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::6cc8:2dff:fe15:f754/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': []}, 'VDMZ2': {'iface': 'VDMZ2', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VDMZ2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::acd7:e4ff:febf:c990/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': []}, 'NAS1': {'iface': 'NAS1', 'addr': '10.1.1.247', 'cfg': {'DEFROUTE': 'no', 'IPADDR': '10.1.1.247', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'NAS1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34e/64'], 'gateway': '', 'netmask': '255.255.255.0', 'stp': 'off', 'bridged': True, 'mtu': '9000', 'ipv6gateway': '::', 'ports': ['p5p1']}, 'VTrust': {'iface': 'VTrust', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VTrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::60dc:eff:fe86:dd47/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': []}, 'Infiniband': {'iface': u'ib0', 'addr': '10.10.30.247', 'ipv6addrs': ['fe80::202:c903:4d:a05b/64'], 'mtu': '2044', 'netmask': '255.255.255.0', 'bridged': False, 'interface': u'ib0', 'ipv6gateway': '::', 'gateway': ''}, 'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '192.168.11.47', 'cfg': {'DEFROUTE': 'yes', 'IPADDR': '192.168.11.47', 'HOTPLUG': 'no', 'GATEWAY': '192.168.10.7', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.254.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf4/64'], 'gateway': '192.168.10.7', 'netmask': '255.255.254.0', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['p1p1']}, 'Untrust': {'iface': 'Untrust', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'Untrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:773/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['p3p2']}, 'VUntrust': {'iface': 'VUntrust', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VUntrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::8cca:51ff:fef0:aefd/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': []}, 'DMZ2': {'iface': 'DMZ2', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'DMZ2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:772/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['p3p1']}, 'DMZ1': {'iface': 'DMZ1', 'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'DMZ1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf5/64'], 'gateway': '', 'netmask': '', 'stp': 'off', 'bridged': True, 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['p1p2']}}, 'bridges': {'NAS2': {'addr': '10.2.1.247', 'cfg': {'DEFROUTE': 'no', 'IPADDR': '10.2.1.247', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'NAS2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34f/64'], 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['p5p2']}, 'VDMZ1': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VDMZ1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::6cc8:2dff:fe15:f754/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'VDMZ2': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VDMZ2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::acd7:e4ff:febf:c990/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'NAS1': {'addr': '10.1.1.247', 'cfg': {'DEFROUTE': 'no', 'IPADDR': '10.1.1.247', 'HOTPLUG': 'no', 'MTU': '9000', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'NAS1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34e/64'], 'mtu': '9000', 'netmask': '255.255.255.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['p5p1']}, 'VTrust': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VTrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::60dc:eff:fe86:dd47/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'ovirtmgmt': {'addr': '192.168.11.47', 'cfg': {'DEFROUTE': 'yes', 'IPADDR': '192.168.11.47', 'HOTPLUG': 'no', 'GATEWAY': '192.168.10.7', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'NETMASK': '255.255.254.0', 'BOOTPROTO': 'none', 'STP': 'no', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf4/64'], 'mtu': '1500', 'netmask': '255.255.254.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '192.168.10.7', 'ports': ['p1p1']}, 'Untrust': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'Untrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:773/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['p3p2']}, ';vdsmdummy;': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'VUntrust': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'VUntrust', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::8cca:51ff:fef0:aefd/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}, 'DMZ2': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'DMZ2', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:772/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['p3p1']}, 'DMZ1': {'addr': '', 'cfg': {'DEFROUTE': 'no', 'HOTPLUG': 'no', 'DELAY': '0', 'NM_CONTROLLED': 'no', 'STP': 'no', 'DEVICE': 'DMZ1', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf5/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': ['p1p2']}}, 'uuid': '6AC1F064-B7B0-11DF-9C4C-0019998D0BF4', 'lastClientIface': 'ovirtmgmt', 'nics': {'p5p1': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:36:c3:4e', 'cfg': {'BRIDGE': 'NAS1', 'NM_CONTROLLED': 'no', 'MTU': '9000', 'HWADDR': '00:15:17:36:c3:4e', 'STP': 'no', 'DEVICE': 'p5p1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34e/64'], 'speed': 1000, 'mtu': '9000'}, 'p5p2': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:36:c3:4f', 'cfg': {'BRIDGE': 'NAS2', 'NM_CONTROLLED': 'no', 'MTU': '9000', 'HWADDR': '00:15:17:36:c3:4f', 'STP': 'no', 'DEVICE': 'p5p2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:c34f/64'], 'speed': 1000, 'mtu': '9000'}, 'p1p1': {'netmask': '', 'addr': '', 'hwaddr': '00:19:99:8d:0b:f4', 'cfg': {'BRIDGE': 'ovirtmgmt', 'NM_CONTROLLED': 'no', 'HWADDR': '00:19:99:8d:0b:f4', 'STP': 'no', 'DEVICE': 'p1p1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf4/64'], 'speed': 1000, 'mtu': '1500'}, 'p1p2': {'netmask': '', 'addr': '', 'hwaddr': '00:19:99:8d:0b:f5', 'cfg': {'BRIDGE': 'DMZ1', 'NM_CONTROLLED': 'no', 'HWADDR': '00:19:99:8d:0b:f5', 'STP': 'no', 'DEVICE': 'p1p2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::219:99ff:fe8d:bf5/64'], 'speed': 1000, 'mtu': '1500'}, 'ib0': {'netmask': '255.255.255.0', 'addr': '10.10.30.247', 'hwaddr': '80:00:00:48:fe:80:00:00:00:00:00:00:00:02:c9:03:00:4d:a0:5b', 'cfg': {'NM_CONTROLLED': 'no', 'DEFROUTE': 'no', 'IPADDR': '10.10.30.247', 'HWADDR': '80:00:00:48:fe:80:00:00:00:00:00:00:00:02:c9:03:00:4d:a0:5b', 'NETMASK': '255.255.255.0', 'BOOTPROTO': 'none', 'DEVICE': 'ib0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::202:c903:4d:a05b/64'], 'speed': 0, 'mtu': '2044'}, 'dummy0': {'netmask': '', 'addr': '', 'hwaddr': '62:dc:0e:86:dd:47', 'cfg': {'BRIDGE': 'VTrust', 'NM_CONTROLLED': 'no', 'HWADDR': '62:dc:0e:86:dd:47', 'STP': 'no', 'DEVICE': 'dummy0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::60dc:eff:fe86:dd47/64'], 'speed': 0, 'mtu': '1500'}, 'p3p2': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:36:07:73', 'cfg': {'BRIDGE': 'Untrust', 'NM_CONTROLLED': 'no', 'HWADDR': '00:15:17:36:07:73', 'STP': 'no', 'DEVICE': 'p3p2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:773/64'], 'speed': 1000, 'mtu': '1500'}, 'p3p1': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:36:07:72', 'cfg': {'BRIDGE': 'DMZ2', 'NM_CONTROLLED': 'no', 'HWADDR': '00:15:17:36:07:72', 'STP': 'no', 'DEVICE': 'p3p1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe36:772/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,pdpe1gb,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,dca,sse4_1,sse4_2,popcnt,aes,lahf_lm,ida,arat,epb,dtherm,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:7df62fdc4a0', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '52:e3:2b:9a:de:ad', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '96678', 'cpuSpeed': '2129.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '16', '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': '3', 'version': '20', 'name': 'Fedora'}, 'lastClient': '192.168.11.2'}}
>Thread-13::DEBUG::2014-07-20 14:23:08,891::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call getHardwareInfo with () {} flowID [54db931a]
>Thread-13::DEBUG::2014-07-20 14:23:08,893::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'PRIMERGY RX300 S6', 'systemSerialNumber': 'YL6T009514', 'systemFamily': 'SERVER', 'systemVersion': 'GS01', 'systemUUID': '6ac1f064-b7b0-11df-9c4c-0019998d0bf4', 'systemManufacturer': 'FUJITSU'}}
>Thread-13::DEBUG::2014-07-20 14:23:09,071::BindingXMLRPC::251::vds::(wrapper) client [192.168.11.2] flowID [3e757378]
>Thread-13::DEBUG::2014-07-20 14:23:09,072::task::595::TaskManager.Task::(_updateState) Task=`2562d514-f535-4d0d-8c6f-f61effc5aff2`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:09,072::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', conList=[{'connection': '10.10.30.253:/var/nas3/OVirtISO', 'iqn': '', 'user': '', 'tpgt': '', 'password': '******', 'id': '4bcc316a-d6c9-48cd-af67-bf6c06be702d', 'port': ''}, {'connection': '10.10.30.251:/var/nas1/OVirtIB', 'iqn': '', 'user': '', 'tpgt': '', 'password': '******', 'id': '4d0b50e6-05c2-4751-a268-1ee5d3878415', 'port': ''}, {'connection': '10.10.30.253:/var/nas3/OVirtIB', 'iqn': '', 'user': '', 'tpgt': '', 'password': '******', 'id': '4dbcef7e-48b3-4a41-9772-40d4480c074c', 'port': ''}, {'connection': '10.10.30.253:/var/nas3/OVirtEXP', 'iqn': '', 'user': '', 'tpgt': '', 'password': '******', 'id': 'a120f183-f080-40f8-93b0-f5301978ff3c', 'port': ''}, {'connection': '10.10.30.252:/var/nas2/OVirtIB', 'iqn': '', 'user': '', 'tpgt': '', 'password': '******', 'id': 'ff550c17-a171-4a46-93b5-3ae4c8600f60', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-07-20 14:23:09,075::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 10.10.30.253:/var/nas3/OVirtISO /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,265::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO
>Thread-13::DEBUG::2014-07-20 14:23:09,267::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('bff3a2be-fdd9-4e37-b416-fa4ef7fafba2',)
>Thread-13::DEBUG::2014-07-20 14:23:09,268::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {bff3a2be-fdd9-4e37-b416-fa4ef7fafba2: storage.nfsSD.findDomain}
>Thread-13::DEBUG::2014-07-20 14:23:09,272::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 10.10.30.251:/var/nas1/OVirtIB /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,303::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB
>Thread-13::DEBUG::2014-07-20 14:23:09,304::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545',)
>Thread-13::DEBUG::2014-07-20 14:23:09,304::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545: storage.nfsSD.findDomain, bff3a2be-fdd9-4e37-b416-fa4ef7fafba2: storage.nfsSD.findDomain}
>Thread-13::DEBUG::2014-07-20 14:23:09,308::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 10.10.30.253:/var/nas3/OVirtIB /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,337::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB
>Thread-13::DEBUG::2014-07-20 14:23:09,338::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('2c51d320-88ce-4f23-8215-e15f55f66906',)
>Thread-13::DEBUG::2014-07-20 14:23:09,339::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545: storage.nfsSD.findDomain, bff3a2be-fdd9-4e37-b416-fa4ef7fafba2: storage.nfsSD.findDomain, 2c51d320-88ce-4f23-8215-e15f55f66906: storage.nfsSD.findDomain}
>Thread-13::DEBUG::2014-07-20 14:23:09,342::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 10.10.30.253:/var/nas3/OVirtEXP /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,371::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP
>Thread-13::DEBUG::2014-07-20 14:23:09,373::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('63041fa9-e093-4b44-b36f-f39f16d3974f',)
>Thread-13::DEBUG::2014-07-20 14:23:09,373::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545: storage.nfsSD.findDomain, bff3a2be-fdd9-4e37-b416-fa4ef7fafba2: storage.nfsSD.findDomain, 63041fa9-e093-4b44-b36f-f39f16d3974f: storage.nfsSD.findDomain, 2c51d320-88ce-4f23-8215-e15f55f66906: storage.nfsSD.findDomain}
>Thread-13::DEBUG::2014-07-20 14:23:09,377::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 10.10.30.252:/var/nas2/OVirtIB /rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,407::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB
>Thread-13::DEBUG::2014-07-20 14:23:09,408::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('272ec473-6041-42ee-bd1a-732789dd18d4',)
>Thread-13::DEBUG::2014-07-20 14:23:09,408::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {272ec473-6041-42ee-bd1a-732789dd18d4: storage.nfsSD.findDomain, 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545: storage.nfsSD.findDomain, bff3a2be-fdd9-4e37-b416-fa4ef7fafba2: storage.nfsSD.findDomain, 63041fa9-e093-4b44-b36f-f39f16d3974f: storage.nfsSD.findDomain, 2c51d320-88ce-4f23-8215-e15f55f66906: storage.nfsSD.findDomain}
>Thread-13::INFO::2014-07-20 14:23:09,408::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '4bcc316a-d6c9-48cd-af67-bf6c06be702d'}, {'status': 0, 'id': '4d0b50e6-05c2-4751-a268-1ee5d3878415'}, {'status': 0, 'id': '4dbcef7e-48b3-4a41-9772-40d4480c074c'}, {'status': 0, 'id': 'a120f183-f080-40f8-93b0-f5301978ff3c'}, {'status': 0, 'id': 'ff550c17-a171-4a46-93b5-3ae4c8600f60'}]}
>Thread-13::DEBUG::2014-07-20 14:23:09,409::task::1185::TaskManager.Task::(prepare) Task=`2562d514-f535-4d0d-8c6f-f61effc5aff2`::finished: {'statuslist': [{'status': 0, 'id': '4bcc316a-d6c9-48cd-af67-bf6c06be702d'}, {'status': 0, 'id': '4d0b50e6-05c2-4751-a268-1ee5d3878415'}, {'status': 0, 'id': '4dbcef7e-48b3-4a41-9772-40d4480c074c'}, {'status': 0, 'id': 'a120f183-f080-40f8-93b0-f5301978ff3c'}, {'status': 0, 'id': 'ff550c17-a171-4a46-93b5-3ae4c8600f60'}]}
>Thread-13::DEBUG::2014-07-20 14:23:09,409::task::595::TaskManager.Task::(_updateState) Task=`2562d514-f535-4d0d-8c6f-f61effc5aff2`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:09,409::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:09,409::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:09,410::task::990::TaskManager.Task::(_decref) Task=`2562d514-f535-4d0d-8c6f-f61effc5aff2`::ref 0 aborting False
>Thread-13::DEBUG::2014-07-20 14:23:09,490::BindingXMLRPC::251::vds::(wrapper) client [192.168.11.2]
>Thread-13::DEBUG::2014-07-20 14:23:09,490::task::595::TaskManager.Task::(_updateState) Task=`cfc452d3-9f77-45e6-b930-c6a0542f0f65`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:09,491::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', hostID=6, msdUUID='2c51d320-88ce-4f23-8215-e15f55f66906', masterVersion=3, domainsMap=None, options=None)
>Thread-13::DEBUG::2014-07-20 14:23:09,491::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`c518ec60-6e14-4230-9466-312dbc0a7068`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1018' at 'connectStoragePool'
>Thread-13::DEBUG::2014-07-20 14:23:09,491::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-13::DEBUG::2014-07-20 14:23:09,492::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-13::DEBUG::2014-07-20 14:23:09,492::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`c518ec60-6e14-4230-9466-312dbc0a7068`::Granted request
>Thread-13::DEBUG::2014-07-20 14:23:09,493::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95`ReqID=`c4295944-618b-41f3-a84b-6559b1d3578b`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1066' at '_connectStoragePool'
>Thread-13::DEBUG::2014-07-20 14:23:09,493::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95' for lock type 'exclusive'
>Thread-13::DEBUG::2014-07-20 14:23:09,493::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95' is free. Now locking as 'exclusive' (1 active user)
>Thread-13::DEBUG::2014-07-20 14:23:09,494::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95`ReqID=`c4295944-618b-41f3-a84b-6559b1d3578b`::Granted request
>Thread-13::INFO::2014-07-20 14:23:09,494::sp::133::Storage.StoragePool::(setBackend) updating pool 94ed7a19-fade-4bd6-83f2-2cbb2f730b95 backend from type NoneType instance 0x317ed8ff00 to type StoragePoolDiskBackend instance 0x7f1060101f38
>Thread-13::INFO::2014-07-20 14:23:09,494::sp::623::Storage.StoragePool::(connect) Connect host #6 to the storage pool 94ed7a19-fade-4bd6-83f2-2cbb2f730b95 with master domain: 2c51d320-88ce-4f23-8215-e15f55f66906 (ver = 3)
>Thread-13::DEBUG::2014-07-20 14:23:09,495::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,495::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,495::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,495::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,496::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,496::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,496::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-13::DEBUG::2014-07-20 14:23:09,496::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-13::DEBUG::2014-07-20 14:23:09,496::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-13::DEBUG::2014-07-20 14:23:09,497::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-13::DEBUG::2014-07-20 14:23:09,497::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-13::DEBUG::2014-07-20 14:23:09,497::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,514::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-13::DEBUG::2014-07-20 14:23:09,514::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:09,572::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:09,572::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,572::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,573::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,573::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,573::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,573::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-07-20 14:23:09,574::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-13::DEBUG::2014-07-20 14:23:09,756::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-13::DEBUG::2014-07-20 14:23:09,907::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-13::DEBUG::2014-07-20 14:23:09,914::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas03_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=3', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=9', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtIB', 'ROLE=Master', 'SDUUID=2c51d320-88ce-4f23-8215-e15f55f66906', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5e7f2c6795a9078697f2fa918bfc2570287142fa']
>Thread-13::DEBUG::2014-07-20 14:23:09,916::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-13::DEBUG::2014-07-20 14:23:09,917::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '2c51d320-88ce-4f23-8215-e15f55f66906_imageNS'
>Thread-13::DEBUG::2014-07-20 14:23:09,917::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '2c51d320-88ce-4f23-8215-e15f55f66906_volumeNS'
>Thread-13::DEBUG::2014-07-20 14:23:09,918::sp::1375::Storage.StoragePool::(setMasterDomain) Master domain 2c51d320-88ce-4f23-8215-e15f55f66906 verified, version 3
>Thread-13::DEBUG::2014-07-20 14:23:09,918::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-13::DEBUG::2014-07-20 14:23:09,918::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-13::DEBUG::2014-07-20 14:23:09,920::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas03_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=3', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=9', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtIB', 'ROLE=Master', 'SDUUID=2c51d320-88ce-4f23-8215-e15f55f66906', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5e7f2c6795a9078697f2fa918bfc2570287142fa']
>Thread-13::INFO::2014-07-20 14:23:09,921::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-19::DEBUG::2014-07-20 14:23:09,921::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-13::DEBUG::2014-07-20 14:23:09,921::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `94ed7a19-fade-4bd6-83f2-2cbb2f730b95` started monitoring domain `2c51d320-88ce-4f23-8215-e15f55f66906`
>Thread-13::INFO::2014-07-20 14:23:09,923::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545
>Thread-13::DEBUG::2014-07-20 14:23:09,924::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `94ed7a19-fade-4bd6-83f2-2cbb2f730b95` started monitoring domain `965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`
>Thread-20::DEBUG::2014-07-20 14:23:09,924::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545
>Thread-13::INFO::2014-07-20 14:23:09,926::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring bff3a2be-fdd9-4e37-b416-fa4ef7fafba2
>Thread-13::DEBUG::2014-07-20 14:23:09,930::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `94ed7a19-fade-4bd6-83f2-2cbb2f730b95` started monitoring domain `bff3a2be-fdd9-4e37-b416-fa4ef7fafba2`
>Thread-21::DEBUG::2014-07-20 14:23:09,930::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for bff3a2be-fdd9-4e37-b416-fa4ef7fafba2
>Thread-13::INFO::2014-07-20 14:23:09,934::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 63041fa9-e093-4b44-b36f-f39f16d3974f
>Thread-13::DEBUG::2014-07-20 14:23:09,952::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `94ed7a19-fade-4bd6-83f2-2cbb2f730b95` started monitoring domain `63041fa9-e093-4b44-b36f-f39f16d3974f`
>Thread-27::DEBUG::2014-07-20 14:23:09,953::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 63041fa9-e093-4b44-b36f-f39f16d3974f
>Thread-13::INFO::2014-07-20 14:23:09,962::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 272ec473-6041-42ee-bd1a-732789dd18d4
>Thread-13::DEBUG::2014-07-20 14:23:09,981::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `94ed7a19-fade-4bd6-83f2-2cbb2f730b95` started monitoring domain `272ec473-6041-42ee-bd1a-732789dd18d4`
>Thread-33::DEBUG::2014-07-20 14:23:09,981::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 272ec473-6041-42ee-bd1a-732789dd18d4
>Thread-13::DEBUG::2014-07-20 14:23:09,994::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-13::DEBUG::2014-07-20 14:23:10,110::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas03_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=3', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=9', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtIB', 'ROLE=Master', 'SDUUID=2c51d320-88ce-4f23-8215-e15f55f66906', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5e7f2c6795a9078697f2fa918bfc2570287142fa']
>Thread-13::DEBUG::2014-07-20 14:23:10,136::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-19::DEBUG::2014-07-20 14:23:10,168::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:10,183::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545
>Thread-21::DEBUG::2014-07-20 14:23:10,213::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2
>Thread-19::DEBUG::2014-07-20 14:23:10,216::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000146619 s, 4.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:10,218::lvm::296::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  use_lvmetad=0 }  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 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 bff3a2be-fdd9-4e37-b416-fa4ef7fafba2 63041fa9-e093-4b44-b36f-f39f16d3974f 272ec473-6041-42ee-bd1a-732789dd18d4' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:10,256::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f
>Thread-33::DEBUG::2014-07-20 14:23:10,279::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4
>Thread-13::DEBUG::2014-07-20 14:23:10,279::lvm::296::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n  Volume group "965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545" not found\n  Skipping volume group 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545\n  Volume group "bff3a2be-fdd9-4e37-b416-fa4ef7fafba2" not found\n  Skipping volume group bff3a2be-fdd9-4e37-b416-fa4ef7fafba2\n  Volume group "63041fa9-e093-4b44-b36f-f39f16d3974f" not found\n  Skipping volume group 63041fa9-e093-4b44-b36f-f39f16d3974f\n  Volume group "272ec473-6041-42ee-bd1a-732789dd18d4" not found\n  Skipping volume group 272ec473-6041-42ee-bd1a-732789dd18d4\n'; <rc> = 5
>Thread-19::DEBUG::2014-07-20 14:23:10,282::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 2c51d320-88ce-4f23-8215-e15f55f66906 changed its status to Valid
>Thread-13::WARNING::2014-07-20 14:23:10,284::lvm::378::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!', '  Volume group "965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545" not found', '  Skipping volume group 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', '  Volume group "bff3a2be-fdd9-4e37-b416-fa4ef7fafba2" not found', '  Skipping volume group bff3a2be-fdd9-4e37-b416-fa4ef7fafba2', '  Volume group "63041fa9-e093-4b44-b36f-f39f16d3974f" not found', '  Skipping volume group 63041fa9-e093-4b44-b36f-f39f16d3974f', '  Volume group "272ec473-6041-42ee-bd1a-732789dd18d4" not found', '  Skipping volume group 272ec473-6041-42ee-bd1a-732789dd18d4']
>Thread-44::DEBUG::2014-07-20 14:23:10,293::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-19::INFO::2014-07-20 14:23:10,293::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 2c51d320-88ce-4f23-8215-e15f55f66906 (id: 6)
>Thread-44::DEBUG::2014-07-20 14:23:10,298::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-13::DEBUG::2014-07-20 14:23:10,298::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-19::DEBUG::2014-07-20 14:23:10,299::clusterlock::202::SANLock::(acquireHostId) Host id for domain 2c51d320-88ce-4f23-8215-e15f55f66906 successfully acquired (id: 6)
>Thread-44::DEBUG::2014-07-20 14:23:10,303::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-44::DEBUG::2014-07-20 14:23:10,307::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-46::INFO::2014-07-20 14:23:10,312::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-13::INFO::2014-07-20 14:23:10,331::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545
>Thread-13::INFO::2014-07-20 14:23:10,333::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2 to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2
>Thread-13::INFO::2014-07-20 14:23:10,335::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/63041fa9-e093-4b44-b36f-f39f16d3974f
>Thread-13::INFO::2014-07-20 14:23:10,336::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4 to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/272ec473-6041-42ee-bd1a-732789dd18d4
>Thread-13::INFO::2014-07-20 14:23:10,338::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906 to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-13::INFO::2014-07-20 14:23:10,339::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906 to /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/mastersd
>Thread-13::DEBUG::2014-07-20 14:23:10,341::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 5.0, waitTimeout: 3, maxTasks: 500.0
>Thread-13::DEBUG::2014-07-20 14:23:10,348::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/usr/bin/dd if=/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/mastersd/dom_md/outbox iflag=direct,fullblock bs=512 count=8 skip=48' (cwd None)
>Thread-13::DEBUG::2014-07-20 14:23:10,358::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.00127296 s, 3.2 MB/s\n'; <rc> = 0
>Thread-13::INFO::2014-07-20 14:23:10,359::storage_mailbox::385::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/usr/bin/dd', 'of=/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=512', 'seek=48']
>Thread-13::DEBUG::2014-07-20 14:23:10,361::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/usr/bin/dd of=/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=512 seek=48' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:10,369::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-20::DEBUG::2014-07-20 14:23:10,377::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas01_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,272ec473-6041-42ee-bd1a-732789dd18d4:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=5', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.251:/var/nas1/OVirtIB', 'ROLE=Regular', 'SDUUID=965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=33104b1d06083e25e9500f69ce80b4a66b51257c']
>Thread-20::DEBUG::2014-07-20 14:23:10,386::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-20::DEBUG::2014-07-20 14:23:10,387::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545_imageNS'
>Thread-20::DEBUG::2014-07-20 14:23:10,389::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545_volumeNS'
>Thread-21::DEBUG::2014-07-20 14:23:10,397::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-21::DEBUG::2014-07-20 14:23:10,409::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=colnas03_ISO', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtISO', 'ROLE=Regular', 'SDUUID=bff3a2be-fdd9-4e37-b416-fa4ef7fafba2', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=c50201e21217b2f429ff30bead20d9af06fab3f0']
>Thread-21::DEBUG::2014-07-20 14:23:10,422::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-21::DEBUG::2014-07-20 14:23:10,425::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2_imageNS'
>Thread-27::DEBUG::2014-07-20 14:23:10,427::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-21::DEBUG::2014-07-20 14:23:10,431::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2_volumeNS'
>Thread-27::DEBUG::2014-07-20 14:23:10,440::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Backup', 'DESCRIPTION=colnas03_EXPORT', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtEXP', 'ROLE=Regular', 'SDUUID=63041fa9-e093-4b44-b36f-f39f16d3974f', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=05042021c79752349f1701a69f9049b70f993176']
>Thread-20::DEBUG::2014-07-20 14:23:10,440::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-07-20 14:23:10,455::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-20::DEBUG::2014-07-20 14:23:10,465::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000186591 s, 3.0 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-07-20 14:23:10,470::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-27::DEBUG::2014-07-20 14:23:10,475::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '63041fa9-e093-4b44-b36f-f39f16d3974f_imageNS'
>Thread-33::DEBUG::2014-07-20 14:23:10,477::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas02_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,272ec473-6041-42ee-bd1a-732789dd18d4:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=5', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.252:/var/nas2/OVirtIB', 'ROLE=Regular', 'SDUUID=272ec473-6041-42ee-bd1a-732789dd18d4', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=101ee262507ad44a448dbc39eebf0320e49150e4']
>Thread-27::DEBUG::2014-07-20 14:23:10,483::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '63041fa9-e093-4b44-b36f-f39f16d3974f_volumeNS'
>Thread-20::DEBUG::2014-07-20 14:23:10,486::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 changed its status to Valid
>Thread-57::DEBUG::2014-07-20 14:23:10,492::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-20::INFO::2014-07-20 14:23:10,493::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (id: 6)
>Thread-57::DEBUG::2014-07-20 14:23:10,498::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-20::DEBUG::2014-07-20 14:23:10,500::clusterlock::202::SANLock::(acquireHostId) Host id for domain 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 successfully acquired (id: 6)
>Thread-33::DEBUG::2014-07-20 14:23:10,502::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-57::DEBUG::2014-07-20 14:23:10,509::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-33::DEBUG::2014-07-20 14:23:10,512::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '272ec473-6041-42ee-bd1a-732789dd18d4_imageNS'
>Thread-57::DEBUG::2014-07-20 14:23:10,519::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-59::INFO::2014-07-20 14:23:10,521::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-33::DEBUG::2014-07-20 14:23:10,524::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '272ec473-6041-42ee-bd1a-732789dd18d4_volumeNS'
>Thread-21::DEBUG::2014-07-20 14:23:10,549::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-07-20 14:23:10,568::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000136486 s, 2.6 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-20 14:23:10,583::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain bff3a2be-fdd9-4e37-b416-fa4ef7fafba2 changed its status to Valid
>Thread-60::DEBUG::2014-07-20 14:23:10,588::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-60::DEBUG::2014-07-20 14:23:10,591::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-60::DEBUG::2014-07-20 14:23:10,597::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-60::DEBUG::2014-07-20 14:23:10,603::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-62::INFO::2014-07-20 14:23:10,604::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-27::DEBUG::2014-07-20 14:23:10,604::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:10,619::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000142409 s, 2.5 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-07-20 14:23:10,624::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:10,630::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 63041fa9-e093-4b44-b36f-f39f16d3974f changed its status to Valid
>Thread-63::DEBUG::2014-07-20 14:23:10,633::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-63::DEBUG::2014-07-20 14:23:10,635::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-33::DEBUG::2014-07-20 14:23:10,636::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000137625 s, 4.0 MB/s\n'; <rc> = 0
>Thread-63::DEBUG::2014-07-20 14:23:10,639::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-63::DEBUG::2014-07-20 14:23:10,642::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-65::INFO::2014-07-20 14:23:10,643::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-33::DEBUG::2014-07-20 14:23:10,648::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 272ec473-6041-42ee-bd1a-732789dd18d4 changed its status to Valid
>Thread-33::INFO::2014-07-20 14:23:10,650::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 272ec473-6041-42ee-bd1a-732789dd18d4 (id: 6)
>Thread-66::DEBUG::2014-07-20 14:23:10,650::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-33::DEBUG::2014-07-20 14:23:10,652::clusterlock::202::SANLock::(acquireHostId) Host id for domain 272ec473-6041-42ee-bd1a-732789dd18d4 successfully acquired (id: 6)
>Thread-66::DEBUG::2014-07-20 14:23:10,653::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-66::DEBUG::2014-07-20 14:23:10,656::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-66::DEBUG::2014-07-20 14:23:10,658::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-68::INFO::2014-07-20 14:23:10,660::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-13::DEBUG::2014-07-20 14:23:11,372::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 1.00473 s, 4.1 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:11,372::storage_mailbox::207::Storage.Mailbox.HSM::(__init__) HSM_MailboxMonitor created for pool 94ed7a19-fade-4bd6-83f2-2cbb2f730b95
>Thread-13::DEBUG::2014-07-20 14:23:11,373::sp::465::Storage.StoragePool::(__createMailboxMonitor) HSM mailbox ready for pool 94ed7a19-fade-4bd6-83f2-2cbb2f730b95 on master domain 2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-13::DEBUG::2014-07-20 14:23:11,373::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95'
>Thread-13::DEBUG::2014-07-20 14:23:11,373::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95' (0 active users)
>Thread-13::DEBUG::2014-07-20 14:23:11,373::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95' is free, finding out if anyone is waiting for it.
>Thread-13::DEBUG::2014-07-20 14:23:11,374::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.94ed7a19-fade-4bd6-83f2-2cbb2f730b95', Clearing records.
>Thread-13::DEBUG::2014-07-20 14:23:11,374::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-13::DEBUG::2014-07-20 14:23:11,374::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-13::DEBUG::2014-07-20 14:23:11,374::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-13::DEBUG::2014-07-20 14:23:11,375::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-13::INFO::2014-07-20 14:23:11,375::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>Thread-13::DEBUG::2014-07-20 14:23:11,375::task::1185::TaskManager.Task::(prepare) Task=`cfc452d3-9f77-45e6-b930-c6a0542f0f65`::finished: True
>Thread-13::DEBUG::2014-07-20 14:23:11,375::task::595::TaskManager.Task::(_updateState) Task=`cfc452d3-9f77-45e6-b930-c6a0542f0f65`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:11,375::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:11,376::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:11,376::task::990::TaskManager.Task::(_decref) Task=`cfc452d3-9f77-45e6-b930-c6a0542f0f65`::ref 0 aborting False
>Thread-13::DEBUG::2014-07-20 14:23:11,384::task::595::TaskManager.Task::(_updateState) Task=`983e86c1-c92c-4c2f-8f36-3c682e304c80`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:11,384::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-07-20 14:23:11,385::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000146619', 'lastCheck': '1.1', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000186591', 'lastCheck': '0.9', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000136486', 'lastCheck': '0.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000142409', 'lastCheck': '0.8', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000137625', 'lastCheck': '0.7', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:11,385::task::1185::TaskManager.Task::(prepare) Task=`983e86c1-c92c-4c2f-8f36-3c682e304c80`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000146619', 'lastCheck': '1.1', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000186591', 'lastCheck': '0.9', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000136486', 'lastCheck': '0.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000142409', 'lastCheck': '0.8', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000137625', 'lastCheck': '0.7', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:11,385::task::595::TaskManager.Task::(_updateState) Task=`983e86c1-c92c-4c2f-8f36-3c682e304c80`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:11,385::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:11,386::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:11,386::task::990::TaskManager.Task::(_decref) Task=`983e86c1-c92c-4c2f-8f36-3c682e304c80`::ref 0 aborting False
>Thread-13::DEBUG::2014-07-20 14:23:12,074::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call setMOMPolicyParameters with ({'balloonEnabled': False, 'ksmEnabled': True},) {} flowID [3e757378]
>Thread-13::DEBUG::2014-07-20 14:23:12,125::BindingXMLRPC::1074::vds::(wrapper) return setMOMPolicyParameters with {'status': {'message': 'Done', 'code': 0}}
>Thread-19::DEBUG::2014-07-20 14:23:20,327::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-07-20 14:23:20,334::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000200145 s, 3.2 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-07-20 14:23:20,512::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:20,517::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000186575 s, 3.0 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-20 14:23:20,593::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-07-20 14:23:20,598::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000183127 s, 1.9 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-07-20 14:23:20,637::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:20,642::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000239033 s, 1.5 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-07-20 14:23:20,659::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-07-20 14:23:20,664::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000217198 s, 2.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:24,499::task::595::TaskManager.Task::(_updateState) Task=`d8aafb27-2517-4de1-996d-2b3bde6aa208`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:24,500::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-07-20 14:23:24,500::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000200145', 'lastCheck': '4.2', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000186575', 'lastCheck': '4.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000183127', 'lastCheck': '3.9', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000239033', 'lastCheck': '3.9', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000217198', 'lastCheck': '3.8', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:24,500::task::1185::TaskManager.Task::(prepare) Task=`d8aafb27-2517-4de1-996d-2b3bde6aa208`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000200145', 'lastCheck': '4.2', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000186575', 'lastCheck': '4.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000183127', 'lastCheck': '3.9', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000239033', 'lastCheck': '3.9', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000217198', 'lastCheck': '3.8', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:24,500::task::595::TaskManager.Task::(_updateState) Task=`d8aafb27-2517-4de1-996d-2b3bde6aa208`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:24,501::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:24,501::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:24,501::task::990::TaskManager.Task::(_decref) Task=`d8aafb27-2517-4de1-996d-2b3bde6aa208`::ref 0 aborting False
>Thread-19::DEBUG::2014-07-20 14:23:30,348::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-07-20 14:23:30,354::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000191778 s, 3.4 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-07-20 14:23:30,524::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:30,529::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000226461 s, 2.5 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-20 14:23:30,604::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-07-20 14:23:30,608::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000200802 s, 1.8 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-07-20 14:23:30,648::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:30,652::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000163784 s, 2.2 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-07-20 14:23:30,670::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-07-20 14:23:30,675::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000207545 s, 2.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:39,918::task::595::TaskManager.Task::(_updateState) Task=`d0c135e7-1be5-4dae-b94c-1d8d8a42726f`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:39,919::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-07-20 14:23:39,919::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000191778', 'lastCheck': '9.6', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000226461', 'lastCheck': '9.4', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000200802', 'lastCheck': '9.3', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000163784', 'lastCheck': '9.3', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000207545', 'lastCheck': '9.2', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:39,919::task::1185::TaskManager.Task::(prepare) Task=`d0c135e7-1be5-4dae-b94c-1d8d8a42726f`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000191778', 'lastCheck': '9.6', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000226461', 'lastCheck': '9.4', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000200802', 'lastCheck': '9.3', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000163784', 'lastCheck': '9.3', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000207545', 'lastCheck': '9.2', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:39,919::task::595::TaskManager.Task::(_updateState) Task=`d0c135e7-1be5-4dae-b94c-1d8d8a42726f`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:39,920::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:39,920::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:39,920::task::990::TaskManager.Task::(_decref) Task=`d0c135e7-1be5-4dae-b94c-1d8d8a42726f`::ref 0 aborting False
>Thread-19::DEBUG::2014-07-20 14:23:40,363::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-07-20 14:23:40,369::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000188218 s, 3.4 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-07-20 14:23:40,535::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:40,540::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000215105 s, 2.6 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-20 14:23:40,614::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-07-20 14:23:40,619::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000239968 s, 1.5 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-07-20 14:23:40,659::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:40,663::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000218832 s, 1.7 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-07-20 14:23:40,682::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-07-20 14:23:40,686::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00027825 s, 2.0 MB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-07-20 14:23:50,378::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-07-20 14:23:50,384::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000226545 s, 2.8 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-07-20 14:23:50,546::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-07-20 14:23:50,552::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000178493 s, 3.1 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-20 14:23:50,625::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-07-20 14:23:50,630::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000197167 s, 1.8 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-07-20 14:23:50,669::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-07-20 14:23:50,673::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000186633 s, 1.9 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-07-20 14:23:50,693::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-07-20 14:23:50,697::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000182019 s, 3.1 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-07-20 14:23:56,408::task::595::TaskManager.Task::(_updateState) Task=`bb55952e-99ba-4605-bd4f-9fee1cfa9668`::moving from state init -> state preparing
>Thread-13::INFO::2014-07-20 14:23:56,408::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-07-20 14:23:56,409::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000226545', 'lastCheck': '6.0', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000178493', 'lastCheck': '5.9', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000197167', 'lastCheck': '5.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000186633', 'lastCheck': '5.7', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000182019', 'lastCheck': '5.7', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:56,409::task::1185::TaskManager.Task::(prepare) Task=`bb55952e-99ba-4605-bd4f-9fee1cfa9668`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000226545', 'lastCheck': '6.0', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000178493', 'lastCheck': '5.9', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000197167', 'lastCheck': '5.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000186633', 'lastCheck': '5.7', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000182019', 'lastCheck': '5.7', 'valid': True}}
>Thread-13::DEBUG::2014-07-20 14:23:56,409::task::595::TaskManager.Task::(_updateState) Task=`bb55952e-99ba-4605-bd4f-9fee1cfa9668`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-07-20 14:23:56,409::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-07-20 14:23:56,409::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-07-20 14:23:56,410::task::990::TaskManager.Task::(_decref) Task=`bb55952e-99ba-4605-bd4f-9fee1cfa9668`::ref 0 aborting False

Actions: View

Attachments on bug 1120823: 918799 | 919387 | 919388 | 920192 | 920193