MainThread::INFO::2013-10-11 15:19:10,294::vdsm::101::vds::(run) (PID: 6840) I am the actual vdsm 4.13.0-10.el6 lostisles.gso.med.ge.com (2.6.39-400.209.1.el6uek.x86_64)
MainThread::DEBUG::2013-10-11 15:19:10,505::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2013-10-11 15:19:10,505::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2013-10-11 15:19:10,509::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2013-10-11 15:19:10,866::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2013-10-11 15:19:10,874::multipath::144::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2013-10-11 15:19:10,875::hsm::420::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2013-10-11 15:19:10,886::hsm::420::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2013-10-11 15:19:10,887::hsm::444::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2013-10-11 15:19:10,888::hsm::476::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2013-10-11 15:19:10,888::hsm::477::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/192.168.0.1:_das0_iso', '/rhev/data-center/mnt/192.168.0.1:_das0_stormwind', '/rhev/data-center/mnt/192.168.0.1:_das0_export', '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar']
MainThread::DEBUG::2013-10-11 15:19:10,888::hsm::479::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2013-10-11 15:19:10,891::hsm::522::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2013-10-11 15:19:10,891::lvm::337::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
MainThread::INFO::2013-10-11 15:19:10,892::dispatcher::98::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
MainThread::DEBUG::2013-10-11 15:19:10,893::task::579::TaskManager.Task::(_updateState) Task=`66c6e75f-fbd5-4a8f-9da4-c22214d4d72e`::moving from state init -> state preparing
MainThread::INFO::2013-10-11 15:19:10,894::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x7f147defb0e0>>)
storageRefresh::DEBUG::2013-10-11 15:19:10,894::lvm::308::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 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::2013-10-11 15:19:10,894::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2013-10-11 15:19:10,897::task::1168::TaskManager.Task::(prepare) Task=`66c6e75f-fbd5-4a8f-9da4-c22214d4d72e`::finished: None
MainThread::DEBUG::2013-10-11 15:19:10,898::task::579::TaskManager.Task::(_updateState) Task=`66c6e75f-fbd5-4a8f-9da4-c22214d4d72e`::moving from state preparing -> state finished
MainThread::DEBUG::2013-10-11 15:19:10,898::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2013-10-11 15:19:10,898::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2013-10-11 15:19:10,898::task::974::TaskManager.Task::(_decref) Task=`66c6e75f-fbd5-4a8f-9da4-c22214d4d72e`::ref 0 aborting False
MainThread::ERROR::2013-10-11 15:19:10,905::netinfo::302::root::(speed) cannot read ib0 speed
Traceback (most recent call last):
  File "/usr/lib64/python2.6/site-packages/vdsm/netinfo.py", line 298, in speed
    s = int(speedFile.read())
IOError: [Errno 22] Invalid argument
MainThread::INFO::2013-10-11 15:19:10,911::momIF::47::MOM::(__init__) Starting up MOM
storageRefresh::DEBUG::2013-10-11 15:19:10,911::lvm::308::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2013-10-11 15:19:10,912::lvm::362::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:10,913::lvm::385::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:10,914::lvm::308::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 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::INFO::2013-10-11 15:19:10,925::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
clientIFinit::DEBUG::2013-10-11 15:19:10,925::libvirtconnection::131::libvirtconnection::(get) trying to connect libvirt
VM Channels Listener::INFO::2013-10-11 15:19:10,931::vmChannels::170::vds::(run) Starting VM channels listener thread.
MainThread::WARNING::2013-10-11 15:19:10,932::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
storageRefresh::DEBUG::2013-10-11 15:19:10,937::lvm::308::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2013-10-11 15:19:10,938::lvm::427::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:10,938::lvm::308::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 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::2013-10-11 15:19:10,970::lvm::308::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2013-10-11 15:19:10,974::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
storageRefresh::DEBUG::2013-10-11 15:19:10,978::misc::811::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2013-10-11 15:19:10,981::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2013-10-11 15:19:10,985::misc::811::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2013-10-11 15:19:10,990::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2013-10-11 15:19:11,015::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
storageRefresh::DEBUG::2013-10-11 15:19:11,018::misc::819::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2013-10-11 15:19:14,042::multipath::112::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
storageRefresh::DEBUG::2013-10-11 15:19:14,092::multipath::112::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2013-10-11 15:19:14,093::lvm::509::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,093::lvm::511::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,093::lvm::520::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,093::lvm::522::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,094::lvm::540::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,094::lvm::542::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2013-10-11 15:19:14,094::misc::819::SamplingMethod::(__call__) Returning last result
storageRefresh::WARNING::2013-10-11 15:19:14,094::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
Thread-13::DEBUG::2013-10-11 15:19:21,720::task::579::TaskManager.Task::(_updateState) Task=`075290fa-a617-40f2-b9b7-f1a319c95a8a`::moving from state init -> state preparing
Thread-13::INFO::2013-10-11 15:19:21,720::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-13::INFO::2013-10-11 15:19:21,720::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-13::DEBUG::2013-10-11 15:19:21,720::task::1168::TaskManager.Task::(prepare) Task=`075290fa-a617-40f2-b9b7-f1a319c95a8a`::finished: {}
Thread-13::DEBUG::2013-10-11 15:19:21,720::task::579::TaskManager.Task::(_updateState) Task=`075290fa-a617-40f2-b9b7-f1a319c95a8a`::moving from state preparing -> state finished
Thread-13::DEBUG::2013-10-11 15:19:21,721::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-13::DEBUG::2013-10-11 15:19:21,721::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-13::DEBUG::2013-10-11 15:19:21,721::task::974::TaskManager.Task::(_decref) Task=`075290fa-a617-40f2-b9b7-f1a319c95a8a`::ref 0 aborting False
Thread-14::DEBUG::2013-10-11 15:19:21,876::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getCapabilities with () {}
Thread-14::DEBUG::2013-10-11 15:19:21,956::utils::489::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-14::DEBUG::2013-10-11 15:19:21,961::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-14::ERROR::2013-10-11 15:19:22,003::netinfo::302::root::(speed) cannot read ib0 speed
Traceback (most recent call last):
  File "/usr/lib64/python2.6/site-packages/vdsm/netinfo.py", line 298, in speed
    s = int(speedFile.read())
IOError: [Errno 22] Invalid argument
Thread-14::DEBUG::2013-10-11 15:19:22,034::caps::347::root::(_getKeyPackages) rpm package glusterfs-rdma not found
Thread-14::DEBUG::2013-10-11 15:19:22,034::caps::347::root::(_getKeyPackages) rpm package glusterfs-fuse not found
Thread-14::DEBUG::2013-10-11 15:19:22,035::caps::347::root::(_getKeyPackages) rpm package gluster-swift not found
Thread-14::DEBUG::2013-10-11 15:19:22,039::caps::347::root::(_getKeyPackages) rpm package gluster-swift-object not found
Thread-14::DEBUG::2013-10-11 15:19:22,039::caps::347::root::(_getKeyPackages) rpm package glusterfs not found
Thread-14::DEBUG::2013-10-11 15:19:22,039::caps::347::root::(_getKeyPackages) rpm package gluster-swift-plugin not found
Thread-14::DEBUG::2013-10-11 15:19:22,044::caps::347::root::(_getKeyPackages) rpm package gluster-swift-account not found
Thread-14::DEBUG::2013-10-11 15:19:22,044::caps::347::root::(_getKeyPackages) rpm package gluster-swift-proxy not found
Thread-14::DEBUG::2013-10-11 15:19:22,045::caps::347::root::(_getKeyPackages) rpm package gluster-swift-doc not found
Thread-14::DEBUG::2013-10-11 15:19:22,045::caps::347::root::(_getKeyPackages) rpm package glusterfs-server not found
Thread-14::DEBUG::2013-10-11 15:19:22,045::caps::347::root::(_getKeyPackages) rpm package gluster-swift-container not found
Thread-14::DEBUG::2013-10-11 15:19:22,045::caps::347::root::(_getKeyPackages) rpm package glusterfs-geo-replication not found
Thread-14::DEBUG::2013-10-11 15:19:22,057::BindingXMLRPC::981::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.2013-07.net.azerothptr:lostisles'}], 'FC': []}, 'packages2': {'kernel': {'release': '400.209.1.el6uek.x86_64', 'buildtime': 1378863579.0, 'version': '2.6.39'}, 'spice-server': {'release': '12.el6_4.3', 'buildtime': 1378241404L, 'version': '0.12.0'}, 'vdsm': {'release': '10.el6', 'buildtime': 1381512173L, 'version': '4.13.0'}, 'qemu-kvm': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'libvirt': {'release': '18.0.1.el6_4.14', 'buildtime': 1379619458L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'mom': {'release': '13.el6', 'buildtime': 1379693580L, 'version': '0.3.2'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5540  @ 2.53GHz', 'hooks': {'after_vm_start': {'50_promisc': {'md5': '5ea469fa06dd7cd1e52508672a7519db'}}, 'before_vm_migrate_source': {'50_floppy': {'md5': 'c68fb91d44105c8b6f2d80566314027a'}, '50_hostusb': {'md5': 'e50a0975acd8bafd0052b65a787c2fdd'}, '50_scratchpad': {'md5': 'be90995f959c60c5110c6a0bef67c7b8'}, '50_sriov': {'md5': '47a59103b7c8b1439ae17dcd5ed197cd'}}, 'before_vm_destroy': {'50_promisc': {'md5': 'dae0434ea8ca2492422a6fde5cc47a1e'}}, 'before_vm_start': {'50_sriov': {'md5': '3ebc60cd2e4eb089820102285fad7c45'}, '50_vmfex': {'md5': '9f5abb892ddb6b3daa779985d38d9f55'}, '50_vmdisk': {'md5': 'b06259a563c750cf46c1d2a7c4ef739b'}, '50_scratchpad': {'md5': '7db25a4b8cb04f6e7132cb7c2300c111'}, '50_numa': {'md5': '5008c2826714ac5b63748780aabd2f25'}, '50_floppy': {'md5': '202fe18705a7d4c50c40c126e8f8dbe8'}, '50_qemucmdline': {'md5': 'a884929ad6f5eb039887157288867409'}, '50_pincpu': {'md5': '0b5fb99ff0e7acb9ad534b87c02c59e3'}, '50_macspoof': {'md5': '25deea559772719b90117f2e1009d823'}, '50_fileinject': {'md5': '290dafd45601e010e0f496fa5b889a76'}, '60_checkimages': {'md5': 'abd32c723a90ab2816e2163f5e02faf7'}, '50_usbtablet': {'md5': '392a12fb67be02d43d83855e585b6f9d'}, '50_directlun': {'md5': '5380575c0e80dc9907ab874393ad30a0'}, '50_hugepages': {'md5': '6713d703f9d316f1664145b700cd7904'}, '50_smbios': {'md5': '1a6bd8eddc3a86943e558bc4d3e73bd6'}, '50_qos': {'md5': '18b596a6b4e4bad80357f240ba122a5e'}, '50_hostusb': {'md5': '21c58568f3eae4f0d091005e0eff891a'}, '50_isolatedprivatevlan': {'md5': '0a25d7cd0b807ea5e0dfc3318ee98c91'}}, 'after_device_migrate_destination': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_device_create': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_nic_hotplug': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_vm_migrate_destination': {'50_vmfex': {'md5': 'eac2633f47fb309b4a5b7fe76531baec'}, '50_hugepages': {'md5': '6ddc484746297308b9f9acc5fcabaf10'}, '50_directlun': {'md5': '8a29ce41de079630cb58d48e280d55c2'}}, 'after_vm_destroy': {'50_sriov': {'md5': '5890b2899d450495a62f3611fad3c526'}, '50_hostusb': {'md5': '0a37bf0a26546e3ab5e424b13653ce2b'}, '50_directlun': {'md5': '6d05c19e68a141eeb7ee5981d68c0cfa'}, '50_scratchpad': {'md5': '316d21a669f97e83b485b45ab0b23eee'}, '50_hugepages': {'md5': '4a980b78f8ee908bf2c61ea9bf156f4a'}}, 'before_nic_hotplug': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_device_create': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'gateway': '0.0.0.0', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond2']}, 'csebackbone': {'iface': 'csebackbone', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'gateway': '0.0.0.0', 'netmask': '', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond0']}, 'display': {'iface': u'bond1', 'addr': '3.70.204.32', 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500', 'qosInbound': '', 'netmask': '255.255.252.0', 'qosOutbound': '', 'bridged': False, 'interface': u'bond1', 'ipv6gateway': '::', 'gateway': '3.70.204.254'}}, 'bridges': {'ovirtmgmt': {'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond2']}, 'csebackbone': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond0']}}, 'uuid': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'lastClientIface': 'ovirtmgmt', 'nics': {'ib0': {'netmask': '255.255.0.0', 'addr': '192.168.1.2', 'hwaddr': '80:00:04:04:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:59', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '192.168.1.2', 'PREFIX': '16', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib0', 'TYPE': 'Infiniband', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::212:79ff:ffb5:c059/64'], 'speed': 0, 'mtu': '65520'}, 'ib1': {'netmask': '', 'addr': '', 'hwaddr': '80:00:04:05:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:5a', 'cfg': {'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib1', 'TYPE': 'Infiniband', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'speed': 0, 'mtu': '2044'}, 'eth5': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A7', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth5', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A7', 'speed': 1000, 'mtu': '1500'}, 'eth4': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A6', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth4', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A6', 'speed': 1000, 'mtu': '1500'}, 'eth3': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A1', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A1', 'speed': 1000, 'mtu': '1500'}, 'eth2': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A0', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A0', 'speed': 1000, 'mtu': '1500'}, 'eth1': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9F', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9F', 'speed': 1000, 'mtu': '1500'}, 'eth0': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9E', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9E', 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '10', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_n270', 'ISCSIInitiatorName': 'iqn.2013-07.net.azerothptr:lostisles', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3'], 'reservedMem': '321', 'bondings': {'bond4': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond0': {'netmask': '', 'addr': '', 'slaves': ['eth0', 'eth1'], 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'BRIDGE': 'csebackbone', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500'}, 'bond1': {'netmask': '255.255.252.0', 'addr': '3.70.204.32', 'slaves': ['eth2', 'eth3'], 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.32', 'PREFIX': '22', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500'}, 'bond2': {'netmask': '', 'addr': '', 'slaves': ['eth4', 'eth5'], 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'BRIDGE': 'ovirtmgmt', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64'], 'mtu': '1500'}, 'bond3': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.13', 'memSize': '36272', 'cpuSpeed': '2534.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '16', 'emulatedMachines': [u'rhel6.4.0', u'pc', u'rhel6.3.0', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '4.0.4', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '3.57.111.30'}}
Thread-15::DEBUG::2013-10-11 15:19:22,102::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getHardwareInfo with () {}
Thread-15::DEBUG::2013-10-11 15:19:22,104::BindingXMLRPC::981::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'SUN FIRE X4170 SERVER', 'systemSerialNumber': '0950XF5199', 'systemFamily': 'To Be Filled By O.E.M.', 'systemVersion': '', 'systemUUID': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'systemManufacturer': 'SUN MICROSYSTEMS'}}
Thread-21::DEBUG::2013-10-11 15:19:38,272::task::579::TaskManager.Task::(_updateState) Task=`c8a2139d-385c-49ef-aa65-edb79996c49f`::moving from state init -> state preparing
Thread-21::INFO::2013-10-11 15:19:38,272::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-21::INFO::2013-10-11 15:19:38,273::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-21::DEBUG::2013-10-11 15:19:38,273::task::1168::TaskManager.Task::(prepare) Task=`c8a2139d-385c-49ef-aa65-edb79996c49f`::finished: {}
Thread-21::DEBUG::2013-10-11 15:19:38,273::task::579::TaskManager.Task::(_updateState) Task=`c8a2139d-385c-49ef-aa65-edb79996c49f`::moving from state preparing -> state finished
Thread-21::DEBUG::2013-10-11 15:19:38,273::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-21::DEBUG::2013-10-11 15:19:38,273::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-21::DEBUG::2013-10-11 15:19:38,273::task::974::TaskManager.Task::(_decref) Task=`c8a2139d-385c-49ef-aa65-edb79996c49f`::ref 0 aborting False
Thread-27::DEBUG::2013-10-11 15:19:53,656::task::579::TaskManager.Task::(_updateState) Task=`feaee9e4-effa-4f60-ad57-b2dd1e98e1a6`::moving from state init -> state preparing
Thread-27::INFO::2013-10-11 15:19:53,656::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-27::INFO::2013-10-11 15:19:53,656::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-27::DEBUG::2013-10-11 15:19:53,657::task::1168::TaskManager.Task::(prepare) Task=`feaee9e4-effa-4f60-ad57-b2dd1e98e1a6`::finished: {}
Thread-27::DEBUG::2013-10-11 15:19:53,657::task::579::TaskManager.Task::(_updateState) Task=`feaee9e4-effa-4f60-ad57-b2dd1e98e1a6`::moving from state preparing -> state finished
Thread-27::DEBUG::2013-10-11 15:19:53,657::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-27::DEBUG::2013-10-11 15:19:53,657::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-27::DEBUG::2013-10-11 15:19:53,657::task::974::TaskManager.Task::(_decref) Task=`feaee9e4-effa-4f60-ad57-b2dd1e98e1a6`::ref 0 aborting False
Thread-33::DEBUG::2013-10-11 15:20:09,118::task::579::TaskManager.Task::(_updateState) Task=`a5704260-5b34-4906-981b-a69a6792f112`::moving from state init -> state preparing
Thread-33::INFO::2013-10-11 15:20:09,118::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-33::INFO::2013-10-11 15:20:09,118::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-33::DEBUG::2013-10-11 15:20:09,119::task::1168::TaskManager.Task::(prepare) Task=`a5704260-5b34-4906-981b-a69a6792f112`::finished: {}
Thread-33::DEBUG::2013-10-11 15:20:09,119::task::579::TaskManager.Task::(_updateState) Task=`a5704260-5b34-4906-981b-a69a6792f112`::moving from state preparing -> state finished
Thread-33::DEBUG::2013-10-11 15:20:09,119::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-33::DEBUG::2013-10-11 15:20:09,119::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-33::DEBUG::2013-10-11 15:20:09,119::task::974::TaskManager.Task::(_decref) Task=`a5704260-5b34-4906-981b-a69a6792f112`::ref 0 aborting False
Thread-39::DEBUG::2013-10-11 15:20:24,513::task::579::TaskManager.Task::(_updateState) Task=`8279e4d3-e239-422c-a534-db24ac36c6a0`::moving from state init -> state preparing
Thread-39::INFO::2013-10-11 15:20:24,514::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-39::INFO::2013-10-11 15:20:24,514::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-39::DEBUG::2013-10-11 15:20:24,514::task::1168::TaskManager.Task::(prepare) Task=`8279e4d3-e239-422c-a534-db24ac36c6a0`::finished: {}
Thread-39::DEBUG::2013-10-11 15:20:24,514::task::579::TaskManager.Task::(_updateState) Task=`8279e4d3-e239-422c-a534-db24ac36c6a0`::moving from state preparing -> state finished
Thread-39::DEBUG::2013-10-11 15:20:24,514::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-39::DEBUG::2013-10-11 15:20:24,514::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-39::DEBUG::2013-10-11 15:20:24,515::task::974::TaskManager.Task::(_decref) Task=`8279e4d3-e239-422c-a534-db24ac36c6a0`::ref 0 aborting False
Thread-45::DEBUG::2013-10-11 15:20:39,855::task::579::TaskManager.Task::(_updateState) Task=`272cc129-c70d-4c1a-a7fe-0eba02cb4d9f`::moving from state init -> state preparing
Thread-45::INFO::2013-10-11 15:20:39,856::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-45::INFO::2013-10-11 15:20:39,856::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-45::DEBUG::2013-10-11 15:20:39,856::task::1168::TaskManager.Task::(prepare) Task=`272cc129-c70d-4c1a-a7fe-0eba02cb4d9f`::finished: {}
Thread-45::DEBUG::2013-10-11 15:20:39,856::task::579::TaskManager.Task::(_updateState) Task=`272cc129-c70d-4c1a-a7fe-0eba02cb4d9f`::moving from state preparing -> state finished
Thread-45::DEBUG::2013-10-11 15:20:39,856::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-45::DEBUG::2013-10-11 15:20:39,856::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-45::DEBUG::2013-10-11 15:20:39,857::task::974::TaskManager.Task::(_decref) Task=`272cc129-c70d-4c1a-a7fe-0eba02cb4d9f`::ref 0 aborting False
Thread-51::DEBUG::2013-10-11 15:20:55,174::task::579::TaskManager.Task::(_updateState) Task=`934e2987-b302-421f-ba42-d68f97a31119`::moving from state init -> state preparing
Thread-51::INFO::2013-10-11 15:20:55,174::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-51::INFO::2013-10-11 15:20:55,175::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-51::DEBUG::2013-10-11 15:20:55,175::task::1168::TaskManager.Task::(prepare) Task=`934e2987-b302-421f-ba42-d68f97a31119`::finished: {}
Thread-51::DEBUG::2013-10-11 15:20:55,175::task::579::TaskManager.Task::(_updateState) Task=`934e2987-b302-421f-ba42-d68f97a31119`::moving from state preparing -> state finished
Thread-51::DEBUG::2013-10-11 15:20:55,175::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-51::DEBUG::2013-10-11 15:20:55,175::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-51::DEBUG::2013-10-11 15:20:55,175::task::974::TaskManager.Task::(_decref) Task=`934e2987-b302-421f-ba42-d68f97a31119`::ref 0 aborting False
Thread-57::DEBUG::2013-10-11 15:21:10,487::task::579::TaskManager.Task::(_updateState) Task=`00d2191a-1c41-4914-8524-d34e01e989e1`::moving from state init -> state preparing
Thread-57::INFO::2013-10-11 15:21:10,487::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-57::INFO::2013-10-11 15:21:10,487::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-57::DEBUG::2013-10-11 15:21:10,487::task::1168::TaskManager.Task::(prepare) Task=`00d2191a-1c41-4914-8524-d34e01e989e1`::finished: {}
Thread-57::DEBUG::2013-10-11 15:21:10,487::task::579::TaskManager.Task::(_updateState) Task=`00d2191a-1c41-4914-8524-d34e01e989e1`::moving from state preparing -> state finished
Thread-57::DEBUG::2013-10-11 15:21:10,487::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-57::DEBUG::2013-10-11 15:21:10,488::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-57::DEBUG::2013-10-11 15:21:10,488::task::974::TaskManager.Task::(_decref) Task=`00d2191a-1c41-4914-8524-d34e01e989e1`::ref 0 aborting False
Thread-63::DEBUG::2013-10-11 15:21:25,787::task::579::TaskManager.Task::(_updateState) Task=`d17947f6-9574-4e27-8c2e-240a4bbd1f23`::moving from state init -> state preparing
Thread-63::INFO::2013-10-11 15:21:25,787::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-63::INFO::2013-10-11 15:21:25,787::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-63::DEBUG::2013-10-11 15:21:25,787::task::1168::TaskManager.Task::(prepare) Task=`d17947f6-9574-4e27-8c2e-240a4bbd1f23`::finished: {}
Thread-63::DEBUG::2013-10-11 15:21:25,787::task::579::TaskManager.Task::(_updateState) Task=`d17947f6-9574-4e27-8c2e-240a4bbd1f23`::moving from state preparing -> state finished
Thread-63::DEBUG::2013-10-11 15:21:25,787::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-63::DEBUG::2013-10-11 15:21:25,788::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-63::DEBUG::2013-10-11 15:21:25,788::task::974::TaskManager.Task::(_decref) Task=`d17947f6-9574-4e27-8c2e-240a4bbd1f23`::ref 0 aborting False
Thread-69::DEBUG::2013-10-11 15:21:41,097::task::579::TaskManager.Task::(_updateState) Task=`24738b38-ac8b-40f8-9550-3710d153f086`::moving from state init -> state preparing
Thread-69::INFO::2013-10-11 15:21:41,097::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-69::INFO::2013-10-11 15:21:41,097::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-69::DEBUG::2013-10-11 15:21:41,097::task::1168::TaskManager.Task::(prepare) Task=`24738b38-ac8b-40f8-9550-3710d153f086`::finished: {}
Thread-69::DEBUG::2013-10-11 15:21:41,098::task::579::TaskManager.Task::(_updateState) Task=`24738b38-ac8b-40f8-9550-3710d153f086`::moving from state preparing -> state finished
Thread-69::DEBUG::2013-10-11 15:21:41,098::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-69::DEBUG::2013-10-11 15:21:41,098::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-69::DEBUG::2013-10-11 15:21:41,098::task::974::TaskManager.Task::(_decref) Task=`24738b38-ac8b-40f8-9550-3710d153f086`::ref 0 aborting False
Thread-75::DEBUG::2013-10-11 15:21:56,394::task::579::TaskManager.Task::(_updateState) Task=`14bb8efc-d34f-4691-b274-1f282f497587`::moving from state init -> state preparing
Thread-75::INFO::2013-10-11 15:21:56,394::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-75::INFO::2013-10-11 15:21:56,394::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-75::DEBUG::2013-10-11 15:21:56,394::task::1168::TaskManager.Task::(prepare) Task=`14bb8efc-d34f-4691-b274-1f282f497587`::finished: {}
Thread-75::DEBUG::2013-10-11 15:21:56,394::task::579::TaskManager.Task::(_updateState) Task=`14bb8efc-d34f-4691-b274-1f282f497587`::moving from state preparing -> state finished
Thread-75::DEBUG::2013-10-11 15:21:56,394::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-75::DEBUG::2013-10-11 15:21:56,395::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-75::DEBUG::2013-10-11 15:21:56,395::task::974::TaskManager.Task::(_decref) Task=`14bb8efc-d34f-4691-b274-1f282f497587`::ref 0 aborting False
Thread-81::DEBUG::2013-10-11 15:22:11,677::task::579::TaskManager.Task::(_updateState) Task=`476d7d33-0ba0-4c27-a555-84d64d888c69`::moving from state init -> state preparing
Thread-81::INFO::2013-10-11 15:22:11,678::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-81::INFO::2013-10-11 15:22:11,679::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-81::DEBUG::2013-10-11 15:22:11,680::task::1168::TaskManager.Task::(prepare) Task=`476d7d33-0ba0-4c27-a555-84d64d888c69`::finished: {}
Thread-81::DEBUG::2013-10-11 15:22:11,681::task::579::TaskManager.Task::(_updateState) Task=`476d7d33-0ba0-4c27-a555-84d64d888c69`::moving from state preparing -> state finished
Thread-81::DEBUG::2013-10-11 15:22:11,681::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-81::DEBUG::2013-10-11 15:22:11,682::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-81::DEBUG::2013-10-11 15:22:11,683::task::974::TaskManager.Task::(_decref) Task=`476d7d33-0ba0-4c27-a555-84d64d888c69`::ref 0 aborting False
Thread-87::DEBUG::2013-10-11 15:22:27,041::task::579::TaskManager.Task::(_updateState) Task=`86c0764d-2ba2-4228-a9ee-b6926598dc68`::moving from state init -> state preparing
Thread-87::INFO::2013-10-11 15:22:27,041::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-87::INFO::2013-10-11 15:22:27,041::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-87::DEBUG::2013-10-11 15:22:27,041::task::1168::TaskManager.Task::(prepare) Task=`86c0764d-2ba2-4228-a9ee-b6926598dc68`::finished: {}
Thread-87::DEBUG::2013-10-11 15:22:27,042::task::579::TaskManager.Task::(_updateState) Task=`86c0764d-2ba2-4228-a9ee-b6926598dc68`::moving from state preparing -> state finished
Thread-87::DEBUG::2013-10-11 15:22:27,042::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-87::DEBUG::2013-10-11 15:22:27,042::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-87::DEBUG::2013-10-11 15:22:27,042::task::974::TaskManager.Task::(_decref) Task=`86c0764d-2ba2-4228-a9ee-b6926598dc68`::ref 0 aborting False
Thread-92::DEBUG::2013-10-11 15:22:38,754::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.31]::call vmGetStats with ('4bad94ad-c338-4ec5-8e5b-9910d58c1854',) {}
Thread-92::DEBUG::2013-10-11 15:22:38,754::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
Thread-93::DEBUG::2013-10-11 15:22:38,846::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.31]::call vmMigrationCreate with ({'username': 'Unknown', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'afterMigrationStatus': '', 'guestFQDN': '', 'vmId': '4bad94ad-c338-4ec5-8e5b-9910d58c1854', 'memGuaranteedSize': 1024, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'timeOffset': '-2', 'cpuType': 'Nehalem', 'custom': {'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602b': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=0e83e447-9a2c-4428-854c-7ae93183602b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=7dab6ddd-54c5-413b-adaf-b6db67c7f028, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=88c83317-c5a8-4594-80e3-d8cf0ddb6037, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028device_f5bd8220-0271-4c4e-8089-5e94b09b5993': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=f5bd8220-0271-4c4e-8089-5e94b09b5993, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=92d5b02c-db78-40eb-9006-0d95314392b4, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}}'}, 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'smp': '1', 'vmType': 'kvm', '_srcDomXML': "<domain type='kvm' id='3'>\n  <name>opensuse111</name>\n  <uuid>4bad94ad-c338-4ec5-8e5b-9910d58c1854</uuid>\n  <memory unit='KiB'>1048576</memory>\n  <currentMemory unit='KiB'>1048576</currentMemory>\n  <memtune>\n    <min_guarantee unit='KiB'>1048576</min_guarantee>\n  </memtune>\n  <vcpu placement='static'>1</vcpu>\n  <cputune>\n    <shares>1020</shares>\n  </cputune>\n  <sysinfo type='smbios'>\n    <system>\n      <entry name='manufacturer'>oVirt</entry>\n      <entry name='product'>oVirt Node</entry>\n      <entry name='version'>6Server-4.0.4</entry>\n      <entry name='serial'>FF200008-FFFF-FFFF-FFFF-00212883CE4C</entry>\n      <entry name='uuid'>4bad94ad-c338-4ec5-8e5b-9910d58c1854</entry>\n    </system>\n  </sysinfo>\n  <os>\n    <type arch='x86_64' machine='rhel6.4.0'>hvm</type>\n    <smbios mode='sysinfo'/>\n  </os>\n  <features>\n    <acpi/>\n  </features>\n  <cpu mode='custom' match='exact'>\n    <model fallback='allow'>Nehalem</model>\n    <topology sockets='1' cores='1' threads='1'/>\n  </cpu>\n  <clock offset='variable' adjustment='-2' basis='utc'>\n    <timer name='rtc' tickpolicy='catchup'/>\n  </clock>\n  <on_poweroff>destroy</on_poweroff>\n  <on_reboot>restart</on_reboot>\n  <on_crash>destroy</on_crash>\n  <devices>\n    <emulator>/usr/libexec/qemu-kvm</emulator>\n    <disk type='file' device='cdrom'>\n      <driver name='qemu' type='raw'/>\n      <source startupPolicy='optional'/>\n      <target dev='hdc' bus='ide'/>\n      <readonly/>\n      <serial></serial>\n      <boot order='1'/>\n      <alias name='ide0-1-0'/>\n      <address type='drive' controller='0' bus='1' target='0' unit='0'/>\n    </disk>\n    <disk type='file' device='disk' snapshot='no'>\n      <driver name='qemu' type='raw' cache='none' error_policy='stop' io='threads'/>\n      <source file='/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247'/>\n      <target dev='vda' bus='virtio'/>\n      <serial>513da23d-9469-49b5-8ef4-f00902cc061d</serial>\n      <alias name='virtio-disk0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/>\n    </disk>\n    <controller type='usb' index='0'>\n      <alias name='usb0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x2'/>\n    </controller>\n    <controller type='ide' index='0'>\n      <alias name='ide0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>\n    </controller>\n    <controller type='virtio-serial' index='0'>\n      <alias name='virtio-serial0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>\n    </controller>\n    <interface type='bridge'>\n      <mac address='00:1a:4a:46:cc:50'/>\n      <source bridge='ovirtmgmt'/>\n      <target dev='vnet0'/>\n      <model type='virtio'/>\n      <filterref filter='vdsm-no-mac-spoofing'/>\n      <link state='up'/>\n      <alias name='net0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>\n    </interface>\n    <channel type='unix'>\n      <source mode='bind' path='/var/lib/libvirt/qemu/channels/4bad94ad-c338-4ec5-8e5b-9910d58c1854.com.redhat.rhevm.vdsm'/>\n      <target type='virtio' name='com.redhat.rhevm.vdsm'/>\n      <alias name='channel0'/>\n      <address type='virtio-serial' controller='0' bus='0' port='1'/>\n    </channel>\n    <channel type='unix'>\n      <source mode='bind' path='/var/lib/libvirt/qemu/channels/4bad94ad-c338-4ec5-8e5b-9910d58c1854.org.qemu.guest_agent.0'/>\n      <target type='virtio' name='org.qemu.guest_agent.0'/>\n      <alias name='channel1'/>\n      <address type='virtio-serial' controller='0' bus='0' port='2'/>\n    </channel>\n    <channel type='spicevmc'>\n      <target type='virtio' name='com.redhat.spice.0'/>\n      <alias name='channel2'/>\n      <address type='virtio-serial' controller='0' bus='0' port='3'/>\n    </channel>\n    <input type='mouse' bus='ps2'/>\n    <graphics type='spice' port='5900' autoport='yes' keymap='en-us' passwdValidTo='1970-01-01T00:00:01'>\n      <listen type='network' address='3.70.204.31' network='vdsm-display'/>\n    </graphics>\n    <sound model='ac97'>\n      <alias name='sound0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>\n    </sound>\n    <video>\n      <model type='qxl' ram='65536' vram='65536' heads='1'/>\n      <alias name='video0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>\n    </video>\n    <memballoon model='virtio'>\n      <alias name='balloon0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>\n    </memballoon>\n  </devices>\n  <seclabel type='none'/>\n</domain>\n", 'memSize': 1024, 'elapsedTimeOffset': 116.61261296272278, 'vmName': 'opensuse111', 'nice': '0', 'status': 'Up', 'displayIp': '3.70.204.31', 'displayPort': '5900', 'smpCoresPerSocket': '1', 'smartcardEnable': 'false', 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'display', 'devices': [{'specParams': {'vram': '65536', 'heads': '1'}, 'alias': 'video0', 'deviceId': 'd4c0d314-ad32-4b34-82c0-4421b968a348', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:46:cc:50', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': '4296d12c-ff3a-4965-a818-a91ab5399122', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet0'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'bootOrder': '1', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '08d9f1f5-c0f8-4429-9a90-90669a625f3e', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '21474836480', 'specParams': {}, 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d', 'readonly': 'False', 'shared': 'false', 'truesize': '5380919296', 'type': 'disk', 'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volumeInfo': {'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d', 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247'}, 'format': 'raw', 'deviceId': '513da23d-9469-49b5-8ef4-f00902cc061d', 'poolID': '5849b030-626e-47cb-ad90-3ce782d831b3', 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d', 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247'}]}, {'specParams': {}, 'alias': 'sound0', 'deviceId': '62f5896d-da01-4d03-b4e5-5ce3fd81e33b', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'target': 1048576, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': 'fc0e3405-5869-49fa-ad0b-b452d6d9d731', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'device': 'usb', 'alias': 'usb0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x2'}}, {'device': 'ide', 'alias': 'ide0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x1'}}, {'device': 'virtio-serial', 'alias': 'virtio-serial0', 'type': 'controller', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}], 'guestIPs': '', 'display': 'qxl'},) {}
Thread-93::DEBUG::2013-10-11 15:22:38,846::API::498::vds::(migrationCreate) Migration create
Thread-93::INFO::2013-10-11 15:22:38,853::clientIF::391::vds::(createVm) vmContainerLock acquired by vm 4bad94ad-c338-4ec5-8e5b-9910d58c1854
Thread-93::DEBUG::2013-10-11 15:22:38,853::libvirtconnection::131::libvirtconnection::(get) trying to connect libvirt
Thread-94::DEBUG::2013-10-11 15:22:38,875::vm::2097::vm.Vm::(_startUnderlyingVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Start
Thread-93::DEBUG::2013-10-11 15:22:38,875::clientIF::404::vds::(createVm) Total desktops after creation of 4bad94ad-c338-4ec5-8e5b-9910d58c1854 is 1
Thread-94::DEBUG::2013-10-11 15:22:38,875::vm::2101::vm.Vm::(_startUnderlyingVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::_ongoingCreations acquired
Thread-93::DEBUG::2013-10-11 15:22:38,875::vm::4951::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::migration destination: waiting for VM creation
Thread-94::INFO::2013-10-11 15:22:38,876::vm::2899::vm.Vm::(_run) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::VM wrapper has started
Thread-93::DEBUG::2013-10-11 15:22:38,876::vm::4956::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::migration destination: waiting 36s for path preparation
Thread-94::WARNING::2013-10-11 15:22:38,877::vm::1884::vm.Vm::(getConfDevices) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found
Thread-94::WARNING::2013-10-11 15:22:38,877::vm::1884::vm.Vm::(getConfDevices) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found
Thread-94::WARNING::2013-10-11 15:22:38,877::vm::1884::vm.Vm::(getConfDevices) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Unknown type found, device: '{'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}' found
Thread-94::DEBUG::2013-10-11 15:22:38,878::task::579::TaskManager.Task::(_updateState) Task=`943e06b8-88a7-4cc3-8096-53ca393c0d1c`::moving from state init -> state preparing
Thread-94::INFO::2013-10-11 15:22:38,878::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='80e0d147-2e01-4499-a06b-697f9f0894ed', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='513da23d-9469-49b5-8ef4-f00902cc061d', volUUID='655420d5-6c5f-4bb8-a567-09b70a0c1247', options=None)
Thread-94::ERROR::2013-10-11 15:22:38,878::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-94::ERROR::2013-10-11 15:22:38,879::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-94::DEBUG::2013-10-11 15:22:38,879::lvm::385::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-94::DEBUG::2013-10-11 15:22:38,879::lvm::308::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 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 80e0d147-2e01-4499-a06b-697f9f0894ed' (cwd None)
Thread-94::DEBUG::2013-10-11 15:22:38,907::lvm::308::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "80e0d147-2e01-4499-a06b-697f9f0894ed" not found\n'; <rc> = 5
Thread-94::WARNING::2013-10-11 15:22:38,907::lvm::390::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "80e0d147-2e01-4499-a06b-697f9f0894ed" not found']
Thread-94::DEBUG::2013-10-11 15:22:38,908::lvm::427::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-94::DEBUG::2013-10-11 15:22:38,991::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-94::DEBUG::2013-10-11 15:22:39,061::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-94::DEBUG::2013-10-11 15:22:39,067::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=orgrimmar', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=Azeroth', 'POOL_DOMAINS=80e0d147-2e01-4499-a06b-697f9f0894ed:Active,26be0640-01a3-415d-82c9-0a92f2f84c3f:Active,afa8cb3b-2e93-4d6b-ad48-183cfc9f5732:Active,47b5e247-730c-413c-8413-655b0aeba82d:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=12', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/orgrimmar', 'ROLE=Master', 'SDUUID=80e0d147-2e01-4499-a06b-697f9f0894ed', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=d28229d739b379085bdb5c399fc3939596af1d93']
Thread-94::DEBUG::2013-10-11 15:22:39,070::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-94::DEBUG::2013-10-11 15:22:39,070::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '80e0d147-2e01-4499-a06b-697f9f0894ed_imageNS'
Thread-94::DEBUG::2013-10-11 15:22:39,071::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '80e0d147-2e01-4499-a06b-697f9f0894ed_volumeNS'
Thread-94::INFO::2013-10-11 15:22:39,073::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '5380927488', 'apparentsize': '21474836480'}
Thread-94::DEBUG::2013-10-11 15:22:39,073::task::1168::TaskManager.Task::(prepare) Task=`943e06b8-88a7-4cc3-8096-53ca393c0d1c`::finished: {'truesize': '5380927488', 'apparentsize': '21474836480'}
Thread-94::DEBUG::2013-10-11 15:22:39,073::task::579::TaskManager.Task::(_updateState) Task=`943e06b8-88a7-4cc3-8096-53ca393c0d1c`::moving from state preparing -> state finished
Thread-94::DEBUG::2013-10-11 15:22:39,074::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-94::DEBUG::2013-10-11 15:22:39,074::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-94::DEBUG::2013-10-11 15:22:39,074::task::974::TaskManager.Task::(_decref) Task=`943e06b8-88a7-4cc3-8096-53ca393c0d1c`::ref 0 aborting False
Thread-94::INFO::2013-10-11 15:22:39,074::clientIF::350::vds::(prepareVolumePath) prepared volume path: 
Thread-94::DEBUG::2013-10-11 15:22:39,075::task::579::TaskManager.Task::(_updateState) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::moving from state init -> state preparing
Thread-94::INFO::2013-10-11 15:22:39,075::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='80e0d147-2e01-4499-a06b-697f9f0894ed', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='513da23d-9469-49b5-8ef4-f00902cc061d', leafUUID='655420d5-6c5f-4bb8-a567-09b70a0c1247')
Thread-94::DEBUG::2013-10-11 15:22:39,075::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.80e0d147-2e01-4499-a06b-697f9f0894ed`ReqID=`6cde8e8c-e03c-4cc9-b0be-7c4907aa24bb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3237' at 'prepareImage'
Thread-94::DEBUG::2013-10-11 15:22:39,076::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' for lock type 'shared'
Thread-94::DEBUG::2013-10-11 15:22:39,076::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' is free. Now locking as 'shared' (1 active user)
Thread-94::DEBUG::2013-10-11 15:22:39,076::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.80e0d147-2e01-4499-a06b-697f9f0894ed`ReqID=`6cde8e8c-e03c-4cc9-b0be-7c4907aa24bb`::Granted request
Thread-94::DEBUG::2013-10-11 15:22:39,076::task::811::TaskManager.Task::(resourceAcquired) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::_resourcesAcquired: Storage.80e0d147-2e01-4499-a06b-697f9f0894ed (shared)
Thread-94::DEBUG::2013-10-11 15:22:39,077::task::974::TaskManager.Task::(_decref) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::ref 1 aborting False
Thread-94::WARNING::2013-10-11 15:22:39,079::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/80e0d147-2e01-4499-a06b-697f9f0894ed already exists
Thread-94::DEBUG::2013-10-11 15:22:39,079::fileSD::443::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/80e0d147-2e01-4499-a06b-697f9f0894ed/513da23d-9469-49b5-8ef4-f00902cc061d
Thread-94::DEBUG::2013-10-11 15:22:39,080::fileVolume::528::Storage.Volume::(validateVolumePath) validate path for 655420d5-6c5f-4bb8-a567-09b70a0c1247
Thread-94::INFO::2013-10-11 15:22:39,081::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'imgVolumesInfo': [{'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}]}
Thread-94::DEBUG::2013-10-11 15:22:39,081::task::1168::TaskManager.Task::(prepare) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::finished: {'info': {'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'imgVolumesInfo': [{'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}]}
Thread-94::DEBUG::2013-10-11 15:22:39,081::task::579::TaskManager.Task::(_updateState) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::moving from state preparing -> state finished
Thread-94::DEBUG::2013-10-11 15:22:39,081::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed': < ResourceRef 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed', isValid: 'True' obj: 'None'>}
Thread-94::DEBUG::2013-10-11 15:22:39,082::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-94::DEBUG::2013-10-11 15:22:39,082::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed'
Thread-94::DEBUG::2013-10-11 15:22:39,082::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' (0 active users)
Thread-94::DEBUG::2013-10-11 15:22:39,082::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' is free, finding out if anyone is waiting for it.
Thread-94::DEBUG::2013-10-11 15:22:39,082::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed', Clearing records.
Thread-94::DEBUG::2013-10-11 15:22:39,083::task::974::TaskManager.Task::(_decref) Task=`2c17d121-e180-4dcf-8e5c-70c14c8b1ce4`::ref 0 aborting False
Thread-94::INFO::2013-10-11 15:22:39,083::clientIF::350::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247
Thread-94::DEBUG::2013-10-11 15:22:39,089::vm::2118::vm.Vm::(_startUnderlyingVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::_ongoingCreations released
Thread-94::DEBUG::2013-10-11 15:22:39,091::vm::3472::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Waiting 300 seconds for end of migration
Thread-93::DEBUG::2013-10-11 15:22:39,099::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_migrate_destination/50_directlun' (cwd None)
Thread-93::DEBUG::2013-10-11 15:22:39,144::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-93::INFO::2013-10-11 15:22:39,144::hooks::88::root::(_runHooksDir) 
Thread-93::DEBUG::2013-10-11 15:22:39,144::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_migrate_destination/50_hugepages' (cwd None)
Thread-93::DEBUG::2013-10-11 15:22:39,191::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-93::INFO::2013-10-11 15:22:39,191::hooks::88::root::(_runHooksDir) 
Thread-93::DEBUG::2013-10-11 15:22:39,191::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_migrate_destination/50_vmfex' (cwd None)
Thread-93::DEBUG::2013-10-11 15:22:39,250::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-93::INFO::2013-10-11 15:22:39,251::hooks::88::root::(_runHooksDir) 
Thread-93::DEBUG::2013-10-11 15:22:39,251::API::511::vds::(migrationCreate) Destination VM creation succeeded
Thread-93::DEBUG::2013-10-11 15:22:39,251::BindingXMLRPC::981::vds::(wrapper) return vmMigrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'guestFQDN': '', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'afterMigrationStatus': '', 'pid': '0', 'memGuaranteedSize': 1024, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'timeOffset': '-2', 'cpuType': 'Nehalem', 'smp': '1', 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'custom': {'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602b': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=0e83e447-9a2c-4428-854c-7ae93183602b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=7dab6ddd-54c5-413b-adaf-b6db67c7f028, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=88c83317-c5a8-4594-80e3-d8cf0ddb6037, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028device_f5bd8220-0271-4c4e-8089-5e94b09b5993': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=f5bd8220-0271-4c4e-8089-5e94b09b5993, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=92d5b02c-db78-40eb-9006-0d95314392b4, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}}'}, 'vmType': 'kvm', 'memSize': 1024, 'vmName': 'opensuse111', 'nice': '0', 'username': 'Unknown', 'vmId': '4bad94ad-c338-4ec5-8e5b-9910d58c1854', 'displayIp': '3.70.204.32', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'smartcardEnable': 'false', 'guestIPs': '', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'display', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}, {'device': 'usb', 'alias': 'usb0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x2'}}, {'device': 'ide', 'alias': 'ide0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x1'}}, {'device': 'virtio-serial', 'alias': 'virtio-serial0', 'type': 'controller', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'specParams': {'vram': '65536', 'heads': '1'}, 'alias': 'video0', 'deviceId': 'd4c0d314-ad32-4b34-82c0-4421b968a348', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:46:cc:50', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': '4296d12c-ff3a-4965-a818-a91ab5399122', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet0'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'bootOrder': '1', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '08d9f1f5-c0f8-4429-9a90-90669a625f3e', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '21474836480', 'specParams': {}, 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d', 'readonly': 'False', 'shared': 'false', 'truesize': '5380927488', 'type': 'disk', 'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volumeInfo': {'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}, 'format': 'raw', 'deviceId': '513da23d-9469-49b5-8ef4-f00902cc061d', 'poolID': '5849b030-626e-47cb-ad90-3ce782d831b3', 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}]}, {'specParams': {}, 'alias': 'sound0', 'deviceId': '62f5896d-da01-4d03-b4e5-5ce3fd81e33b', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'target': 1048576, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': 'fc0e3405-5869-49fa-ad0b-b452d6d9d731', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}], 'status': 'Migration Destination', 'clientIp': '', 'display': 'qxl'}}
Thread-100::DEBUG::2013-10-11 15:22:39,270::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.31]::call vmDestroy with ('4bad94ad-c338-4ec5-8e5b-9910d58c1854',) {}
Thread-100::INFO::2013-10-11 15:22:39,271::API::318::vds::(destroy) vmContainerLock acquired by vm 4bad94ad-c338-4ec5-8e5b-9910d58c1854
Thread-100::DEBUG::2013-10-11 15:22:39,271::vm::4400::vm.Vm::(destroy) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::destroy Called
Thread-100::DEBUG::2013-10-11 15:22:39,271::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_destroy/50_promisc' (cwd None)
Thread-102::DEBUG::2013-10-11 15:22:39,282::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call vmGetStats with ('4bad94ad-c338-4ec5-8e5b-9910d58c1854',) {}
Thread-102::DEBUG::2013-10-11 15:22:39,283::BindingXMLRPC::981::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '3.70.204.32', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '-2', 'pauseCode': 'NOERR', 'kvmEnable': 'true', 'network': {}, 'vmId': '4bad94ad-c338-4ec5-8e5b-9910d58c1854', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '117', 'vmType': 'kvm', 'clientIp': ''}]}
Thread-100::DEBUG::2013-10-11 15:22:39,316::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,316::hooks::88::root::(_runHooksDir) 
Thread-100::INFO::2013-10-11 15:22:39,317::vm::4346::vm.Vm::(releaseVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Release VM resources
Thread-94::DEBUG::2013-10-11 15:22:39,318::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '4bad94ad-c338-4ec5-8e5b-9910d58c1854'
Thread-100::WARNING::2013-10-11 15:22:39,317::clientIF::362::vds::(teardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUNK_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories:<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f1428076050>> _customize:<bound method Drive._customize of <vm.Drive object at 0x7f1428076050>> _deviceXML:<disk device="cdrom" type="file">
      <driver name="qemu" type="raw"/>
      <source startupPolicy="optional"/>
      <target bus="ide" dev="hdc"/>
      <readonly/>
      <serial/>
      <boot order="1"/>
      <alias name="ide0-1-0"/>
      <address bus="1" controller="0" target="0" type="drive" unit="0"/>
    </disk> _makeName:<bound method Drive._makeName of <vm.Drive object at 0x7f1428076050>> _setExtSharedState:<bound method Drive._setExtSharedState of <vm.Drive object at 0x7f1428076050>> _validateIoTuneParams:<bound method Drive._validateIoTuneParams of <vm.Drive object at 0x7f1428076050>> address:{'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'} alias:ide0-1-0 apparentsize:0 blockDev:False bootOrder:1 cache:none conf:{'guestFQDN': '', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.4.0', 'afterMigrationStatus': '', 'pid': '0', 'memGuaranteedSize': 1024, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'timeOffset': '-2', 'cpuType': 'Nehalem', 'smp': '1', 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'custom': {'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602b': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=0e83e447-9a2c-4428-854c-7ae93183602b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=7dab6ddd-54c5-413b-adaf-b6db67c7f028, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=88c83317-c5a8-4594-80e3-d8cf0ddb6037, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4device_0e83e447-9a2c-4428-854c-7ae93183602bdevice_7dab6ddd-54c5-413b-adaf-b6db67c7f028device_f5bd8220-0271-4c4e-8089-5e94b09b5993': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=f5bd8220-0271-4c4e-8089-5e94b09b5993, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}}', 'device_88c83317-c5a8-4594-80e3-d8cf0ddb6037device_92d5b02c-db78-40eb-9006-0d95314392b4': 'VmDevice {vmId=4bad94ad-c338-4ec5-8e5b-9910d58c1854, deviceId=92d5b02c-db78-40eb-9006-0d95314392b4, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}}'}, 'vmType': 'kvm', 'memSize': 1024, 'vmName': 'opensuse111', 'nice': '0', 'username': 'Unknown', 'vmId': '4bad94ad-c338-4ec5-8e5b-9910d58c1854', 'displayIp': '3.70.204.32', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'smartcardEnable': 'false', 'guestIPs': '', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'display', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}, {'device': 'usb', 'alias': 'usb0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x2'}}, {'device': 'ide', 'alias': 'ide0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x1'}}, {'device': 'virtio-serial', 'alias': 'virtio-serial0', 'type': 'controller', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'specParams': {'vram': '65536', 'heads': '1'}, 'alias': 'video0', 'deviceId': 'd4c0d314-ad32-4b34-82c0-4421b968a348', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:46:cc:50', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'custom': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': '4296d12c-ff3a-4965-a818-a91ab5399122', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet0'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'bootOrder': '1', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '08d9f1f5-c0f8-4429-9a90-90669a625f3e', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '21474836480', 'specParams': {}, 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d', 'readonly': 'False', 'shared': 'false', 'truesize': '5380927488', 'type': 'disk', 'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volumeInfo': {'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}, 'format': 'raw', 'deviceId': '513da23d-9469-49b5-8ef4-f00902cc061d', 'poolID': '5849b030-626e-47cb-ad90-3ce782d831b3', 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '80e0d147-2e01-4499-a06b-697f9f0894ed', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247', 'volumeID': '655420d5-6c5f-4bb8-a567-09b70a0c1247', 'leasePath': '/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/images/513da23d-9469-49b5-8ef4-f00902cc061d/655420d5-6c5f-4bb8-a567-09b70a0c1247.lease', 'imageID': '513da23d-9469-49b5-8ef4-f00902cc061d'}]}, {'specParams': {}, 'alias': 'sound0', 'deviceId': '62f5896d-da01-4d03-b4e5-5ce3fd81e33b', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'target': 1048576, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': 'fc0e3405-5869-49fa-ad0b-b452d6d9d731', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}], 'status': 'Migration Destination', 'clientIp': '', 'display': 'qxl'} createXmlElem:<bound method Drive.createXmlElem of <vm.Drive object at 0x7f1428076050>> device:cdrom deviceId:08d9f1f5-c0f8-4429-9a90-90669a625f3e extSharedState:none getLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f1428076050>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Drive object at 0x7f1428076050>> getXML:<bound method Drive.getXML of <vm.Drive object at 0x7f1428076050>> hasVolumeLeases:False iface:ide index:2 isDiskReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <vm.Drive object at 0x7f1428076050>> isVdsmImage:<bound method Drive.isVdsmImage of <vm.Drive object at 0x7f1428076050>> log:<logUtils.SimpleLogAdapter instance at 0x7f14300685a8> name:hdc networkDev:False path: readonly:True reqsize:0 serial: shared:false specParams:{'path': ''} transientDisk:False truesize:0 type:disk volExtensionChunk:1024 watermarkLimit:536870912
Traceback (most recent call last):
  File "/usr/share/vdsm/clientIF.py", line 356, in teardownVolumePath
    res = self.irs.teardownImage(drive['domainID'],
  File "/usr/share/vdsm/vm.py", line 1388, in __getitem__
    raise KeyError(key)
KeyError: 'domainID'
Thread-94::ERROR::2013-10-11 15:22:39,320::vm::2144::vm.Vm::(_startUnderlyingVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 2122, in _startUnderlyingVm
    self._waitForIncomingMigrationFinish()
  File "/usr/share/vdsm/vm.py", line 3478, in _waitForIncomingMigrationFinish
    self._connection.lookupByUUIDString(self.id),
  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 76, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2838, in lookupByUUIDString
    if ret is None:raise libvirtError('virDomainLookupByUUIDString() failed', conn=self)
libvirtError: Domain not found: no domain with matching uuid '4bad94ad-c338-4ec5-8e5b-9910d58c1854'
Thread-100::DEBUG::2013-10-11 15:22:39,325::task::579::TaskManager.Task::(_updateState) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::moving from state init -> state preparing
Thread-94::DEBUG::2013-10-11 15:22:39,326::vm::2545::vm.Vm::(setDownStatus) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Changed state to Down: Domain not found: no domain with matching uuid '4bad94ad-c338-4ec5-8e5b-9910d58c1854'
Thread-100::INFO::2013-10-11 15:22:39,326::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='80e0d147-2e01-4499-a06b-697f9f0894ed', spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID='513da23d-9469-49b5-8ef4-f00902cc061d', volUUID=None)
Thread-100::DEBUG::2013-10-11 15:22:39,328::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.80e0d147-2e01-4499-a06b-697f9f0894ed`ReqID=`19d3b393-a91e-46e9-8788-e058b9db7dee`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3285' at 'teardownImage'
Thread-100::DEBUG::2013-10-11 15:22:39,328::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' for lock type 'shared'
Thread-100::DEBUG::2013-10-11 15:22:39,328::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' is free. Now locking as 'shared' (1 active user)
Thread-100::DEBUG::2013-10-11 15:22:39,328::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.80e0d147-2e01-4499-a06b-697f9f0894ed`ReqID=`19d3b393-a91e-46e9-8788-e058b9db7dee`::Granted request
Thread-100::DEBUG::2013-10-11 15:22:39,329::task::811::TaskManager.Task::(resourceAcquired) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::_resourcesAcquired: Storage.80e0d147-2e01-4499-a06b-697f9f0894ed (shared)
Thread-100::DEBUG::2013-10-11 15:22:39,329::task::974::TaskManager.Task::(_decref) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::ref 1 aborting False
Thread-100::INFO::2013-10-11 15:22:39,329::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
Thread-100::DEBUG::2013-10-11 15:22:39,329::task::1168::TaskManager.Task::(prepare) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::finished: None
Thread-100::DEBUG::2013-10-11 15:22:39,329::task::579::TaskManager.Task::(_updateState) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::moving from state preparing -> state finished
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed': < ResourceRef 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed', isValid: 'True' obj: 'None'>}
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed'
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' (0 active users)
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed' is free, finding out if anyone is waiting for it.
Thread-100::DEBUG::2013-10-11 15:22:39,330::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.80e0d147-2e01-4499-a06b-697f9f0894ed', Clearing records.
Thread-100::DEBUG::2013-10-11 15:22:39,331::task::974::TaskManager.Task::(_decref) Task=`ece74f83-7525-4bb6-b9e1-e499e364b9d1`::ref 0 aborting False
Thread-100::WARNING::2013-10-11 15:22:39,331::utils::113::root::(rmFile) File: /var/lib/libvirt/qemu/channels/4bad94ad-c338-4ec5-8e5b-9910d58c1854.com.redhat.rhevm.vdsm already removed
Thread-100::WARNING::2013-10-11 15:22:39,331::utils::113::root::(rmFile) File: /var/lib/libvirt/qemu/channels/4bad94ad-c338-4ec5-8e5b-9910d58c1854.org.qemu.guest_agent.0 already removed
Thread-100::DEBUG::2013-10-11 15:22:39,332::task::579::TaskManager.Task::(_updateState) Task=`727df5c2-5015-4a3d-ad9b-5bc1801e6064`::moving from state init -> state preparing
Thread-100::INFO::2013-10-11 15:22:39,332::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='4bad94ad-c338-4ec5-8e5b-9910d58c1854')
Thread-100::INFO::2013-10-11 15:22:39,333::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-100::DEBUG::2013-10-11 15:22:39,334::task::1168::TaskManager.Task::(prepare) Task=`727df5c2-5015-4a3d-ad9b-5bc1801e6064`::finished: None
Thread-100::DEBUG::2013-10-11 15:22:39,334::task::579::TaskManager.Task::(_updateState) Task=`727df5c2-5015-4a3d-ad9b-5bc1801e6064`::moving from state preparing -> state finished
Thread-100::DEBUG::2013-10-11 15:22:39,334::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-100::DEBUG::2013-10-11 15:22:39,334::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-100::DEBUG::2013-10-11 15:22:39,334::task::974::TaskManager.Task::(_decref) Task=`727df5c2-5015-4a3d-ad9b-5bc1801e6064`::ref 0 aborting False
Thread-100::DEBUG::2013-10-11 15:22:39,335::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/after_vm_destroy/50_directlun' (cwd None)
Thread-100::DEBUG::2013-10-11 15:22:39,378::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,379::hooks::88::root::(_runHooksDir) 
Thread-100::DEBUG::2013-10-11 15:22:39,379::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/after_vm_destroy/50_hostusb' (cwd None)
Thread-100::DEBUG::2013-10-11 15:22:39,423::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,423::hooks::88::root::(_runHooksDir) 
Thread-100::DEBUG::2013-10-11 15:22:39,423::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/after_vm_destroy/50_hugepages' (cwd None)
Thread-100::DEBUG::2013-10-11 15:22:39,437::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,438::hooks::88::root::(_runHooksDir) 
Thread-100::DEBUG::2013-10-11 15:22:39,438::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/after_vm_destroy/50_scratchpad' (cwd None)
Thread-100::DEBUG::2013-10-11 15:22:39,450::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,451::hooks::88::root::(_runHooksDir) 
Thread-100::DEBUG::2013-10-11 15:22:39,451::utils::489::root::(execCmd) '/usr/libexec/vdsm/hooks/after_vm_destroy/50_sriov' (cwd None)
Thread-100::DEBUG::2013-10-11 15:22:39,494::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-100::INFO::2013-10-11 15:22:39,494::hooks::88::root::(_runHooksDir) 
Thread-100::DEBUG::2013-10-11 15:22:39,495::vm::4394::vm.Vm::(deleteVm) vmId=`4bad94ad-c338-4ec5-8e5b-9910d58c1854`::Total desktops after destroy of 4bad94ad-c338-4ec5-8e5b-9910d58c1854 is 0
Thread-100::DEBUG::2013-10-11 15:22:39,495::BindingXMLRPC::981::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
Thread-103::DEBUG::2013-10-11 15:22:42,349::task::579::TaskManager.Task::(_updateState) Task=`20543373-03c2-4b6f-abdd-4e6099aa3237`::moving from state init -> state preparing
Thread-103::INFO::2013-10-11 15:22:42,349::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-103::INFO::2013-10-11 15:22:42,350::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-103::DEBUG::2013-10-11 15:22:42,350::task::1168::TaskManager.Task::(prepare) Task=`20543373-03c2-4b6f-abdd-4e6099aa3237`::finished: {}
Thread-103::DEBUG::2013-10-11 15:22:42,350::task::579::TaskManager.Task::(_updateState) Task=`20543373-03c2-4b6f-abdd-4e6099aa3237`::moving from state preparing -> state finished
Thread-103::DEBUG::2013-10-11 15:22:42,350::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-103::DEBUG::2013-10-11 15:22:42,350::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-103::DEBUG::2013-10-11 15:22:42,350::task::974::TaskManager.Task::(_decref) Task=`20543373-03c2-4b6f-abdd-4e6099aa3237`::ref 0 aborting False
Thread-109::DEBUG::2013-10-11 15:22:57,639::task::579::TaskManager.Task::(_updateState) Task=`0dc18dae-2b61-4009-8840-554cd914ebf3`::moving from state init -> state preparing
Thread-109::INFO::2013-10-11 15:22:57,639::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-109::INFO::2013-10-11 15:22:57,639::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-109::DEBUG::2013-10-11 15:22:57,639::task::1168::TaskManager.Task::(prepare) Task=`0dc18dae-2b61-4009-8840-554cd914ebf3`::finished: {}
Thread-109::DEBUG::2013-10-11 15:22:57,640::task::579::TaskManager.Task::(_updateState) Task=`0dc18dae-2b61-4009-8840-554cd914ebf3`::moving from state preparing -> state finished
Thread-109::DEBUG::2013-10-11 15:22:57,640::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-109::DEBUG::2013-10-11 15:22:57,640::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-109::DEBUG::2013-10-11 15:22:57,640::task::974::TaskManager.Task::(_decref) Task=`0dc18dae-2b61-4009-8840-554cd914ebf3`::ref 0 aborting False
Thread-115::DEBUG::2013-10-11 15:23:12,968::task::579::TaskManager.Task::(_updateState) Task=`ffd560c7-1f04-4544-9bdc-e9fde2f5e93e`::moving from state init -> state preparing
Thread-115::INFO::2013-10-11 15:23:12,969::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-115::INFO::2013-10-11 15:23:12,969::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-115::DEBUG::2013-10-11 15:23:12,969::task::1168::TaskManager.Task::(prepare) Task=`ffd560c7-1f04-4544-9bdc-e9fde2f5e93e`::finished: {}
Thread-115::DEBUG::2013-10-11 15:23:12,969::task::579::TaskManager.Task::(_updateState) Task=`ffd560c7-1f04-4544-9bdc-e9fde2f5e93e`::moving from state preparing -> state finished
Thread-115::DEBUG::2013-10-11 15:23:12,969::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-115::DEBUG::2013-10-11 15:23:12,970::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-115::DEBUG::2013-10-11 15:23:12,970::task::974::TaskManager.Task::(_decref) Task=`ffd560c7-1f04-4544-9bdc-e9fde2f5e93e`::ref 0 aborting False
Thread-121::DEBUG::2013-10-11 15:23:28,297::task::579::TaskManager.Task::(_updateState) Task=`4816983f-cbc7-4e72-b3fa-7b8df3fe311b`::moving from state init -> state preparing
Thread-121::INFO::2013-10-11 15:23:28,297::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-121::INFO::2013-10-11 15:23:28,297::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-121::DEBUG::2013-10-11 15:23:28,297::task::1168::TaskManager.Task::(prepare) Task=`4816983f-cbc7-4e72-b3fa-7b8df3fe311b`::finished: {}
Thread-121::DEBUG::2013-10-11 15:23:28,297::task::579::TaskManager.Task::(_updateState) Task=`4816983f-cbc7-4e72-b3fa-7b8df3fe311b`::moving from state preparing -> state finished
Thread-121::DEBUG::2013-10-11 15:23:28,298::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-121::DEBUG::2013-10-11 15:23:28,298::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-121::DEBUG::2013-10-11 15:23:28,298::task::974::TaskManager.Task::(_decref) Task=`4816983f-cbc7-4e72-b3fa-7b8df3fe311b`::ref 0 aborting False
Thread-127::DEBUG::2013-10-11 15:23:43,598::task::579::TaskManager.Task::(_updateState) Task=`0f75539f-7da9-4acf-9a33-aa5ea004e5fc`::moving from state init -> state preparing
Thread-127::INFO::2013-10-11 15:23:43,598::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-127::INFO::2013-10-11 15:23:43,598::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-127::DEBUG::2013-10-11 15:23:43,599::task::1168::TaskManager.Task::(prepare) Task=`0f75539f-7da9-4acf-9a33-aa5ea004e5fc`::finished: {}
Thread-127::DEBUG::2013-10-11 15:23:43,599::task::579::TaskManager.Task::(_updateState) Task=`0f75539f-7da9-4acf-9a33-aa5ea004e5fc`::moving from state preparing -> state finished
Thread-127::DEBUG::2013-10-11 15:23:43,599::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-127::DEBUG::2013-10-11 15:23:43,599::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-127::DEBUG::2013-10-11 15:23:43,599::task::974::TaskManager.Task::(_decref) Task=`0f75539f-7da9-4acf-9a33-aa5ea004e5fc`::ref 0 aborting False
Thread-133::DEBUG::2013-10-11 15:23:58,876::task::579::TaskManager.Task::(_updateState) Task=`953c2cb0-21d2-4376-8b31-91488a4cfac0`::moving from state init -> state preparing
Thread-133::INFO::2013-10-11 15:23:58,877::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-133::INFO::2013-10-11 15:23:58,877::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-133::DEBUG::2013-10-11 15:23:58,877::task::1168::TaskManager.Task::(prepare) Task=`953c2cb0-21d2-4376-8b31-91488a4cfac0`::finished: {}
Thread-133::DEBUG::2013-10-11 15:23:58,877::task::579::TaskManager.Task::(_updateState) Task=`953c2cb0-21d2-4376-8b31-91488a4cfac0`::moving from state preparing -> state finished
Thread-133::DEBUG::2013-10-11 15:23:58,877::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-133::DEBUG::2013-10-11 15:23:58,878::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-133::DEBUG::2013-10-11 15:23:58,878::task::974::TaskManager.Task::(_decref) Task=`953c2cb0-21d2-4376-8b31-91488a4cfac0`::ref 0 aborting False
Thread-139::DEBUG::2013-10-11 15:24:14,164::task::579::TaskManager.Task::(_updateState) Task=`7335b8aa-adf6-4a08-9bb4-569aa48ea3ae`::moving from state init -> state preparing
Thread-139::INFO::2013-10-11 15:24:14,165::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-139::INFO::2013-10-11 15:24:14,165::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-139::DEBUG::2013-10-11 15:24:14,165::task::1168::TaskManager.Task::(prepare) Task=`7335b8aa-adf6-4a08-9bb4-569aa48ea3ae`::finished: {}
Thread-139::DEBUG::2013-10-11 15:24:14,165::task::579::TaskManager.Task::(_updateState) Task=`7335b8aa-adf6-4a08-9bb4-569aa48ea3ae`::moving from state preparing -> state finished
Thread-139::DEBUG::2013-10-11 15:24:14,165::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-139::DEBUG::2013-10-11 15:24:14,165::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-139::DEBUG::2013-10-11 15:24:14,166::task::974::TaskManager.Task::(_decref) Task=`7335b8aa-adf6-4a08-9bb4-569aa48ea3ae`::ref 0 aborting False
Thread-143::DEBUG::2013-10-11 15:25:00,218::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getCapabilities with () {}
Thread-143::DEBUG::2013-10-11 15:25:00,220::utils::489::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-143::DEBUG::2013-10-11 15:25:00,225::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-143::ERROR::2013-10-11 15:25:00,270::netinfo::302::root::(speed) cannot read ib0 speed
Traceback (most recent call last):
  File "/usr/lib64/python2.6/site-packages/vdsm/netinfo.py", line 298, in speed
    s = int(speedFile.read())
IOError: [Errno 22] Invalid argument
Thread-143::DEBUG::2013-10-11 15:25:00,291::caps::347::root::(_getKeyPackages) rpm package glusterfs-rdma not found
Thread-143::DEBUG::2013-10-11 15:25:00,291::caps::347::root::(_getKeyPackages) rpm package glusterfs-fuse not found
Thread-143::DEBUG::2013-10-11 15:25:00,292::caps::347::root::(_getKeyPackages) rpm package gluster-swift not found
Thread-143::DEBUG::2013-10-11 15:25:00,296::caps::347::root::(_getKeyPackages) rpm package gluster-swift-object not found
Thread-143::DEBUG::2013-10-11 15:25:00,296::caps::347::root::(_getKeyPackages) rpm package glusterfs not found
Thread-143::DEBUG::2013-10-11 15:25:00,296::caps::347::root::(_getKeyPackages) rpm package gluster-swift-plugin not found
Thread-143::DEBUG::2013-10-11 15:25:00,301::caps::347::root::(_getKeyPackages) rpm package gluster-swift-account not found
Thread-143::DEBUG::2013-10-11 15:25:00,301::caps::347::root::(_getKeyPackages) rpm package gluster-swift-proxy not found
Thread-143::DEBUG::2013-10-11 15:25:00,301::caps::347::root::(_getKeyPackages) rpm package gluster-swift-doc not found
Thread-143::DEBUG::2013-10-11 15:25:00,302::caps::347::root::(_getKeyPackages) rpm package glusterfs-server not found
Thread-143::DEBUG::2013-10-11 15:25:00,302::caps::347::root::(_getKeyPackages) rpm package gluster-swift-container not found
Thread-143::DEBUG::2013-10-11 15:25:00,302::caps::347::root::(_getKeyPackages) rpm package glusterfs-geo-replication not found
Thread-143::DEBUG::2013-10-11 15:25:00,311::BindingXMLRPC::981::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.2013-07.net.azerothptr:lostisles'}], 'FC': []}, 'packages2': {'kernel': {'release': '400.209.1.el6uek.x86_64', 'buildtime': 1378863579.0, 'version': '2.6.39'}, 'spice-server': {'release': '12.el6_4.3', 'buildtime': 1378241404L, 'version': '0.12.0'}, 'vdsm': {'release': '10.el6', 'buildtime': 1381512173L, 'version': '4.13.0'}, 'qemu-kvm': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'libvirt': {'release': '18.0.1.el6_4.14', 'buildtime': 1379619458L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'mom': {'release': '13.el6', 'buildtime': 1379693580L, 'version': '0.3.2'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5540  @ 2.53GHz', 'hooks': {'after_vm_start': {'50_promisc': {'md5': '5ea469fa06dd7cd1e52508672a7519db'}}, 'before_vm_migrate_source': {'50_floppy': {'md5': 'c68fb91d44105c8b6f2d80566314027a'}, '50_hostusb': {'md5': 'e50a0975acd8bafd0052b65a787c2fdd'}, '50_scratchpad': {'md5': 'be90995f959c60c5110c6a0bef67c7b8'}, '50_sriov': {'md5': '47a59103b7c8b1439ae17dcd5ed197cd'}}, 'before_vm_destroy': {'50_promisc': {'md5': 'dae0434ea8ca2492422a6fde5cc47a1e'}}, 'before_vm_start': {'50_sriov': {'md5': '3ebc60cd2e4eb089820102285fad7c45'}, '50_vmfex': {'md5': '9f5abb892ddb6b3daa779985d38d9f55'}, '50_vmdisk': {'md5': 'b06259a563c750cf46c1d2a7c4ef739b'}, '50_scratchpad': {'md5': '7db25a4b8cb04f6e7132cb7c2300c111'}, '50_numa': {'md5': '5008c2826714ac5b63748780aabd2f25'}, '50_floppy': {'md5': '202fe18705a7d4c50c40c126e8f8dbe8'}, '50_qemucmdline': {'md5': 'a884929ad6f5eb039887157288867409'}, '50_pincpu': {'md5': '0b5fb99ff0e7acb9ad534b87c02c59e3'}, '50_macspoof': {'md5': '25deea559772719b90117f2e1009d823'}, '50_fileinject': {'md5': '290dafd45601e010e0f496fa5b889a76'}, '60_checkimages': {'md5': 'abd32c723a90ab2816e2163f5e02faf7'}, '50_usbtablet': {'md5': '392a12fb67be02d43d83855e585b6f9d'}, '50_directlun': {'md5': '5380575c0e80dc9907ab874393ad30a0'}, '50_hugepages': {'md5': '6713d703f9d316f1664145b700cd7904'}, '50_smbios': {'md5': '1a6bd8eddc3a86943e558bc4d3e73bd6'}, '50_qos': {'md5': '18b596a6b4e4bad80357f240ba122a5e'}, '50_hostusb': {'md5': '21c58568f3eae4f0d091005e0eff891a'}, '50_isolatedprivatevlan': {'md5': '0a25d7cd0b807ea5e0dfc3318ee98c91'}}, 'after_device_migrate_destination': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_device_create': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_nic_hotplug': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_vm_migrate_destination': {'50_vmfex': {'md5': 'eac2633f47fb309b4a5b7fe76531baec'}, '50_hugepages': {'md5': '6ddc484746297308b9f9acc5fcabaf10'}, '50_directlun': {'md5': '8a29ce41de079630cb58d48e280d55c2'}}, 'after_vm_destroy': {'50_sriov': {'md5': '5890b2899d450495a62f3611fad3c526'}, '50_hostusb': {'md5': '0a37bf0a26546e3ab5e424b13653ce2b'}, '50_directlun': {'md5': '6d05c19e68a141eeb7ee5981d68c0cfa'}, '50_scratchpad': {'md5': '316d21a669f97e83b485b45ab0b23eee'}, '50_hugepages': {'md5': '4a980b78f8ee908bf2c61ea9bf156f4a'}}, 'before_nic_hotplug': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_device_create': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'gateway': '0.0.0.0', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond2']}, 'csebackbone': {'iface': 'csebackbone', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'gateway': '0.0.0.0', 'netmask': '', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond0']}, 'display': {'iface': u'bond1', 'addr': '3.70.204.32', 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500', 'qosInbound': '', 'netmask': '255.255.252.0', 'qosOutbound': '', 'bridged': False, 'interface': u'bond1', 'ipv6gateway': '::', 'gateway': '3.70.204.254'}}, 'bridges': {'ovirtmgmt': {'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond2']}, 'csebackbone': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond0']}}, 'uuid': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'lastClientIface': 'ovirtmgmt', 'nics': {'ib0': {'netmask': '255.255.0.0', 'addr': '192.168.1.2', 'hwaddr': '80:00:04:04:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:59', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '192.168.1.2', 'PREFIX': '16', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib0', 'TYPE': 'Infiniband', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::212:79ff:ffb5:c059/64'], 'speed': 0, 'mtu': '65520'}, 'ib1': {'netmask': '', 'addr': '', 'hwaddr': '80:00:04:05:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:5a', 'cfg': {'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib1', 'TYPE': 'Infiniband', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'speed': 0, 'mtu': '2044'}, 'eth5': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A7', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth5', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A7', 'speed': 1000, 'mtu': '1500'}, 'eth4': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A6', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth4', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A6', 'speed': 1000, 'mtu': '1500'}, 'eth3': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A1', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A1', 'speed': 1000, 'mtu': '1500'}, 'eth2': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A0', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A0', 'speed': 1000, 'mtu': '1500'}, 'eth1': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9F', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9F', 'speed': 1000, 'mtu': '1500'}, 'eth0': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9E', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9E', 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '10', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_n270', 'ISCSIInitiatorName': 'iqn.2013-07.net.azerothptr:lostisles', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3'], 'reservedMem': '321', 'bondings': {'bond4': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond0': {'netmask': '', 'addr': '', 'slaves': ['eth0', 'eth1'], 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'BRIDGE': 'csebackbone', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500'}, 'bond1': {'netmask': '255.255.252.0', 'addr': '3.70.204.32', 'slaves': ['eth2', 'eth3'], 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.32', 'PREFIX': '22', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500'}, 'bond2': {'netmask': '', 'addr': '', 'slaves': ['eth4', 'eth5'], 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'BRIDGE': 'ovirtmgmt', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64'], 'mtu': '1500'}, 'bond3': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.13', 'memSize': '36272', 'cpuSpeed': '2534.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '16', 'emulatedMachines': [u'rhel6.4.0', u'pc', u'rhel6.3.0', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '4.0.4', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '3.57.111.30'}}
Thread-144::DEBUG::2013-10-11 15:25:00,334::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getHardwareInfo with () {}
Thread-144::DEBUG::2013-10-11 15:25:00,336::BindingXMLRPC::981::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'SUN FIRE X4170 SERVER', 'systemSerialNumber': '0950XF5199', 'systemFamily': 'To Be Filled By O.E.M.', 'systemVersion': '', 'systemUUID': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'systemManufacturer': 'SUN MICROSYSTEMS'}}
Thread-145::DEBUG::2013-10-11 15:25:02,806::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getCapabilities with () {}
Thread-145::DEBUG::2013-10-11 15:25:02,807::utils::489::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-145::DEBUG::2013-10-11 15:25:02,813::utils::509::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-145::ERROR::2013-10-11 15:25:02,857::netinfo::302::root::(speed) cannot read ib0 speed
Traceback (most recent call last):
  File "/usr/lib64/python2.6/site-packages/vdsm/netinfo.py", line 298, in speed
    s = int(speedFile.read())
IOError: [Errno 22] Invalid argument
Thread-145::DEBUG::2013-10-11 15:25:02,879::caps::347::root::(_getKeyPackages) rpm package glusterfs-rdma not found
Thread-145::DEBUG::2013-10-11 15:25:02,879::caps::347::root::(_getKeyPackages) rpm package glusterfs-fuse not found
Thread-145::DEBUG::2013-10-11 15:25:02,880::caps::347::root::(_getKeyPackages) rpm package gluster-swift not found
Thread-145::DEBUG::2013-10-11 15:25:02,884::caps::347::root::(_getKeyPackages) rpm package gluster-swift-object not found
Thread-145::DEBUG::2013-10-11 15:25:02,884::caps::347::root::(_getKeyPackages) rpm package glusterfs not found
Thread-145::DEBUG::2013-10-11 15:25:02,884::caps::347::root::(_getKeyPackages) rpm package gluster-swift-plugin not found
Thread-145::DEBUG::2013-10-11 15:25:02,889::caps::347::root::(_getKeyPackages) rpm package gluster-swift-account not found
Thread-145::DEBUG::2013-10-11 15:25:02,889::caps::347::root::(_getKeyPackages) rpm package gluster-swift-proxy not found
Thread-145::DEBUG::2013-10-11 15:25:02,890::caps::347::root::(_getKeyPackages) rpm package gluster-swift-doc not found
Thread-145::DEBUG::2013-10-11 15:25:02,890::caps::347::root::(_getKeyPackages) rpm package glusterfs-server not found
Thread-145::DEBUG::2013-10-11 15:25:02,890::caps::347::root::(_getKeyPackages) rpm package gluster-swift-container not found
Thread-145::DEBUG::2013-10-11 15:25:02,890::caps::347::root::(_getKeyPackages) rpm package glusterfs-geo-replication not found
Thread-145::DEBUG::2013-10-11 15:25:02,899::BindingXMLRPC::981::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.2013-07.net.azerothptr:lostisles'}], 'FC': []}, 'packages2': {'kernel': {'release': '400.209.1.el6uek.x86_64', 'buildtime': 1378863579.0, 'version': '2.6.39'}, 'spice-server': {'release': '12.el6_4.3', 'buildtime': 1378241404L, 'version': '0.12.0'}, 'vdsm': {'release': '10.el6', 'buildtime': 1381512173L, 'version': '4.13.0'}, 'qemu-kvm': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'libvirt': {'release': '18.0.1.el6_4.14', 'buildtime': 1379619458L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.355.el6_4.9', 'buildtime': 1380718347L, 'version': '0.12.1.2'}, 'mom': {'release': '13.el6', 'buildtime': 1379693580L, 'version': '0.3.2'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU           E5540  @ 2.53GHz', 'hooks': {'after_vm_start': {'50_promisc': {'md5': '5ea469fa06dd7cd1e52508672a7519db'}}, 'before_vm_migrate_source': {'50_floppy': {'md5': 'c68fb91d44105c8b6f2d80566314027a'}, '50_hostusb': {'md5': 'e50a0975acd8bafd0052b65a787c2fdd'}, '50_scratchpad': {'md5': 'be90995f959c60c5110c6a0bef67c7b8'}, '50_sriov': {'md5': '47a59103b7c8b1439ae17dcd5ed197cd'}}, 'before_vm_destroy': {'50_promisc': {'md5': 'dae0434ea8ca2492422a6fde5cc47a1e'}}, 'before_vm_start': {'50_sriov': {'md5': '3ebc60cd2e4eb089820102285fad7c45'}, '50_vmfex': {'md5': '9f5abb892ddb6b3daa779985d38d9f55'}, '50_vmdisk': {'md5': 'b06259a563c750cf46c1d2a7c4ef739b'}, '50_scratchpad': {'md5': '7db25a4b8cb04f6e7132cb7c2300c111'}, '50_numa': {'md5': '5008c2826714ac5b63748780aabd2f25'}, '50_floppy': {'md5': '202fe18705a7d4c50c40c126e8f8dbe8'}, '50_qemucmdline': {'md5': 'a884929ad6f5eb039887157288867409'}, '50_pincpu': {'md5': '0b5fb99ff0e7acb9ad534b87c02c59e3'}, '50_macspoof': {'md5': '25deea559772719b90117f2e1009d823'}, '50_fileinject': {'md5': '290dafd45601e010e0f496fa5b889a76'}, '60_checkimages': {'md5': 'abd32c723a90ab2816e2163f5e02faf7'}, '50_usbtablet': {'md5': '392a12fb67be02d43d83855e585b6f9d'}, '50_directlun': {'md5': '5380575c0e80dc9907ab874393ad30a0'}, '50_hugepages': {'md5': '6713d703f9d316f1664145b700cd7904'}, '50_smbios': {'md5': '1a6bd8eddc3a86943e558bc4d3e73bd6'}, '50_qos': {'md5': '18b596a6b4e4bad80357f240ba122a5e'}, '50_hostusb': {'md5': '21c58568f3eae4f0d091005e0eff891a'}, '50_isolatedprivatevlan': {'md5': '0a25d7cd0b807ea5e0dfc3318ee98c91'}}, 'after_device_migrate_destination': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_device_create': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'after_nic_hotplug': {'50_openstacknet': {'md5': '2fc481b6124f4d4c0b23a536fa7d1b64'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_vm_migrate_destination': {'50_vmfex': {'md5': 'eac2633f47fb309b4a5b7fe76531baec'}, '50_hugepages': {'md5': '6ddc484746297308b9f9acc5fcabaf10'}, '50_directlun': {'md5': '8a29ce41de079630cb58d48e280d55c2'}}, 'after_vm_destroy': {'50_sriov': {'md5': '5890b2899d450495a62f3611fad3c526'}, '50_hostusb': {'md5': '0a37bf0a26546e3ab5e424b13653ce2b'}, '50_directlun': {'md5': '6d05c19e68a141eeb7ee5981d68c0cfa'}, '50_scratchpad': {'md5': '316d21a669f97e83b485b45ab0b23eee'}, '50_hugepages': {'md5': '4a980b78f8ee908bf2c61ea9bf156f4a'}}, 'before_nic_hotplug': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}, 'before_device_create': {'50_openstacknet': {'md5': '24da5c2618e63fc811f10715d4e73f8d'}, '50_macspoof': {'md5': 'ca9c8ade572d4b5b4390755d4196c416'}, 'openstacknet_consts.py': {'md5': 'af4c005614282867517ea4cfb03d9089'}}}, 'cpuSockets': '2', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'gateway': '0.0.0.0', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond2']}, 'csebackbone': {'iface': 'csebackbone', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'gateway': '0.0.0.0', 'netmask': '', 'stp': 'off', 'bridged': True, 'qosInbound': '', 'qosOutbound': '', 'mtu': '1500', 'ipv6gateway': '::', 'ports': ['bond0']}, 'display': {'iface': u'bond1', 'addr': '3.70.204.32', 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500', 'qosInbound': '', 'netmask': '255.255.252.0', 'qosOutbound': '', 'bridged': False, 'interface': u'bond1', 'ipv6gateway': '::', 'gateway': '3.70.204.254'}}, 'bridges': {'ovirtmgmt': {'addr': '3.57.111.32', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.32', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64', 'fec0::a:215:17ff:fe00:fa6/64', '2002:32d:169d:a:215:17ff:fe00:fa6/64', '2002:339:6d53:a:215:17ff:fe00:fa6/64'], 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond2']}, 'csebackbone': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'csebackbone', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '0.0.0.0', 'ports': ['bond0']}}, 'uuid': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'lastClientIface': 'ovirtmgmt', 'nics': {'ib0': {'netmask': '255.255.0.0', 'addr': '192.168.1.2', 'hwaddr': '80:00:04:04:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:59', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '192.168.1.2', 'PREFIX': '16', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib0', 'TYPE': 'Infiniband', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::212:79ff:ffb5:c059/64'], 'speed': 0, 'mtu': '65520'}, 'ib1': {'netmask': '', 'addr': '', 'hwaddr': '80:00:04:05:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:c0:5a', 'cfg': {'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib1', 'TYPE': 'Infiniband', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'speed': 0, 'mtu': '2044'}, 'eth5': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A7', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth5', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A7', 'speed': 1000, 'mtu': '1500'}, 'eth4': {'netmask': '', 'addr': '', 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:0F:A6', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth4', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:15:17:00:0F:A6', 'speed': 1000, 'mtu': '1500'}, 'eth3': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A1', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A1', 'speed': 1000, 'mtu': '1500'}, 'eth2': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:A0', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:A0', 'speed': 1000, 'mtu': '1500'}, 'eth1': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9F', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9F', 'speed': 1000, 'mtu': '1500'}, 'eth0': {'netmask': '', 'addr': '', 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:6B:0E:9E', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'ipv6addrs': [], 'permhwaddr': '00:21:28:6B:0E:9E', 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '10', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_n270', 'ISCSIInitiatorName': 'iqn.2013-07.net.azerothptr:lostisles', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3'], 'reservedMem': '321', 'bondings': {'bond4': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond0': {'netmask': '', 'addr': '', 'slaves': ['eth0', 'eth1'], 'hwaddr': '00:21:28:6b:0e:9e', 'cfg': {'BRIDGE': 'csebackbone', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:e9e/64'], 'mtu': '1500'}, 'bond1': {'netmask': '255.255.252.0', 'addr': '3.70.204.32', 'slaves': ['eth2', 'eth3'], 'hwaddr': '00:21:28:6b:0e:a0', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.32', 'PREFIX': '22', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond1', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::221:28ff:fe6b:ea0/64'], 'mtu': '1500'}, 'bond2': {'netmask': '', 'addr': '', 'slaves': ['eth4', 'eth5'], 'hwaddr': '00:15:17:00:0f:a6', 'cfg': {'BRIDGE': 'ovirtmgmt', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond2', 'ONBOOT': 'yes'}, 'ipv6addrs': ['fe80::215:17ff:fe00:fa6/64'], 'mtu': '1500'}, 'bond3': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.13', 'memSize': '36272', 'cpuSpeed': '2534.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '16', 'emulatedMachines': [u'rhel6.4.0', u'pc', u'rhel6.3.0', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '4.0.4', 'version': '6Server', 'name': 'RHEL'}, 'lastClient': '3.57.111.30'}}
Thread-146::DEBUG::2013-10-11 15:25:02,920::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call getHardwareInfo with () {}
Thread-146::DEBUG::2013-10-11 15:25:02,922::BindingXMLRPC::981::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'SUN FIRE X4170 SERVER', 'systemSerialNumber': '0950XF5199', 'systemFamily': 'To Be Filled By O.E.M.', 'systemVersion': '', 'systemUUID': 'FF200008-FFFF-FFFF-FFFF-0021286B0EA2', 'systemManufacturer': 'SUN MICROSYSTEMS'}}
Thread-148::DEBUG::2013-10-11 15:25:03,138::BindingXMLRPC::177::vds::(wrapper) client [3.57.111.30]
Thread-148::DEBUG::2013-10-11 15:25:03,138::task::579::TaskManager.Task::(_updateState) Task=`a52c3cf5-7698-4a63-be47-1e6413e86412`::moving from state init -> state preparing
Thread-148::INFO::2013-10-11 15:25:03,138::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', conList=[{'port': '', 'connection': '192.168.0.1:/das0/iso', 'iqn': '', 'portal': '', 'user': '', 'protocol_version': '3', 'password': '******', 'id': '14cee8a8-123f-40dc-8be1-bf8ee25edb0e'}, {'port': '', 'connection': '192.168.0.1:/das0/stormwind', 'iqn': '', 'portal': '', 'user': '', 'protocol_version': '3', 'password': '******', 'id': '6900af84-9d1a-4205-9c86-c9a7278bde16'}, {'port': '', 'connection': '192.168.0.1:/das0/export', 'iqn': '', 'portal': '', 'user': '', 'protocol_version': '3', 'password': '******', 'id': '8bac1094-dcbf-45ed-b7e7-9468d4942870'}, {'port': '', 'connection': '192.168.0.1:/das0/orgrimmar', 'iqn': '', 'portal': '', 'user': '', 'protocol_version': '3', 'password': '******', 'id': '7cf948eb-9336-4f9a-9346-e630c27be8d6'}], options=None)
Thread-148::DEBUG::2013-10-11 15:25:03,140::hsm::2303::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.0.1:_das0_iso
Thread-148::DEBUG::2013-10-11 15:25:03,210::hsm::2327::Storage.HSM::(__prefetchDomains) Found SD uuids: ('afa8cb3b-2e93-4d6b-ad48-183cfc9f5732',)
Thread-148::DEBUG::2013-10-11 15:25:03,210::hsm::2378::Storage.HSM::(connectStorageServer) knownSDs: {afa8cb3b-2e93-4d6b-ad48-183cfc9f5732: storage.nfsSD.findDomain}
Thread-148::DEBUG::2013-10-11 15:25:03,212::hsm::2303::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.0.1:_das0_stormwind
Thread-148::DEBUG::2013-10-11 15:25:03,213::hsm::2327::Storage.HSM::(__prefetchDomains) Found SD uuids: ('26be0640-01a3-415d-82c9-0a92f2f84c3f',)
Thread-148::DEBUG::2013-10-11 15:25:03,213::hsm::2378::Storage.HSM::(connectStorageServer) knownSDs: {26be0640-01a3-415d-82c9-0a92f2f84c3f: storage.nfsSD.findDomain, afa8cb3b-2e93-4d6b-ad48-183cfc9f5732: storage.nfsSD.findDomain}
Thread-148::DEBUG::2013-10-11 15:25:03,215::hsm::2303::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.0.1:_das0_export
Thread-148::DEBUG::2013-10-11 15:25:03,216::hsm::2327::Storage.HSM::(__prefetchDomains) Found SD uuids: ('47b5e247-730c-413c-8413-655b0aeba82d',)
Thread-148::DEBUG::2013-10-11 15:25:03,216::hsm::2378::Storage.HSM::(connectStorageServer) knownSDs: {26be0640-01a3-415d-82c9-0a92f2f84c3f: storage.nfsSD.findDomain, afa8cb3b-2e93-4d6b-ad48-183cfc9f5732: storage.nfsSD.findDomain, 47b5e247-730c-413c-8413-655b0aeba82d: storage.nfsSD.findDomain}
Thread-148::DEBUG::2013-10-11 15:25:03,217::hsm::2303::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar
Thread-148::DEBUG::2013-10-11 15:25:03,218::hsm::2327::Storage.HSM::(__prefetchDomains) Found SD uuids: ('80e0d147-2e01-4499-a06b-697f9f0894ed',)
Thread-148::DEBUG::2013-10-11 15:25:03,219::hsm::2378::Storage.HSM::(connectStorageServer) knownSDs: {26be0640-01a3-415d-82c9-0a92f2f84c3f: storage.nfsSD.findDomain, afa8cb3b-2e93-4d6b-ad48-183cfc9f5732: storage.nfsSD.findDomain, 47b5e247-730c-413c-8413-655b0aeba82d: storage.nfsSD.findDomain, 80e0d147-2e01-4499-a06b-697f9f0894ed: storage.nfsSD.findDomain}
Thread-148::INFO::2013-10-11 15:25:03,219::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '14cee8a8-123f-40dc-8be1-bf8ee25edb0e'}, {'status': 0, 'id': '6900af84-9d1a-4205-9c86-c9a7278bde16'}, {'status': 0, 'id': '8bac1094-dcbf-45ed-b7e7-9468d4942870'}, {'status': 0, 'id': '7cf948eb-9336-4f9a-9346-e630c27be8d6'}]}
Thread-148::DEBUG::2013-10-11 15:25:03,219::task::1168::TaskManager.Task::(prepare) Task=`a52c3cf5-7698-4a63-be47-1e6413e86412`::finished: {'statuslist': [{'status': 0, 'id': '14cee8a8-123f-40dc-8be1-bf8ee25edb0e'}, {'status': 0, 'id': '6900af84-9d1a-4205-9c86-c9a7278bde16'}, {'status': 0, 'id': '8bac1094-dcbf-45ed-b7e7-9468d4942870'}, {'status': 0, 'id': '7cf948eb-9336-4f9a-9346-e630c27be8d6'}]}
Thread-148::DEBUG::2013-10-11 15:25:03,219::task::579::TaskManager.Task::(_updateState) Task=`a52c3cf5-7698-4a63-be47-1e6413e86412`::moving from state preparing -> state finished
Thread-148::DEBUG::2013-10-11 15:25:03,219::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-148::DEBUG::2013-10-11 15:25:03,220::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-148::DEBUG::2013-10-11 15:25:03,220::task::974::TaskManager.Task::(_decref) Task=`a52c3cf5-7698-4a63-be47-1e6413e86412`::ref 0 aborting False
Thread-149::DEBUG::2013-10-11 15:25:03,275::BindingXMLRPC::177::vds::(wrapper) client [3.57.111.30]
Thread-149::DEBUG::2013-10-11 15:25:03,275::task::579::TaskManager.Task::(_updateState) Task=`132426d9-f4b3-42c1-bccc-da4d847fa5d6`::moving from state init -> state preparing
Thread-149::INFO::2013-10-11 15:25:03,276::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', hostID=2, scsiKey='5849b030-626e-47cb-ad90-3ce782d831b3', msdUUID='80e0d147-2e01-4499-a06b-697f9f0894ed', masterVersion=1, options=None)
Thread-149::DEBUG::2013-10-11 15:25:03,276::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`ba81c265-45b7-4074-944a-17b1d1577af7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1036' at '_connectStoragePool'
Thread-149::DEBUG::2013-10-11 15:25:03,276::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive'
Thread-149::DEBUG::2013-10-11 15:25:03,276::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user)
Thread-149::DEBUG::2013-10-11 15:25:03,277::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`ba81c265-45b7-4074-944a-17b1d1577af7`::Granted request
Thread-149::INFO::2013-10-11 15:25:03,277::sp::681::Storage.StoragePool::(connect) Connect host #2 to the storage pool 5849b030-626e-47cb-ad90-3ce782d831b3 with master domain: 80e0d147-2e01-4499-a06b-697f9f0894ed (ver = 1)
Thread-149::DEBUG::2013-10-11 15:25:03,278::lvm::509::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,278::lvm::511::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,278::lvm::520::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,278::lvm::522::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,278::lvm::540::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,279::lvm::542::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:03,279::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-149::DEBUG::2013-10-11 15:25:03,279::misc::811::SamplingMethod::(__call__) Got in to sampling method
Thread-149::DEBUG::2013-10-11 15:25:03,279::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-149::DEBUG::2013-10-11 15:25:03,279::misc::811::SamplingMethod::(__call__) Got in to sampling method
Thread-149::DEBUG::2013-10-11 15:25:03,280::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-149::DEBUG::2013-10-11 15:25:03,291::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-149::DEBUG::2013-10-11 15:25:03,292::misc::819::SamplingMethod::(__call__) Returning last result
Thread-149::DEBUG::2013-10-11 15:25:05,323::multipath::112::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-149::DEBUG::2013-10-11 15:25:05,380::multipath::112::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-149::DEBUG::2013-10-11 15:25:05,381::lvm::509::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,381::lvm::511::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,381::lvm::520::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,382::lvm::522::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,382::lvm::540::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,382::lvm::542::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-149::DEBUG::2013-10-11 15:25:05,382::misc::819::SamplingMethod::(__call__) Returning last result
Thread-149::DEBUG::2013-10-11 15:25:05,394::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-149::DEBUG::2013-10-11 15:25:05,396::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-149::DEBUG::2013-10-11 15:25:05,402::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=orgrimmar', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=Azeroth', 'POOL_DOMAINS=80e0d147-2e01-4499-a06b-697f9f0894ed:Active,26be0640-01a3-415d-82c9-0a92f2f84c3f:Active,afa8cb3b-2e93-4d6b-ad48-183cfc9f5732:Active,47b5e247-730c-413c-8413-655b0aeba82d:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=12', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/orgrimmar', 'ROLE=Master', 'SDUUID=80e0d147-2e01-4499-a06b-697f9f0894ed', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=d28229d739b379085bdb5c399fc3939596af1d93']
Thread-149::DEBUG::2013-10-11 15:25:05,404::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-149::INFO::2013-10-11 15:25:05,404::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 80e0d147-2e01-4499-a06b-697f9f0894ed_imageNS already registered
Thread-149::INFO::2013-10-11 15:25:05,404::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 80e0d147-2e01-4499-a06b-697f9f0894ed_volumeNS already registered
Thread-149::DEBUG::2013-10-11 15:25:05,405::sp::1626::Storage.StoragePool::(getMasterDomain) Master domain 80e0d147-2e01-4499-a06b-697f9f0894ed verified, version 1
Thread-149::DEBUG::2013-10-11 15:25:05,405::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
Thread-149::DEBUG::2013-10-11 15:25:05,405::misc::811::SamplingMethod::(__call__) Got in to sampling method
Thread-149::DEBUG::2013-10-11 15:25:05,411::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=orgrimmar', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=Azeroth', 'POOL_DOMAINS=80e0d147-2e01-4499-a06b-697f9f0894ed:Active,26be0640-01a3-415d-82c9-0a92f2f84c3f:Active,afa8cb3b-2e93-4d6b-ad48-183cfc9f5732:Active,47b5e247-730c-413c-8413-655b0aeba82d:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=12', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/orgrimmar', 'ROLE=Master', 'SDUUID=80e0d147-2e01-4499-a06b-697f9f0894ed', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=d28229d739b379085bdb5c399fc3939596af1d93']
Thread-154::DEBUG::2013-10-11 15:25:05,412::domainMonitor::151::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-149::DEBUG::2013-10-11 15:25:05,412::sp::1659::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `5849b030-626e-47cb-ad90-3ce782d831b3` started monitoring domain `80e0d147-2e01-4499-a06b-697f9f0894ed`
Thread-155::DEBUG::2013-10-11 15:25:05,414::domainMonitor::151::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 26be0640-01a3-415d-82c9-0a92f2f84c3f
Thread-149::DEBUG::2013-10-11 15:25:05,414::sp::1659::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `5849b030-626e-47cb-ad90-3ce782d831b3` started monitoring domain `26be0640-01a3-415d-82c9-0a92f2f84c3f`
Thread-149::DEBUG::2013-10-11 15:25:05,422::sp::1659::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `5849b030-626e-47cb-ad90-3ce782d831b3` started monitoring domain `afa8cb3b-2e93-4d6b-ad48-183cfc9f5732`
Thread-156::DEBUG::2013-10-11 15:25:05,422::domainMonitor::151::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for afa8cb3b-2e93-4d6b-ad48-183cfc9f5732
Thread-149::DEBUG::2013-10-11 15:25:05,433::sp::1659::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `5849b030-626e-47cb-ad90-3ce782d831b3` started monitoring domain `47b5e247-730c-413c-8413-655b0aeba82d`
Thread-161::DEBUG::2013-10-11 15:25:05,434::domainMonitor::151::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 47b5e247-730c-413c-8413-655b0aeba82d
Thread-149::DEBUG::2013-10-11 15:25:05,439::misc::819::SamplingMethod::(__call__) Returning last result
Thread-149::DEBUG::2013-10-11 15:25:05,504::lvm::385::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-155::DEBUG::2013-10-11 15:25:05,509::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f
Thread-156::DEBUG::2013-10-11 15:25:05,520::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732
Thread-149::DEBUG::2013-10-11 15:25:05,533::lvm::308::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 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 26be0640-01a3-415d-82c9-0a92f2f84c3f afa8cb3b-2e93-4d6b-ad48-183cfc9f5732 47b5e247-730c-413c-8413-655b0aeba82d' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:05,547::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:05,553::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000253705 s, 2.3 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:05,562::fileSD::154::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d
Thread-149::DEBUG::2013-10-11 15:25:05,578::lvm::308::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "26be0640-01a3-415d-82c9-0a92f2f84c3f" not found\n  Volume group "afa8cb3b-2e93-4d6b-ad48-183cfc9f5732" not found\n  Volume group "47b5e247-730c-413c-8413-655b0aeba82d" not found\n'; <rc> = 5
Thread-149::WARNING::2013-10-11 15:25:05,580::lvm::390::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "26be0640-01a3-415d-82c9-0a92f2f84c3f" not found', '  Volume group "afa8cb3b-2e93-4d6b-ad48-183cfc9f5732" not found', '  Volume group "47b5e247-730c-413c-8413-655b0aeba82d" not found']
Thread-149::DEBUG::2013-10-11 15:25:05,581::lvm::427::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-154::INFO::2013-10-11 15:25:05,584::clusterlock::174::SANLock::(acquireHostId) Acquiring host id for domain 80e0d147-2e01-4499-a06b-697f9f0894ed (id: 2)
Thread-154::DEBUG::2013-10-11 15:25:05,588::clusterlock::192::SANLock::(acquireHostId) Host id for domain 80e0d147-2e01-4499-a06b-697f9f0894ed successfully acquired (id: 2)
Thread-155::DEBUG::2013-10-11 15:25:05,595::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-149::INFO::2013-10-11 15:25:05,596::sp::1198::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732 to /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732
Thread-149::INFO::2013-10-11 15:25:05,597::sp::1198::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f to /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/26be0640-01a3-415d-82c9-0a92f2f84c3f
Thread-149::INFO::2013-10-11 15:25:05,597::sp::1198::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d to /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/47b5e247-730c-413c-8413-655b0aeba82d
Thread-149::INFO::2013-10-11 15:25:05,598::sp::1198::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed to /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/80e0d147-2e01-4499-a06b-697f9f0894ed
Thread-149::INFO::2013-10-11 15:25:05,598::sp::1198::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed to /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/mastersd
Thread-149::DEBUG::2013-10-11 15:25:05,599::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
Thread-149::DEBUG::2013-10-11 15:25:05,599::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users)
Thread-149::DEBUG::2013-10-11 15:25:05,599::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it.
Thread-149::DEBUG::2013-10-11 15:25:05,599::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records.
Thread-149::INFO::2013-10-11 15:25:05,599::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
Thread-149::DEBUG::2013-10-11 15:25:05,600::task::1168::TaskManager.Task::(prepare) Task=`132426d9-f4b3-42c1-bccc-da4d847fa5d6`::finished: True
Thread-149::DEBUG::2013-10-11 15:25:05,600::task::579::TaskManager.Task::(_updateState) Task=`132426d9-f4b3-42c1-bccc-da4d847fa5d6`::moving from state preparing -> state finished
Thread-149::DEBUG::2013-10-11 15:25:05,600::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-149::DEBUG::2013-10-11 15:25:05,600::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-149::DEBUG::2013-10-11 15:25:05,600::task::974::TaskManager.Task::(_decref) Task=`132426d9-f4b3-42c1-bccc-da4d847fa5d6`::ref 0 aborting False
Thread-155::DEBUG::2013-10-11 15:25:05,602::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=stormwind', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/stormwind', 'ROLE=Regular', 'SDUUID=26be0640-01a3-415d-82c9-0a92f2f84c3f', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=c212dca6d5e65f83d6e15f7098741941d7fdb2f9']
Thread-156::DEBUG::2013-10-11 15:25:05,605::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-155::DEBUG::2013-10-11 15:25:05,608::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-155::DEBUG::2013-10-11 15:25:05,611::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '26be0640-01a3-415d-82c9-0a92f2f84c3f_imageNS'
Thread-174::DEBUG::2013-10-11 15:25:05,613::task::579::TaskManager.Task::(_updateState) Task=`fc15a7eb-6527-4e5b-96d9-4a779be8975c`::moving from state init -> state preparing
Thread-155::DEBUG::2013-10-11 15:25:05,614::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '26be0640-01a3-415d-82c9-0a92f2f84c3f_volumeNS'
Thread-174::INFO::2013-10-11 15:25:05,614::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-174::INFO::2013-10-11 15:25:05,619::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000253705', 'lastCheck': '0.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}}
Thread-156::DEBUG::2013-10-11 15:25:05,620::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Iso', 'DESCRIPTION=iso', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/iso', 'ROLE=Regular', 'SDUUID=afa8cb3b-2e93-4d6b-ad48-183cfc9f5732', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=9c29158ff825e435addff1a71b33c5acbec90da2']
Thread-174::DEBUG::2013-10-11 15:25:05,623::task::1168::TaskManager.Task::(prepare) Task=`fc15a7eb-6527-4e5b-96d9-4a779be8975c`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000253705', 'lastCheck': '0.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0', 'lastCheck': '0.2', 'code': 0, 'valid': True, 'version': -1}}
Thread-174::DEBUG::2013-10-11 15:25:05,626::task::579::TaskManager.Task::(_updateState) Task=`fc15a7eb-6527-4e5b-96d9-4a779be8975c`::moving from state preparing -> state finished
Thread-174::DEBUG::2013-10-11 15:25:05,629::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-174::DEBUG::2013-10-11 15:25:05,631::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-174::DEBUG::2013-10-11 15:25:05,632::task::974::TaskManager.Task::(_decref) Task=`fc15a7eb-6527-4e5b-96d9-4a779be8975c`::ref 0 aborting False
Thread-156::DEBUG::2013-10-11 15:25:05,634::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-156::DEBUG::2013-10-11 15:25:05,637::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732_imageNS'
Thread-161::DEBUG::2013-10-11 15:25:05,641::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-156::DEBUG::2013-10-11 15:25:05,643::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732_volumeNS'
Thread-161::DEBUG::2013-10-11 15:25:05,661::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Backup', 'DESCRIPTION=export', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=5849b030-626e-47cb-ad90-3ce782d831b3', 'REMOTE_PATH=192.168.0.1:/das0/export', 'ROLE=Regular', 'SDUUID=47b5e247-730c-413c-8413-655b0aeba82d', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=839e4958a5464f71911a942e9d8927f7b0862387']
Thread-161::DEBUG::2013-10-11 15:25:05,678::fileSD::572::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-161::DEBUG::2013-10-11 15:25:05,682::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '47b5e247-730c-413c-8413-655b0aeba82d_imageNS'
Thread-161::DEBUG::2013-10-11 15:25:05,687::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '47b5e247-730c-413c-8413-655b0aeba82d_volumeNS'
Thread-155::DEBUG::2013-10-11 15:25:05,699::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:05,732::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000194571 s, 1.8 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:05,734::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:05,749::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000257977 s, 1.3 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:05,753::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:05,758::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000203794 s, 1.7 MB/s\n'; <rc> = 0
Thread-175::DEBUG::2013-10-11 15:25:06,244::BindingXMLRPC::974::vds::(wrapper) client [3.57.111.30]::call setMOMPolicyParameters with ({'balloonEnabled': False},) {}
Thread-175::DEBUG::2013-10-11 15:25:06,300::BindingXMLRPC::981::vds::(wrapper) return setMOMPolicyParameters with {'status': {'message': 'Done', 'code': 0}}
Thread-154::DEBUG::2013-10-11 15:25:15,603::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:15,610::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000194172 s, 3.1 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:25:15,752::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:15,787::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000247391 s, 1.4 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:15,815::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:15,829::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:15,830::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000174543 s, 1.9 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:15,840::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000172557 s, 2.0 MB/s\n'; <rc> = 0
Thread-179::DEBUG::2013-10-11 15:25:18,598::task::579::TaskManager.Task::(_updateState) Task=`52c1550d-0d50-44d1-859d-a65169d2366e`::moving from state init -> state preparing
Thread-179::INFO::2013-10-11 15:25:18,598::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-179::INFO::2013-10-11 15:25:18,599::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000194172', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000174543', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000247391', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000172557', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}}
Thread-179::DEBUG::2013-10-11 15:25:18,599::task::1168::TaskManager.Task::(prepare) Task=`52c1550d-0d50-44d1-859d-a65169d2366e`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000194172', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000174543', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000247391', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000172557', 'lastCheck': '2.8', 'code': 0, 'valid': True, 'version': 0}}
Thread-179::DEBUG::2013-10-11 15:25:18,599::task::579::TaskManager.Task::(_updateState) Task=`52c1550d-0d50-44d1-859d-a65169d2366e`::moving from state preparing -> state finished
Thread-179::DEBUG::2013-10-11 15:25:18,599::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-179::DEBUG::2013-10-11 15:25:18,599::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-179::DEBUG::2013-10-11 15:25:18,599::task::974::TaskManager.Task::(_decref) Task=`52c1550d-0d50-44d1-859d-a65169d2366e`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:25:25,619::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:25,624::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000194731 s, 3.1 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:25:25,803::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:25,807::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000227663 s, 1.5 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:25,859::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:25,868::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:25,874::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000205981 s, 1.6 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:25,877::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000266353 s, 1.3 MB/s\n'; <rc> = 0
Thread-185::DEBUG::2013-10-11 15:25:33,865::task::579::TaskManager.Task::(_updateState) Task=`2c09d80c-b259-41b8-9b0b-cd37c7bde742`::moving from state init -> state preparing
Thread-185::INFO::2013-10-11 15:25:33,866::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-185::INFO::2013-10-11 15:25:33,866::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000194731', 'lastCheck': '8.2', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000205981', 'lastCheck': '8.0', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000227663', 'lastCheck': '8.1', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000266353', 'lastCheck': '8.0', 'code': 0, 'valid': True, 'version': 0}}
Thread-185::DEBUG::2013-10-11 15:25:33,866::task::1168::TaskManager.Task::(prepare) Task=`2c09d80c-b259-41b8-9b0b-cd37c7bde742`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000194731', 'lastCheck': '8.2', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000205981', 'lastCheck': '8.0', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000227663', 'lastCheck': '8.1', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000266353', 'lastCheck': '8.0', 'code': 0, 'valid': True, 'version': 0}}
Thread-185::DEBUG::2013-10-11 15:25:33,866::task::579::TaskManager.Task::(_updateState) Task=`2c09d80c-b259-41b8-9b0b-cd37c7bde742`::moving from state preparing -> state finished
Thread-185::DEBUG::2013-10-11 15:25:33,866::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-185::DEBUG::2013-10-11 15:25:33,866::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-185::DEBUG::2013-10-11 15:25:33,867::task::974::TaskManager.Task::(_decref) Task=`2c09d80c-b259-41b8-9b0b-cd37c7bde742`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:25:35,632::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:35,637::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000249917 s, 2.4 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:25:35,814::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:35,818::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000222666 s, 1.6 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:35,906::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:35,917::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:35,923::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000189175 s, 1.8 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:35,930::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000168348 s, 2.0 MB/s\n'; <rc> = 0
Thread-154::DEBUG::2013-10-11 15:25:45,644::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:45,649::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000206341 s, 2.9 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:25:45,825::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:45,829::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000278305 s, 1.3 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:45,955::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:45,972::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000335201 s, 1.0 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:45,974::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:45,981::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000240694 s, 1.4 MB/s\n'; <rc> = 0
Thread-191::DEBUG::2013-10-11 15:25:49,144::task::579::TaskManager.Task::(_updateState) Task=`1825d1a6-8ada-41ee-8e08-983964b8c3bc`::moving from state init -> state preparing
Thread-191::INFO::2013-10-11 15:25:49,145::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-191::INFO::2013-10-11 15:25:49,145::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000206341', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000335201', 'lastCheck': '3.2', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000278305', 'lastCheck': '3.3', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000240694', 'lastCheck': '3.2', 'code': 0, 'valid': True, 'version': 0}}
Thread-191::DEBUG::2013-10-11 15:25:49,145::task::1168::TaskManager.Task::(prepare) Task=`1825d1a6-8ada-41ee-8e08-983964b8c3bc`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000206341', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000335201', 'lastCheck': '3.2', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000278305', 'lastCheck': '3.3', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000240694', 'lastCheck': '3.2', 'code': 0, 'valid': True, 'version': 0}}
Thread-191::DEBUG::2013-10-11 15:25:49,145::task::579::TaskManager.Task::(_updateState) Task=`1825d1a6-8ada-41ee-8e08-983964b8c3bc`::moving from state preparing -> state finished
Thread-191::DEBUG::2013-10-11 15:25:49,145::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-191::DEBUG::2013-10-11 15:25:49,145::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-191::DEBUG::2013-10-11 15:25:49,146::task::974::TaskManager.Task::(_decref) Task=`1825d1a6-8ada-41ee-8e08-983964b8c3bc`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:25:55,656::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:25:55,661::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000206574 s, 2.9 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:25:55,836::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:25:55,840::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000201104 s, 1.7 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:25:56,006::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:25:56,023::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000164019 s, 2.0 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:25:56,026::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:25:56,032::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000188354 s, 1.8 MB/s\n'; <rc> = 0
Thread-197::DEBUG::2013-10-11 15:26:04,396::task::579::TaskManager.Task::(_updateState) Task=`3173eef9-ded1-4418-84d7-f704f29c4e2c`::moving from state init -> state preparing
Thread-197::INFO::2013-10-11 15:26:04,397::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-197::INFO::2013-10-11 15:26:04,397::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000206574', 'lastCheck': '8.7', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000164019', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000201104', 'lastCheck': '8.6', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000188354', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 0}}
Thread-197::DEBUG::2013-10-11 15:26:04,397::task::1168::TaskManager.Task::(prepare) Task=`3173eef9-ded1-4418-84d7-f704f29c4e2c`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000206574', 'lastCheck': '8.7', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000164019', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000201104', 'lastCheck': '8.6', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000188354', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version': 0}}
Thread-197::DEBUG::2013-10-11 15:26:04,397::task::579::TaskManager.Task::(_updateState) Task=`3173eef9-ded1-4418-84d7-f704f29c4e2c`::moving from state preparing -> state finished
Thread-197::DEBUG::2013-10-11 15:26:04,397::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-197::DEBUG::2013-10-11 15:26:04,398::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-197::DEBUG::2013-10-11 15:26:04,398::task::974::TaskManager.Task::(_decref) Task=`3173eef9-ded1-4418-84d7-f704f29c4e2c`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:26:05,669::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:05,674::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000173498 s, 3.4 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:05,848::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:05,853::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000212058 s, 1.6 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:06,057::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:06,073::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.00019094 s, 1.8 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:06,073::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:06,082::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000311306 s, 1.1 MB/s\n'; <rc> = 0
Thread-154::DEBUG::2013-10-11 15:26:15,682::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:15,687::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000252829 s, 2.4 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:15,860::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:15,864::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000184734 s, 1.9 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:16,110::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:16,124::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:16,129::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000159773 s, 2.1 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:16,136::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.00025405 s, 1.4 MB/s\n'; <rc> = 0
Thread-203::DEBUG::2013-10-11 15:26:19,674::task::579::TaskManager.Task::(_updateState) Task=`68b6fb90-e9a4-422b-88af-fe84785cf970`::moving from state init -> state preparing
Thread-203::INFO::2013-10-11 15:26:19,675::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-203::INFO::2013-10-11 15:26:19,675::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000252829', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000159773', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000184734', 'lastCheck': '3.8', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.00025405', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}}
Thread-203::DEBUG::2013-10-11 15:26:19,675::task::1168::TaskManager.Task::(prepare) Task=`68b6fb90-e9a4-422b-88af-fe84785cf970`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000252829', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000159773', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000184734', 'lastCheck': '3.8', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.00025405', 'lastCheck': '3.5', 'code': 0, 'valid': True, 'version': 0}}
Thread-203::DEBUG::2013-10-11 15:26:19,675::task::579::TaskManager.Task::(_updateState) Task=`68b6fb90-e9a4-422b-88af-fe84785cf970`::moving from state preparing -> state finished
Thread-203::DEBUG::2013-10-11 15:26:19,676::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-203::DEBUG::2013-10-11 15:26:19,676::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-203::DEBUG::2013-10-11 15:26:19,676::task::974::TaskManager.Task::(_decref) Task=`68b6fb90-e9a4-422b-88af-fe84785cf970`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:26:25,694::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:25,699::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000201116 s, 3.0 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:25,871::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:25,875::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000186483 s, 1.9 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:26,163::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:26,178::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:26,179::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000172906 s, 1.9 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:26,187::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000234564 s, 1.5 MB/s\n'; <rc> = 0
Thread-209::DEBUG::2013-10-11 15:26:34,947::task::579::TaskManager.Task::(_updateState) Task=`fdb11005-0b0b-4357-9e1b-9d4fdb6af812`::moving from state init -> state preparing
Thread-209::INFO::2013-10-11 15:26:34,948::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-209::INFO::2013-10-11 15:26:34,948::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000201116', 'lastCheck': '9.2', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000172906', 'lastCheck': '8.8', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000186483', 'lastCheck': '9.1', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000234564', 'lastCheck': '8.8', 'code': 0, 'valid': True, 'version': 0}}
Thread-209::DEBUG::2013-10-11 15:26:34,948::task::1168::TaskManager.Task::(prepare) Task=`fdb11005-0b0b-4357-9e1b-9d4fdb6af812`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000201116', 'lastCheck': '9.2', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000172906', 'lastCheck': '8.8', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000186483', 'lastCheck': '9.1', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000234564', 'lastCheck': '8.8', 'code': 0, 'valid': True, 'version': 0}}
Thread-209::DEBUG::2013-10-11 15:26:34,948::task::579::TaskManager.Task::(_updateState) Task=`fdb11005-0b0b-4357-9e1b-9d4fdb6af812`::moving from state preparing -> state finished
Thread-209::DEBUG::2013-10-11 15:26:34,949::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-209::DEBUG::2013-10-11 15:26:34,949::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-209::DEBUG::2013-10-11 15:26:34,949::task::974::TaskManager.Task::(_decref) Task=`fdb11005-0b0b-4357-9e1b-9d4fdb6af812`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:26:35,706::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:35,711::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000183907 s, 3.2 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:35,881::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:35,886::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000225904 s, 1.5 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:36,215::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:36,228::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:36,232::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000180648 s, 1.9 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:36,237::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000186913 s, 1.8 MB/s\n'; <rc> = 0
Thread-154::DEBUG::2013-10-11 15:26:45,718::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:45,723::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000233518 s, 2.5 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:45,892::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:45,897::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000265916 s, 1.3 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:46,255::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:46,266::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000165763 s, 2.0 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:46,266::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:46,273::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000270391 s, 1.3 MB/s\n'; <rc> = 0
Thread-215::DEBUG::2013-10-11 15:26:50,226::task::579::TaskManager.Task::(_updateState) Task=`55cbb082-c185-4703-8dae-7466e907299a`::moving from state init -> state preparing
Thread-215::INFO::2013-10-11 15:26:50,226::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-215::INFO::2013-10-11 15:26:50,226::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000233518', 'lastCheck': '4.5', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000165763', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000265916', 'lastCheck': '4.3', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000270391', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 0}}
Thread-215::DEBUG::2013-10-11 15:26:50,226::task::1168::TaskManager.Task::(prepare) Task=`55cbb082-c185-4703-8dae-7466e907299a`::finished: {'80e0d147-2e01-4499-a06b-697f9f0894ed': {'delay': '0.000233518', 'lastCheck': '4.5', 'code': 0, 'valid': True, 'version': 3}, 'afa8cb3b-2e93-4d6b-ad48-183cfc9f5732': {'delay': '0.000165763', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 0}, '26be0640-01a3-415d-82c9-0a92f2f84c3f': {'delay': '0.000265916', 'lastCheck': '4.3', 'code': 0, 'valid': True, 'version': 3}, '47b5e247-730c-413c-8413-655b0aeba82d': {'delay': '0.000270391', 'lastCheck': '4.0', 'code': 0, 'valid': True, 'version': 0}}
Thread-215::DEBUG::2013-10-11 15:26:50,227::task::579::TaskManager.Task::(_updateState) Task=`55cbb082-c185-4703-8dae-7466e907299a`::moving from state preparing -> state finished
Thread-215::DEBUG::2013-10-11 15:26:50,227::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-215::DEBUG::2013-10-11 15:26:50,227::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-215::DEBUG::2013-10-11 15:26:50,227::task::974::TaskManager.Task::(_decref) Task=`55cbb082-c185-4703-8dae-7466e907299a`::ref 0 aborting False
Thread-154::DEBUG::2013-10-11 15:26:55,731::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_orgrimmar/80e0d147-2e01-4499-a06b-697f9f0894ed/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-154::DEBUG::2013-10-11 15:26:55,737::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n595 bytes (595 B) copied, 0.000201614 s, 3.0 MB/s\n'; <rc> = 0
Thread-155::DEBUG::2013-10-11 15:26:55,904::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_stormwind/26be0640-01a3-415d-82c9-0a92f2f84c3f/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-155::DEBUG::2013-10-11 15:26:55,908::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n349 bytes (349 B) copied, 0.000256729 s, 1.4 MB/s\n'; <rc> = 0
Thread-156::DEBUG::2013-10-11 15:26:56,292::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_iso/afa8cb3b-2e93-4d6b-ad48-183cfc9f5732/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-156::DEBUG::2013-10-11 15:26:56,304::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n336 bytes (336 B) copied, 0.000276243 s, 1.2 MB/s\n'; <rc> = 0
Thread-161::DEBUG::2013-10-11 15:26:56,305::fileSD::239::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/192.168.0.1:_das0_export/47b5e247-730c-413c-8413-655b0aeba82d/dom_md/metadata bs=4096 count=1' (cwd None)
Thread-161::DEBUG::2013-10-11 15:26:56,312::fileSD::239::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n345 bytes (345 B) copied, 0.000297022 s, 1.2 MB/s\n'; <rc> = 0