Attachment 922110 Details for Bug 1124372 – vdsm log

vdsm log

vdsm.log (text/plain), 161.67 KB, created by Jiri Moskovcak on 2014-07-29 11:18:51 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jiri Moskovcak

Created: 2014-07-29 11:18:51 UTC

Size: 161.67 KB

patch

obsolete

>MainThread::INFO::2014-07-29 12:33:06,368::vdsm::131::vds::(run) (PID: 36036) I am the actual vdsm 4.16.1-0.gita4d9abf.el6 dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-29 12:33:06,368::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-29 12:33:06,369::threadPool::35::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-07-29 12:33:06,371::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::DEBUG::2014-07-29 12:33:06,428::multipath::150::Storage.Multipath::(isEnabled) multipath Defaulting to False
>MainThread::DEBUG::2014-07-29 12:33:06,428::multipath::168::Storage.Misc.excCmd::(setupMultipath) /usr/bin/sudo -n /bin/cp /tmp/tmpC9VZK8 /etc/multipath.conf (cwd None)
>MainThread::DEBUG::2014-07-29 12:33:06,437::multipath::168::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:33:06,438::multipath::174::Storage.Misc.excCmd::(setupMultipath) /usr/bin/sudo -n /sbin/multipath -F (cwd None)
>MainThread::DEBUG::2014-07-29 12:33:06,456::multipath::174::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:33:06,456::multipath::177::Storage.Misc.excCmd::(setupMultipath) /usr/bin/sudo -n /usr/bin/vdsm-tool service-reload multipathd (cwd None)
>MainThread::DEBUG::2014-07-29 12:33:06,639::multipath::177::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:33:06,639::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2014-07-29 12:33:06,754::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:33:06,755::hsm::442::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-29 12:33:06,758::hsm::474::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-29 12:33:06,758::hsm::475::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-29 12:33:06,758::hsm::477::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-29 12:33:06,760::hsm::520::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-29 12:33:06,760::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-29 12:33:06,764::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-29 12:33:06,764::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 12:33:06,822::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-29 12:33:06,823::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 12:33:06,823::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-29 12:33:06,823::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2014-07-29 12:33:06,845::task::595::Storage.TaskManager.Task::(_updateState) Task=`80091b34-f391-4966-9e47-dca7c5148a8b`::moving from state init -> state preparing
>storageRefresh::DEBUG::2014-07-29 12:33:06,845::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>MainThread::INFO::2014-07-29 12:33:06,845::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF object at 0x19e4e10>>)
>storageRefresh::DEBUG::2014-07-29 12:33:06,845::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>MainThread::INFO::2014-07-29 12:33:06,846::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-29 12:33:06,848::task::1191::Storage.TaskManager.Task::(prepare) Task=`80091b34-f391-4966-9e47-dca7c5148a8b`::finished: None
>MainThread::DEBUG::2014-07-29 12:33:06,849::task::595::Storage.TaskManager.Task::(_updateState) Task=`80091b34-f391-4966-9e47-dca7c5148a8b`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 12:33:06,849::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 12:33:06,849::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 12:33:06,849::task::993::Storage.TaskManager.Task::(_decref) Task=`80091b34-f391-4966-9e47-dca7c5148a8b`::ref 0 aborting False
>MainThread::INFO::2014-07-29 12:33:06,849::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-29 12:33:06,853::vmchannels::192::vds::(settimeout) Setting channels' timeout to 30 seconds.
>clientIFinit::DEBUG::2014-07-29 12:33:06,863::libvirtconnection::150::root::(get) trying to connect libvirt
>VM Channels Listener::INFO::2014-07-29 12:33:06,868::vmchannels::175::vds::(run) Starting VM channels listener thread.
>MainThread::DEBUG::2014-07-29 12:33:06,877::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <rpc.BindingXMLRPC.XmlDetector instance at 0x1b0cdd0>
>storageRefresh::DEBUG::2014-07-29 12:33:06,917::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:33:06,927::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:06,930::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:06,932::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:06,932::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:06,932::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:06,933::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>MainThread::DEBUG::2014-07-29 12:33:06,933::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <yajsonrpc.stompReactor.StompDetector instance at 0x1cd2368>
>storageRefresh::DEBUG::2014-07-29 12:33:06,936::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>JsonRpcServer::DEBUG::2014-07-29 12:33:06,936::__init__::498::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
>storageRefresh::DEBUG::2014-07-29 12:33:06,937::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Detector thread::DEBUG::2014-07-29 12:33:06,939::protocoldetector::68::vds.MultiProtocolAcceptor::(serve_forever) Acceptor running
>Detector thread::DEBUG::2014-07-29 12:33:06,952::protocoldetector::70::vds.MultiProtocolAcceptor::(serve_forever) Using required_size=11
>storageRefresh::DEBUG::2014-07-29 12:33:06,972::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:33:07,076::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:33:07,077::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:07,078::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:07,079::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:33:07,177::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:33:07,178::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:07,178::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags (cwd None)
>Detector thread::DEBUG::2014-07-29 12:33:07,189::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56653
>Detector thread::DEBUG::2014-07-29 12:33:07,189::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56653
>Detector thread::DEBUG::2014-07-29 12:33:07,189::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56653
>Detector thread::DEBUG::2014-07-29 12:33:07,189::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56653)
>Thread-13::DEBUG::2014-07-29 12:33:07,228::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-29 12:33:07,229::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-07-29 12:33:07,268::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:33:07,268::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:07,268::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:33:07,359::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:33:07,359::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:33:07,359::hsm::387::Storage.HSM::(storageRefresh) HSM is ready
>Detector thread::DEBUG::2014-07-29 12:33:08,242::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56654
>Detector thread::DEBUG::2014-07-29 12:33:08,243::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56654
>Detector thread::DEBUG::2014-07-29 12:33:08,243::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56654
>Detector thread::DEBUG::2014-07-29 12:33:08,243::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56654)
>Thread-14::DEBUG::2014-07-29 12:33:08,283::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-07-29 12:33:08,283::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>Thread-14::DEBUG::2014-07-29 12:33:08,335::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Detector thread::DEBUG::2014-07-29 12:33:08,343::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56655
>Detector thread::DEBUG::2014-07-29 12:33:08,343::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56655
>Detector thread::DEBUG::2014-07-29 12:33:08,343::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56655
>Detector thread::DEBUG::2014-07-29 12:33:08,343::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56655)
>Detector thread::DEBUG::2014-07-29 12:33:08,421::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56656
>Detector thread::DEBUG::2014-07-29 12:33:08,422::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56656
>Detector thread::DEBUG::2014-07-29 12:33:08,422::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56656
>Detector thread::DEBUG::2014-07-29 12:33:08,422::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56656)
>Thread-16::DEBUG::2014-07-29 12:33:08,462::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-07-29 12:33:08,462::task::595::Storage.TaskManager.Task::(_updateState) Task=`4996bef6-36da-4122-9804-1f6c4c2684ab`::moving from state init -> state preparing
>Thread-16::INFO::2014-07-29 12:33:08,462::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-16::INFO::2014-07-29 12:33:08,463::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-16::DEBUG::2014-07-29 12:33:08,463::task::1191::Storage.TaskManager.Task::(prepare) Task=`4996bef6-36da-4122-9804-1f6c4c2684ab`::finished: {'poollist': []}
>Thread-16::DEBUG::2014-07-29 12:33:08,463::task::595::Storage.TaskManager.Task::(_updateState) Task=`4996bef6-36da-4122-9804-1f6c4c2684ab`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-07-29 12:33:08,463::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-07-29 12:33:08,463::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-07-29 12:33:08,464::task::993::Storage.TaskManager.Task::(_decref) Task=`4996bef6-36da-4122-9804-1f6c4c2684ab`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:33:37,294::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56657
>Detector thread::DEBUG::2014-07-29 12:33:37,295::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56657
>Detector thread::DEBUG::2014-07-29 12:33:37,295::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56657
>Detector thread::DEBUG::2014-07-29 12:33:37,295::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56657)
>Thread-17::DEBUG::2014-07-29 12:33:37,335::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-07-29 12:33:37,335::task::595::Storage.TaskManager.Task::(_updateState) Task=`49b8c28d-654a-4c08-bfd9-c07285fcce80`::moving from state init -> state preparing
>Thread-17::INFO::2014-07-29 12:33:37,336::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-17::DEBUG::2014-07-29 12:33:37,336::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=new (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,357::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 12:33:37,357::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,367::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 12:33:37,368::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,410::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 12:33:37,411::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,435::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 12:33:37,436::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --discover (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,451::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 12:33:37,451::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=delete (cwd None)
>Thread-17::DEBUG::2014-07-29 12:33:37,463::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::INFO::2014-07-29 12:33:37,463::logUtils::47::dispatcher::(wrapper) Run and protect: discoverSendTargets, Return response: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-17::DEBUG::2014-07-29 12:33:37,464::task::1191::Storage.TaskManager.Task::(prepare) Task=`49b8c28d-654a-4c08-bfd9-c07285fcce80`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-17::DEBUG::2014-07-29 12:33:37,464::task::595::Storage.TaskManager.Task::(_updateState) Task=`49b8c28d-654a-4c08-bfd9-c07285fcce80`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-07-29 12:33:37,464::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-07-29 12:33:37,464::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-07-29 12:33:37,464::task::993::Storage.TaskManager.Task::(_decref) Task=`49b8c28d-654a-4c08-bfd9-c07285fcce80`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:33:39,846::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56659
>Detector thread::DEBUG::2014-07-29 12:33:39,846::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56659
>Detector thread::DEBUG::2014-07-29 12:33:39,847::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56659
>Detector thread::DEBUG::2014-07-29 12:33:39,847::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56659)
>Thread-18::DEBUG::2014-07-29 12:33:39,886::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-18::DEBUG::2014-07-29 12:33:39,886::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e4e90b4-da6d-4a08-9454-955447f5828f`::moving from state init -> state preparing
>Thread-18::INFO::2014-07-29 12:33:39,886::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-18::DEBUG::2014-07-29 12:33:39,886::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-18::DEBUG::2014-07-29 12:33:39,886::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-07-29 12:33:39,887::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-18::DEBUG::2014-07-29 12:33:39,887::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-07-29 12:33:39,887::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-18::DEBUG::2014-07-29 12:33:39,887::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>Thread-18::DEBUG::2014-07-29 12:33:39,897::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-07-29 12:33:39,897::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>Thread-18::DEBUG::2014-07-29 12:33:39,967::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-18::DEBUG::2014-07-29 12:33:39,968::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,968::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,968::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,968::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,968::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,969::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,969::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-07-29 12:33:39,969::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:39,971::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>Thread-18::DEBUG::2014-07-29 12:33:40,070::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-18::DEBUG::2014-07-29 12:33:40,071::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-18::DEBUG::2014-07-29 12:33:40,096::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvcreate --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --test --metadatasize 128m --metadatacopies 2 --metadataignore y (cwd None)
>Thread-18::DEBUG::2014-07-29 12:33:40,181::lvm::288::Storage.Misc.excCmd::(cmd) FAILED: <err> = "  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Please enter a physical volume path\n  Run `pvcreate --help' for more information.\n"; <rc> = 3
>Thread-18::DEBUG::2014-07-29 12:33:40,182::lvm::852::Storage.LVM::(testPVCreate) rc: 3, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Please enter a physical volume path', "  Run `pvcreate --help' for more information."], unusedDevs: set([]), usedDevs: set([])
>Thread-18::INFO::2014-07-29 12:33:40,183::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': []}
>Thread-18::DEBUG::2014-07-29 12:33:40,183::task::1191::Storage.TaskManager.Task::(prepare) Task=`0e4e90b4-da6d-4a08-9454-955447f5828f`::finished: {'devList': []}
>Thread-18::DEBUG::2014-07-29 12:33:40,183::task::595::Storage.TaskManager.Task::(_updateState) Task=`0e4e90b4-da6d-4a08-9454-955447f5828f`::moving from state preparing -> state finished
>Thread-18::DEBUG::2014-07-29 12:33:40,183::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-18::DEBUG::2014-07-29 12:33:40,184::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-07-29 12:33:40,184::task::993::Storage.TaskManager.Task::(_decref) Task=`0e4e90b4-da6d-4a08-9454-955447f5828f`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:33:40,198::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56660
>Detector thread::DEBUG::2014-07-29 12:33:40,199::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56660
>Detector thread::DEBUG::2014-07-29 12:33:40,199::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56660
>Detector thread::DEBUG::2014-07-29 12:33:40,199::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56660)
>Thread-19::DEBUG::2014-07-29 12:33:40,239::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-19::DEBUG::2014-07-29 12:33:40,239::task::595::Storage.TaskManager.Task::(_updateState) Task=`e78a407a-1f32-4d98-904b-a653c4e30ded`::moving from state init -> state preparing
>Thread-19::INFO::2014-07-29 12:33:40,239::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-19::DEBUG::2014-07-29 12:33:40,240::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=new (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,252::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-07-29 12:33:40,252::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,264::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-07-29 12:33:40,264::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,276::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-07-29 12:33:40,276::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,286::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-07-29 12:33:40,286::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --discover (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,321::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-07-29 12:33:40,322::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=delete (cwd None)
>Thread-19::DEBUG::2014-07-29 12:33:40,333::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::INFO::2014-07-29 12:33:40,334::logUtils::47::dispatcher::(wrapper) Run and protect: discoverSendTargets, Return response: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-19::DEBUG::2014-07-29 12:33:40,334::task::1191::Storage.TaskManager.Task::(prepare) Task=`e78a407a-1f32-4d98-904b-a653c4e30ded`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-19::DEBUG::2014-07-29 12:33:40,334::task::595::Storage.TaskManager.Task::(_updateState) Task=`e78a407a-1f32-4d98-904b-a653c4e30ded`::moving from state preparing -> state finished
>Thread-19::DEBUG::2014-07-29 12:33:40,334::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-19::DEBUG::2014-07-29 12:33:40,335::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-19::DEBUG::2014-07-29 12:33:40,335::task::993::Storage.TaskManager.Task::(_decref) Task=`e78a407a-1f32-4d98-904b-a653c4e30ded`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:33:40,344::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56662
>Detector thread::DEBUG::2014-07-29 12:33:40,344::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56662
>Detector thread::DEBUG::2014-07-29 12:33:40,344::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56662
>Detector thread::DEBUG::2014-07-29 12:33:40,344::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56662)
>Thread-20::DEBUG::2014-07-29 12:33:40,384::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-07-29 12:33:40,384::task::595::Storage.TaskManager.Task::(_updateState) Task=`5d9b34bc-8a0b-44b1-8ff5-79c6d0ec0fc3`::moving from state init -> state preparing
>Thread-20::INFO::2014-07-29 12:33:40,385::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '0', 'user': 'engine', 'password': '******', 'port': '3260', 'id': '00000000-0000-0000-0000-000000000000'}], options=None)
>Thread-20::DEBUG::2014-07-29 12:33:40,385::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 --op=new (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:40,397::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:40,397::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 -n node.session.auth.authmethod -v '****' --op=update (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:40,408::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:40,408::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 -n node.session.auth.username -v '****' --op=update (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:40,451::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:40,452::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 -n node.session.auth.password -v '****' --op=update (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:40,469::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:40,469::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 -l (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:41,753::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:41,754::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2009-02.com.example:for.all -I default -p 10.34.131.193:3260,1 -n node.startup -v manual --op=update (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:41,764::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:41,764::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-20::DEBUG::2014-07-29 12:33:41,765::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>Thread-20::DEBUG::2014-07-29 12:33:41,874::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-20::DEBUG::2014-07-29 12:33:41,874::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-20::DEBUG::2014-07-29 12:33:41,874::hsm::2390::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-20::DEBUG::2014-07-29 12:33:41,875::hsm::2446::Storage.HSM::(connectStorageServer) knownSDs: {}
>Thread-20::INFO::2014-07-29 12:33:41,875::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-20::DEBUG::2014-07-29 12:33:41,875::task::1191::Storage.TaskManager.Task::(prepare) Task=`5d9b34bc-8a0b-44b1-8ff5-79c6d0ec0fc3`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-20::DEBUG::2014-07-29 12:33:41,875::task::595::Storage.TaskManager.Task::(_updateState) Task=`5d9b34bc-8a0b-44b1-8ff5-79c6d0ec0fc3`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-07-29 12:33:41,875::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-20::DEBUG::2014-07-29 12:33:41,876::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-07-29 12:33:41,876::task::993::Storage.TaskManager.Task::(_decref) Task=`5d9b34bc-8a0b-44b1-8ff5-79c6d0ec0fc3`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:33:42,893::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56664
>Detector thread::DEBUG::2014-07-29 12:33:42,893::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56664
>Detector thread::DEBUG::2014-07-29 12:33:42,893::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56664
>Detector thread::DEBUG::2014-07-29 12:33:42,894::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56664)
>Thread-21::DEBUG::2014-07-29 12:33:42,933::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-21::DEBUG::2014-07-29 12:33:42,935::task::595::Storage.TaskManager.Task::(_updateState) Task=`25caa9b4-938f-4b62-b60e-28a2f444ae2f`::moving from state init -> state preparing
>Thread-21::INFO::2014-07-29 12:33:42,936::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-21::DEBUG::2014-07-29 12:33:42,936::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-21::DEBUG::2014-07-29 12:33:42,937::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-21::DEBUG::2014-07-29 12:33:42,937::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-21::DEBUG::2014-07-29 12:33:42,938::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-21::DEBUG::2014-07-29 12:33:42,938::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-21::DEBUG::2014-07-29 12:33:42,938::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>Thread-21::DEBUG::2014-07-29 12:33:42,954::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-21::DEBUG::2014-07-29 12:33:42,954::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>Thread-21::DEBUG::2014-07-29 12:33:42,984::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-07-29 12:33:42,985::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,985::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,985::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,985::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,985::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,986::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,986::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-21::DEBUG::2014-07-29 12:33:42,986::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:42,987::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>Thread-21::DEBUG::2014-07-29 12:33:43,096::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-07-29 12:33:43,096::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-21::DEBUG::2014-07-29 12:33:43,126::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvcreate --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/33000000100000001 (cwd None)
>Thread-21::DEBUG::2014-07-29 12:33:43,243::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n'; <rc> = 0
>Thread-21::INFO::2014-07-29 12:33:43,244::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'free', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '4096', 'pvUUID': '', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-21::DEBUG::2014-07-29 12:33:43,244::task::1191::Storage.TaskManager.Task::(prepare) Task=`25caa9b4-938f-4b62-b60e-28a2f444ae2f`::finished: {'devList': [{'status': 'free', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'logicalblocksize': '512', 'devtype': 'iSCSI', 'physicalblocksize': '4096', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK', 'vendorID': 'IET', 'capacity': '52428800000', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'pvUUID': ''}]}
>Thread-21::DEBUG::2014-07-29 12:33:43,244::task::595::Storage.TaskManager.Task::(_updateState) Task=`25caa9b4-938f-4b62-b60e-28a2f444ae2f`::moving from state preparing -> state finished
>Thread-21::DEBUG::2014-07-29 12:33:43,244::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21::DEBUG::2014-07-29 12:33:43,245::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21::DEBUG::2014-07-29 12:33:43,245::task::993::Storage.TaskManager.Task::(_decref) Task=`25caa9b4-938f-4b62-b60e-28a2f444ae2f`::ref 0 aborting False
>MainThread::DEBUG::2014-07-29 12:35:58,338::vdsm::58::vds::(sigtermHandler) Received signal 15
>MainThread::DEBUG::2014-07-29 12:35:58,338::protocoldetector::133::vds.MultiProtocolAcceptor::(stop) Stopping Acceptor
>MainThread::INFO::2014-07-29 12:35:58,340::__init__::557::jsonrpc.JsonRpcServer::(stop) Stopping JsonRPC Server
>Detector thread::DEBUG::2014-07-29 12:35:58,340::protocoldetector::104::vds.MultiProtocolAcceptor::(_cleanup) Cleaning Acceptor
>MainThread::INFO::2014-07-29 12:35:58,341::vmchannels::188::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-29 12:35:58,341::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-07-29 12:35:58,341::task::595::Storage.TaskManager.Task::(_updateState) Task=`d932b57b-5a39-4f29-bbcc-4c1a9dcfff90`::moving from state init -> state preparing
>MainThread::INFO::2014-07-29 12:35:58,341::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-07-29 12:35:58,342::storageServer::706::Storage.ConnectionMonitor::(_monitorConnections) Monitoring stopped
>MainThread::INFO::2014-07-29 12:35:58,358::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::DEBUG::2014-07-29 12:35:58,359::taskManager::90::Storage.TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-07-29 12:35:58,359::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-07-29 12:35:58,359::task::1191::Storage.TaskManager.Task::(prepare) Task=`d932b57b-5a39-4f29-bbcc-4c1a9dcfff90`::finished: None
>MainThread::DEBUG::2014-07-29 12:35:58,359::task::595::Storage.TaskManager.Task::(_updateState) Task=`d932b57b-5a39-4f29-bbcc-4c1a9dcfff90`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 12:35:58,359::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 12:35:58,359::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 12:35:58,359::task::993::Storage.TaskManager.Task::(_decref) Task=`d932b57b-5a39-4f29-bbcc-4c1a9dcfff90`::ref 0 aborting False
>MainThread::INFO::2014-07-29 12:35:58,359::vdsm::137::vds::(run) VDSM main thread ended. Waiting for 16 other threads...
>MainThread::INFO::2014-07-29 12:35:58,359::vdsm::141::vds::(run) <_MainThread(MainThread, started 140634429019904)>
>MainThread::INFO::2014-07-29 12:35:58,359::vdsm::141::vds::(run) <Thread(libvirtEventLoop, started daemon 140634336589568)>
>MainThread::INFO::2014-07-29 12:35:58,359::vdsm::141::vds::(run) <WorkerThread(Thread-5, started daemon 140633939375872)>
>MainThread::INFO::2014-07-29 12:35:58,359::vdsm::141::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140632890783488)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-10, started daemon 140633886926592)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-9, started daemon 140633897416448)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-6, started daemon 140633928886016)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-8, started daemon 140633907906304)>
>MainThread::INFO::2014-07-29 12:35:58,360::vmchannels::188::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <Listener(VM Channels Listener, started daemon 140633180198656)>
>MainThread::INFO::2014-07-29 12:35:58,360::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <MomThread(MOM, started 140633201178368)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <HostMonitor(HostMonitor, started daemon 140633190688512)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-7, started daemon 140633918396160)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-4, started daemon 140634294630144)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <GuestManager(GuestManager, started daemon 140632922253056)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-3, started daemon 140634305120000)>
>MainThread::INFO::2014-07-29 12:35:58,360::vdsm::141::vds::(run) <WorkerThread(Thread-2, started daemon 140634315609856)>
>MainThread::INFO::2014-07-29 12:35:58,361::vdsm::141::vds::(run) <WorkerThread(Thread-1, started daemon 140634326099712)>
>VM Channels Listener::INFO::2014-07-29 12:35:59,048::vmchannels::183::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-07-29 12:36:10,508::vdsm::131::vds::(run) (PID: 36836) I am the actual vdsm 4.16.1-0.gita4d9abf.el6 dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-29 12:36:10,509::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-29 12:36:10,509::threadPool::35::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-07-29 12:36:10,512::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::WARNING::2014-07-29 12:36:10,513::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-29 12:36:10,554::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-29 12:36:10,563::multipath::141::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-29 12:36:10,563::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2014-07-29 12:36:10,671::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:36:10,671::hsm::442::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-29 12:36:10,675::hsm::474::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-29 12:36:10,675::hsm::475::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-29 12:36:10,675::hsm::477::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-29 12:36:10,676::hsm::520::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-29 12:36:10,677::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-29 12:36:10,680::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-29 12:36:10,680::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 12:36:10,729::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-29 12:36:10,729::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 12:36:10,732::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>MainThread::DEBUG::2014-07-29 12:36:10,733::task::595::Storage.TaskManager.Task::(_updateState) Task=`1aee8a04-4e51-4af7-960f-1b787e81edca`::moving from state init -> state preparing
>storageRefresh::DEBUG::2014-07-29 12:36:10,733::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::INFO::2014-07-29 12:36:10,733::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF object at 0x2cbac10>>)
>MainThread::INFO::2014-07-29 12:36:10,736::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-29 12:36:10,737::task::1191::Storage.TaskManager.Task::(prepare) Task=`1aee8a04-4e51-4af7-960f-1b787e81edca`::finished: None
>MainThread::DEBUG::2014-07-29 12:36:10,737::task::595::Storage.TaskManager.Task::(_updateState) Task=`1aee8a04-4e51-4af7-960f-1b787e81edca`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 12:36:10,737::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 12:36:10,737::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 12:36:10,737::task::993::Storage.TaskManager.Task::(_decref) Task=`1aee8a04-4e51-4af7-960f-1b787e81edca`::ref 0 aborting False
>MainThread::INFO::2014-07-29 12:36:10,738::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-29 12:36:10,740::vmchannels::192::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-29 12:36:10,745::vmchannels::175::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-29 12:36:10,745::libvirtconnection::150::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-29 12:36:10,748::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 12:36:10,749::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>MainThread::DEBUG::2014-07-29 12:36:10,766::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <rpc.BindingXMLRPC.XmlDetector instance at 0x2e35128>
>storageRefresh::DEBUG::2014-07-29 12:36:10,830::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 12:36:10,831::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <yajsonrpc.stompReactor.StompDetector instance at 0x2f6c5a8>
>storageRefresh::DEBUG::2014-07-29 12:36:10,832::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:10,832::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>JsonRpcServer::DEBUG::2014-07-29 12:36:10,833::__init__::498::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
>Detector thread::DEBUG::2014-07-29 12:36:10,834::protocoldetector::68::vds.MultiProtocolAcceptor::(serve_forever) Acceptor running
>storageRefresh::DEBUG::2014-07-29 12:36:10,835::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Detector thread::DEBUG::2014-07-29 12:36:10,835::protocoldetector::70::vds.MultiProtocolAcceptor::(serve_forever) Using required_size=11
>storageRefresh::DEBUG::2014-07-29 12:36:10,835::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:10,844::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:10,844::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:10,866::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 12:36:10,867::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:10,969::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:36:11,120::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:36:11,120::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:11,121::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:11,121::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:36:11,218::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:36:11,218::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:11,219::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags (cwd None)
>storageRefresh::DEBUG::2014-07-29 12:36:11,316::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:36:11,316::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:11,316::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -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)
>Detector thread::DEBUG::2014-07-29 12:36:11,373::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56666
>Detector thread::DEBUG::2014-07-29 12:36:11,374::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56666
>Detector thread::DEBUG::2014-07-29 12:36:11,374::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56666
>Detector thread::DEBUG::2014-07-29 12:36:11,374::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56666)
>Thread-13::DEBUG::2014-07-29 12:36:11,414::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-29 12:36:11,414::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-07-29 12:36:11,415::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 12:36:11,416::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 12:36:11,416::hsm::387::Storage.HSM::(storageRefresh) HSM is ready
>Detector thread::DEBUG::2014-07-29 12:36:12,425::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56667
>Detector thread::DEBUG::2014-07-29 12:36:12,425::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56667
>Detector thread::DEBUG::2014-07-29 12:36:12,425::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56667
>Detector thread::DEBUG::2014-07-29 12:36:12,425::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56667)
>Thread-14::DEBUG::2014-07-29 12:36:12,464::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-07-29 12:36:12,471::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Detector thread::DEBUG::2014-07-29 12:36:12,481::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56668
>Detector thread::DEBUG::2014-07-29 12:36:12,482::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56668
>Detector thread::DEBUG::2014-07-29 12:36:12,482::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56668
>Detector thread::DEBUG::2014-07-29 12:36:12,482::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56668)
>Thread-15::DEBUG::2014-07-29 12:36:12,521::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
>Thread-15::DEBUG::2014-07-29 12:36:12,593::utils::738::root::(execCmd) /sbin/ip route show to 0.0.0.0/0 table all (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,600::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,623::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/bonding_masters (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,635::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,635::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,646::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,665::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,676::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,677::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,688::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,689::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,700::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,702::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,713::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,726::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,737::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,738::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/pTbitgAhWbdS0JL/bonding/mode (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,749::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,755::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/bonding_masters (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,794::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,805::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/sbin/dmidecode -s system-uuid (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,818::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,834::caps::614::root::(get) VirtioRNG DISABLED: libvirt version 0.10.2-29.el6_5.9 required >= 0.10.2-31
>Thread-15::DEBUG::2014-07-29 12:36:12,834::utils::738::root::(execCmd) numactl --hardware (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,839::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,840::utils::738::root::(execCmd) sysctl -n -e kernel.numa_balancing (cwd None)
>Thread-15::DEBUG::2014-07-29 12:36:12,844::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-29 12:36:12,850::BindingXMLRPC::1134::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:431ee67f14b2'}], 'FC': []}, 'packages2': {'kernel': {'release': '431.el6.x86_64', 'buildtime': 1385086509.0, 'version': '2.6.32'}, 'spice-server': {'release': '6.el6_5.2', 'buildtime': 1402324637L, 'version': '0.12.4'}, 'vdsm': {'release': '0.gita4d9abf.el6', 'buildtime': 1406372956L, 'version': '4.16.1'}, 'qemu-kvm': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'libvirt': {'release': '29.el6_5.9', 'buildtime': 1402404612L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'mom': {'release': '2.el6', 'buildtime': 1403794344L, 'version': '0.4.1'}}, 'numaNodeDistance': {'0': [10]}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1220 V2 @ 3.10GHz', 'hooks': {'before_vm_start': {'50_hostedengine': {'md5': '45dde62155b5412eafbfff5ef265acc2'}}}, 'cpuSockets': '1', 'vmTypes': ['kvm'], 'selinux': {'mode': '1'}, 'kdumpStatus': 0, 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'bridges': {}, 'uuid': '30303734-3536-5A43-3133-343330305746_a4:5d:36:11:e4:80', 'lastClientIface': 'lo', 'nics': {'eth1': {'addr': '', 'cfg': {'UUID': 'f4c325df-ca04-4813-98ae-e1bf9e82a0bb', 'NM_CONTROLLED': 'yes', 'HWADDR': 'A4:5D:36:11:E4:81', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth1', 'TYPE': 'Ethernet', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': 'a4:5d:36:11:e4:81', 'speed': 0}, 'eth0': {'addr': '10.34.63.108', 'cfg': {'IPV6INIT': 'no', 'NM_CONTROLLED': 'yes', 'MTU': '1500', 'HWADDR': 'A4:5D:36:11:E4:80', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth0', 'TYPE': 'Ethernet', 'ONBOOT': 'yes', 'UUID': '5ea6e70f-cacd-47a5-8171-9257b8384183'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '255.255.252.0', 'ipv4addrs': ['10.34.63.108/22'], 'hwaddr': 'a4:5d:36:11:e4:80', 'speed': 1000}}, 'software_revision': '0', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], '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,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:431ee67f14b2', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], 'autoNumaBalancing': 2, 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '00:00:00:00:00:00', 'slaves': [], 'opts': {}}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.16', 'memSize': '15782', 'cpuSpeed': '2128.000', 'numaNodes': {u'0': {'totalMemory': '15782', 'cpus': [0, 1, 2, 3]}}, 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'cpuThreads': '4', 'emulatedMachines': [u'rhel6.5.0', u'pc', u'rhel6.4.0', 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': '5.el6.centos.11.1', 'version': '6', 'name': 'RHEL'}, 'lastClient': '127.0.0.1'}}
>Detector thread::DEBUG::2014-07-29 12:36:12,945::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56669
>Detector thread::DEBUG::2014-07-29 12:36:12,945::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56669
>Detector thread::DEBUG::2014-07-29 12:36:12,945::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56669
>Detector thread::DEBUG::2014-07-29 12:36:12,945::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56669)
>Thread-16::DEBUG::2014-07-29 12:36:12,985::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call addNetwork with ('ovirtmgmt', '', '', ['eth0'], {'blockingdhcp': 'true', 'bootproto': 'dhcp', 'force': 'False', 'ONBOOT': 'yes', 'bridged': 'True'}) {}
>Thread-16::ERROR::2014-07-29 12:36:13,009::BindingXMLRPC::1137::vds::(wrapper) libvirt error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/rpc/BindingXMLRPC.py", line 1130, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/rpc/BindingXMLRPC.py", line 541, in addNetwork
>    return api.addNetwork(bridge, vlan, bond, nics, options)
>  File "/usr/share/vdsm/API.py", line 1361, in addNetwork
>    supervdsm.getProxy().addNetwork(bridge, options)
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in addNetwork
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 740, in _callmethod
>    raise convert_to_error(kind, result)
>libvirtError: internal error client socket is closed
>Detector thread::DEBUG::2014-07-29 12:37:17,585::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56670
>Detector thread::DEBUG::2014-07-29 12:37:17,585::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56670
>Detector thread::DEBUG::2014-07-29 12:37:17,585::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56670
>Detector thread::DEBUG::2014-07-29 12:37:17,586::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56670)
>Detector thread::DEBUG::2014-07-29 12:40:12,671::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56671
>Detector thread::DEBUG::2014-07-29 12:40:12,676::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56671
>Detector thread::DEBUG::2014-07-29 12:40:12,677::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56671
>Detector thread::DEBUG::2014-07-29 12:40:12,677::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56671)
>Thread-18::DEBUG::2014-07-29 12:40:12,711::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-18::ERROR::2014-07-29 12:40:12,715::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-18::DEBUG::2014-07-29 12:40:12,721::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:13,731::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56672
>Detector thread::DEBUG::2014-07-29 12:40:13,731::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56672
>Detector thread::DEBUG::2014-07-29 12:40:13,731::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56672
>Detector thread::DEBUG::2014-07-29 12:40:13,732::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56672)
>Thread-19::DEBUG::2014-07-29 12:40:13,770::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-19::ERROR::2014-07-29 12:40:13,771::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-19::DEBUG::2014-07-29 12:40:13,771::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:14,781::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56673
>Detector thread::DEBUG::2014-07-29 12:40:14,781::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56673
>Detector thread::DEBUG::2014-07-29 12:40:14,781::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56673
>Detector thread::DEBUG::2014-07-29 12:40:14,781::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56673)
>Thread-20::DEBUG::2014-07-29 12:40:14,820::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-20::ERROR::2014-07-29 12:40:14,821::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-20::DEBUG::2014-07-29 12:40:14,821::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:15,831::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56674
>Detector thread::DEBUG::2014-07-29 12:40:15,831::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56674
>Detector thread::DEBUG::2014-07-29 12:40:15,831::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56674
>Detector thread::DEBUG::2014-07-29 12:40:15,831::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56674)
>Thread-21::DEBUG::2014-07-29 12:40:15,870::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-21::ERROR::2014-07-29 12:40:15,871::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-21::DEBUG::2014-07-29 12:40:15,871::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:16,881::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56675
>Detector thread::DEBUG::2014-07-29 12:40:16,881::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56675
>Detector thread::DEBUG::2014-07-29 12:40:16,881::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56675
>Detector thread::DEBUG::2014-07-29 12:40:16,881::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56675)
>Thread-22::DEBUG::2014-07-29 12:40:16,920::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-22::ERROR::2014-07-29 12:40:16,921::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-22::DEBUG::2014-07-29 12:40:16,921::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:17,931::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56676
>Detector thread::DEBUG::2014-07-29 12:40:17,931::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56676
>Detector thread::DEBUG::2014-07-29 12:40:17,931::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56676
>Detector thread::DEBUG::2014-07-29 12:40:17,931::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56676)
>Thread-23::DEBUG::2014-07-29 12:40:17,970::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-23::ERROR::2014-07-29 12:40:17,971::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-23::DEBUG::2014-07-29 12:40:17,971::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:18,981::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56677
>Detector thread::DEBUG::2014-07-29 12:40:18,981::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56677
>Detector thread::DEBUG::2014-07-29 12:40:18,981::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56677
>Detector thread::DEBUG::2014-07-29 12:40:18,981::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56677)
>Thread-24::DEBUG::2014-07-29 12:40:19,020::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-24::ERROR::2014-07-29 12:40:19,021::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-24::DEBUG::2014-07-29 12:40:19,021::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:20,030::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56678
>Detector thread::DEBUG::2014-07-29 12:40:20,031::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56678
>Detector thread::DEBUG::2014-07-29 12:40:20,031::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56678
>Detector thread::DEBUG::2014-07-29 12:40:20,031::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56678)
>Thread-25::DEBUG::2014-07-29 12:40:20,070::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-25::ERROR::2014-07-29 12:40:20,071::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-25::DEBUG::2014-07-29 12:40:20,071::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:21,081::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56679
>Detector thread::DEBUG::2014-07-29 12:40:21,081::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56679
>Detector thread::DEBUG::2014-07-29 12:40:21,081::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56679
>Detector thread::DEBUG::2014-07-29 12:40:21,081::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56679)
>Thread-26::DEBUG::2014-07-29 12:40:21,120::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-26::ERROR::2014-07-29 12:40:21,121::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-26::DEBUG::2014-07-29 12:40:21,121::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:22,131::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56680
>Detector thread::DEBUG::2014-07-29 12:40:22,131::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56680
>Detector thread::DEBUG::2014-07-29 12:40:22,152::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56680
>Detector thread::DEBUG::2014-07-29 12:40:22,153::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56680)
>Thread-27::DEBUG::2014-07-29 12:40:22,170::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-27::ERROR::2014-07-29 12:40:22,171::API::1218::vds::(getHardwareInfo) failed to retrieve hardware info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1215, in getHardwareInfo
>    hw = supervdsm.getProxy().getHardwareInfo()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getHardwareInfo
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-27::DEBUG::2014-07-29 12:40:22,171::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Failed to read hardware information', 'code': 57}}
>Detector thread::DEBUG::2014-07-29 12:40:23,182::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56681
>Detector thread::DEBUG::2014-07-29 12:40:23,182::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56681
>Detector thread::DEBUG::2014-07-29 12:40:23,182::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56681
>Detector thread::DEBUG::2014-07-29 12:40:23,182::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56681)
>Detector thread::DEBUG::2014-07-29 12:40:23,244::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56682
>Detector thread::DEBUG::2014-07-29 12:40:23,245::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56682
>Detector thread::DEBUG::2014-07-29 12:40:23,245::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56682
>Detector thread::DEBUG::2014-07-29 12:40:23,245::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56682)
>Thread-29::DEBUG::2014-07-29 12:40:23,285::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-29::DEBUG::2014-07-29 12:40:23,285::task::595::Storage.TaskManager.Task::(_updateState) Task=`8495737e-7498-44c1-a22f-3c673068db3c`::moving from state init -> state preparing
>Thread-29::INFO::2014-07-29 12:40:23,285::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-29::INFO::2014-07-29 12:40:23,285::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-29::DEBUG::2014-07-29 12:40:23,286::task::1191::Storage.TaskManager.Task::(prepare) Task=`8495737e-7498-44c1-a22f-3c673068db3c`::finished: {'poollist': []}
>Thread-29::DEBUG::2014-07-29 12:40:23,286::task::595::Storage.TaskManager.Task::(_updateState) Task=`8495737e-7498-44c1-a22f-3c673068db3c`::moving from state preparing -> state finished
>Thread-29::DEBUG::2014-07-29 12:40:23,286::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-29::DEBUG::2014-07-29 12:40:23,286::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-29::DEBUG::2014-07-29 12:40:23,286::task::993::Storage.TaskManager.Task::(_decref) Task=`8495737e-7498-44c1-a22f-3c673068db3c`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:40:43,394::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56683
>Detector thread::DEBUG::2014-07-29 12:40:43,394::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56683
>Detector thread::DEBUG::2014-07-29 12:40:43,408::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56683
>Detector thread::DEBUG::2014-07-29 12:40:43,408::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56683)
>Thread-30::DEBUG::2014-07-29 12:40:43,435::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-30::DEBUG::2014-07-29 12:40:43,435::task::595::Storage.TaskManager.Task::(_updateState) Task=`a2561691-d4d5-4210-b4a1-b9395a4a5760`::moving from state init -> state preparing
>Thread-30::INFO::2014-07-29 12:40:43,435::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-30::DEBUG::2014-07-29 12:40:43,436::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=new (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,455::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::DEBUG::2014-07-29 12:40:43,456::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,466::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::DEBUG::2014-07-29 12:40:43,467::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,477::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::DEBUG::2014-07-29 12:40:43,478::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,488::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::DEBUG::2014-07-29 12:40:43,489::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --discover (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,508::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::DEBUG::2014-07-29 12:40:43,508::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=delete (cwd None)
>Thread-30::DEBUG::2014-07-29 12:40:43,519::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-30::INFO::2014-07-29 12:40:43,520::logUtils::47::dispatcher::(wrapper) Run and protect: discoverSendTargets, Return response: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-30::DEBUG::2014-07-29 12:40:43,520::task::1191::Storage.TaskManager.Task::(prepare) Task=`a2561691-d4d5-4210-b4a1-b9395a4a5760`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-30::DEBUG::2014-07-29 12:40:43,520::task::595::Storage.TaskManager.Task::(_updateState) Task=`a2561691-d4d5-4210-b4a1-b9395a4a5760`::moving from state preparing -> state finished
>Thread-30::DEBUG::2014-07-29 12:40:43,520::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-30::DEBUG::2014-07-29 12:40:43,520::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-30::DEBUG::2014-07-29 12:40:43,520::task::993::Storage.TaskManager.Task::(_decref) Task=`a2561691-d4d5-4210-b4a1-b9395a4a5760`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 12:40:44,522::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56685
>Detector thread::DEBUG::2014-07-29 12:40:44,522::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56685
>Detector thread::DEBUG::2014-07-29 12:40:44,523::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56685
>Detector thread::DEBUG::2014-07-29 12:40:44,523::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56685)
>Thread-31::DEBUG::2014-07-29 12:40:44,562::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-31::DEBUG::2014-07-29 12:40:44,562::task::595::Storage.TaskManager.Task::(_updateState) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::moving from state init -> state preparing
>Thread-31::INFO::2014-07-29 12:40:44,562::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-31::DEBUG::2014-07-29 12:40:44,562::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-31::DEBUG::2014-07-29 12:40:44,563::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-31::DEBUG::2014-07-29 12:40:44,563::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-31::DEBUG::2014-07-29 12:40:44,563::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-31::DEBUG::2014-07-29 12:40:44,563::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-31::DEBUG::2014-07-29 12:40:44,563::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>Thread-31::DEBUG::2014-07-29 12:40:44,577::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-31::DEBUG::2014-07-29 12:40:44,578::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>Thread-31::DEBUG::2014-07-29 12:40:44,666::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-07-29 12:40:44,667::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,667::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,667::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,667::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,668::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,668::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,668::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-31::DEBUG::2014-07-29 12:40:44,668::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-31::DEBUG::2014-07-29 12:40:44,670::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>Thread-31::DEBUG::2014-07-29 12:40:44,801::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-07-29 12:40:44,801::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-31::ERROR::2014-07-29 12:40:44,802::task::866::Storage.TaskManager.Task::(_setError) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 873, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 1948, in getDeviceList
>    devices = self._getDeviceList(storageType)
>  File "/usr/share/vdsm/storage/hsm.py", line 1980, in _getDeviceList
>    for dev in multipath.pathListIter(guids):
>  File "/usr/share/vdsm/storage/multipath.py", line 254, in pathListIter
>    pathStatuses = devicemapper.getPathsStatus()
>  File "/usr/share/vdsm/storage/devicemapper.py", line 177, in getPathsStatus
>    return getProxy().getPathsStatus()
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in getPathsStatus
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 722, in _callmethod
>    self._connect()
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 709, in _connect
>    conn = self._Client(self._token.address, authkey=self._authkey)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 143, in Client
>    c = SocketClient(address)
>  File "/usr/lib64/python2.6/multiprocessing/connection.py", line 263, in SocketClient
>    s.connect(address)
>  File "<string>", line 1, in connect
>error: [Errno 2] No such file or directory
>Thread-31::DEBUG::2014-07-29 12:40:44,804::task::885::Storage.TaskManager.Task::(_run) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::Task._run: 5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba (3,) {} failed - stopping task
>Thread-31::DEBUG::2014-07-29 12:40:44,804::task::1217::Storage.TaskManager.Task::(stop) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::stopping in state preparing (force False)
>Thread-31::DEBUG::2014-07-29 12:40:44,804::task::993::Storage.TaskManager.Task::(_decref) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::ref 1 aborting True
>Thread-31::INFO::2014-07-29 12:40:44,804::task::1171::Storage.TaskManager.Task::(prepare) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::aborting: Task is aborted: u'[Errno 2] No such file or directory' - code 100
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::1176::Storage.TaskManager.Task::(prepare) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::Prepare: aborted: [Errno 2] No such file or directory
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::993::Storage.TaskManager.Task::(_decref) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::ref 0 aborting True
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::928::Storage.TaskManager.Task::(_doAbort) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::Task._doAbort: force False
>Thread-31::DEBUG::2014-07-29 12:40:44,805::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::595::Storage.TaskManager.Task::(_updateState) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::moving from state preparing -> state aborting
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::550::Storage.TaskManager.Task::(__state_aborting) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::_aborting: recover policy none
>Thread-31::DEBUG::2014-07-29 12:40:44,805::task::595::Storage.TaskManager.Task::(_updateState) Task=`5ea7ebc0-0161-4cec-ad3a-4bc44f5c85ba`::moving from state aborting -> state failed
>Thread-31::DEBUG::2014-07-29 12:40:44,806::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-31::DEBUG::2014-07-29 12:40:44,806::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-31::ERROR::2014-07-29 12:40:44,806::dispatcher::79::Storage.Dispatcher::(wrapper) [Errno 2] No such file or directory
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
>    result = ctask.prepare(func, *args, **kwargs)
>  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
>    return m(self, *a, **kw)
>  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
>    raise self.error
>error: [Errno 2] No such file or directory
>MainThread::DEBUG::2014-07-29 13:01:01,243::vdsm::58::vds::(sigtermHandler) Received signal 15
>MainThread::DEBUG::2014-07-29 13:01:01,250::protocoldetector::133::vds.MultiProtocolAcceptor::(stop) Stopping Acceptor
>MainThread::INFO::2014-07-29 13:01:01,252::__init__::557::jsonrpc.JsonRpcServer::(stop) Stopping JsonRPC Server
>Detector thread::DEBUG::2014-07-29 13:01:01,252::protocoldetector::104::vds.MultiProtocolAcceptor::(_cleanup) Cleaning Acceptor
>MainThread::INFO::2014-07-29 13:01:01,253::vmchannels::188::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-29 13:01:01,253::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-07-29 13:01:01,254::task::595::Storage.TaskManager.Task::(_updateState) Task=`fd240b9f-b8d5-4dc1-9db3-7b34c698d2a6`::moving from state init -> state preparing
>MainThread::INFO::2014-07-29 13:01:01,254::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-07-29 13:01:01,255::storageServer::706::Storage.ConnectionMonitor::(_monitorConnections) Monitoring stopped
>VM Channels Listener::INFO::2014-07-29 13:01:01,318::vmchannels::183::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-07-29 13:01:01,334::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::DEBUG::2014-07-29 13:01:01,334::taskManager::90::Storage.TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-07-29 13:01:01,334::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-07-29 13:01:01,334::task::1191::Storage.TaskManager.Task::(prepare) Task=`fd240b9f-b8d5-4dc1-9db3-7b34c698d2a6`::finished: None
>MainThread::DEBUG::2014-07-29 13:01:01,334::task::595::Storage.TaskManager.Task::(_updateState) Task=`fd240b9f-b8d5-4dc1-9db3-7b34c698d2a6`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 13:01:01,334::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 13:01:01,335::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 13:01:01,335::task::993::Storage.TaskManager.Task::(_decref) Task=`fd240b9f-b8d5-4dc1-9db3-7b34c698d2a6`::ref 0 aborting False
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::137::vds::(run) VDSM main thread ended. Waiting for 11 other threads...
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <_MainThread(MainThread, started 140460119774976)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <Thread(libvirtEventLoop, started daemon 140460027344640)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-3, started daemon 140459791873792)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-8, started daemon 140459739424512)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-7, started daemon 140459749914368)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-6, started daemon 140459760404224)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-10, started daemon 140459378730752)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-9, started daemon 140459389220608)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-1, started daemon 140460016854784)>
>MainThread::INFO::2014-07-29 13:01:01,335::vdsm::141::vds::(run) <WorkerThread(Thread-5, started daemon 140459770894080)>
>MainThread::INFO::2014-07-29 13:01:01,336::vdsm::141::vds::(run) <WorkerThread(Thread-4, started daemon 140459781383936)>
>MainThread::INFO::2014-07-29 13:01:01,336::vdsm::141::vds::(run) <WorkerThread(Thread-2, started daemon 140460006364928)>
>MainThread::INFO::2014-07-29 13:01:04,858::vdsm::131::vds::(run) (PID: 37607) I am the actual vdsm 4.16.1-1.git13255aa.el6 dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-29 13:01:04,859::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-29 13:01:04,859::threadPool::35::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-07-29 13:01:04,861::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::WARNING::2014-07-29 13:01:04,861::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-29 13:01:04,902::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-29 13:01:04,917::multipath::141::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-29 13:01:04,917::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2014-07-29 13:01:05,028::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 13:01:05,029::hsm::442::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-29 13:01:05,031::hsm::474::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-29 13:01:05,031::hsm::475::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-29 13:01:05,031::hsm::477::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-29 13:01:05,032::hsm::520::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-29 13:01:05,032::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-29 13:01:05,035::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-29 13:01:05,035::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 13:01:05,076::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-29 13:01:05,077::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 13:01:05,077::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-29 13:01:05,077::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2014-07-29 13:01:05,080::task::595::Storage.TaskManager.Task::(_updateState) Task=`bca78e80-49d7-49ff-ae9b-82cd0c5c5742`::moving from state init -> state preparing
>MainThread::INFO::2014-07-29 13:01:05,084::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF object at 0x27c6c50>>)
>MainThread::INFO::2014-07-29 13:01:05,085::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-29 13:01:05,085::task::1191::Storage.TaskManager.Task::(prepare) Task=`bca78e80-49d7-49ff-ae9b-82cd0c5c5742`::finished: None
>MainThread::DEBUG::2014-07-29 13:01:05,085::task::595::Storage.TaskManager.Task::(_updateState) Task=`bca78e80-49d7-49ff-ae9b-82cd0c5c5742`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 13:01:05,085::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 13:01:05,085::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 13:01:05,085::task::993::Storage.TaskManager.Task::(_decref) Task=`bca78e80-49d7-49ff-ae9b-82cd0c5c5742`::ref 0 aborting False
>MainThread::INFO::2014-07-29 13:01:05,086::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-29 13:01:05,087::vmchannels::192::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-29 13:01:05,091::vmchannels::175::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-29 13:01:05,092::libvirtconnection::150::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-29 13:01:05,094::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 13:01:05,094::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>MainThread::DEBUG::2014-07-29 13:01:05,109::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <rpc.BindingXMLRPC.XmlDetector instance at 0x2940098>
>MainThread::DEBUG::2014-07-29 13:01:05,162::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <yajsonrpc.stompReactor.StompDetector instance at 0x7f8e7c09f680>
>JsonRpcServer::DEBUG::2014-07-29 13:01:05,164::__init__::498::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
>Detector thread::DEBUG::2014-07-29 13:01:05,166::protocoldetector::68::vds.MultiProtocolAcceptor::(serve_forever) Acceptor running
>Detector thread::DEBUG::2014-07-29 13:01:05,173::protocoldetector::70::vds.MultiProtocolAcceptor::(serve_forever) Using required_size=11
>storageRefresh::DEBUG::2014-07-29 13:01:05,197::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:01:05,198::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,199::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,200::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,200::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,201::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,202::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,203::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 13:01:05,204::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,211::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:01:05,331::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:01:05,334::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,336::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,336::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:01:05,434::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:01:05,435::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,435::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:01:05,527::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:01:05,527::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,527::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:01:05,619::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:01:05,619::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:01:05,619::hsm::387::Storage.HSM::(storageRefresh) HSM is ready
>Detector thread::DEBUG::2014-07-29 13:01:21,264::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56816
>Detector thread::DEBUG::2014-07-29 13:01:21,265::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56816
>Detector thread::DEBUG::2014-07-29 13:01:21,265::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56816
>Detector thread::DEBUG::2014-07-29 13:01:21,266::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56816)
>Thread-13::DEBUG::2014-07-29 13:01:21,305::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-29 13:01:21,334::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Detector thread::DEBUG::2014-07-29 13:01:21,342::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56817
>Detector thread::DEBUG::2014-07-29 13:01:21,342::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56817
>Detector thread::DEBUG::2014-07-29 13:01:21,343::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56817
>Detector thread::DEBUG::2014-07-29 13:01:21,343::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56817)
>Detector thread::DEBUG::2014-07-29 13:01:21,400::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56818
>Detector thread::DEBUG::2014-07-29 13:01:21,400::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56818
>Detector thread::DEBUG::2014-07-29 13:01:21,401::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56818
>Detector thread::DEBUG::2014-07-29 13:01:21,401::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56818)
>Thread-15::DEBUG::2014-07-29 13:01:21,440::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-15::DEBUG::2014-07-29 13:01:21,440::task::595::Storage.TaskManager.Task::(_updateState) Task=`00c7b9fa-4c0b-4f8e-a370-445bd256f84e`::moving from state init -> state preparing
>Thread-15::INFO::2014-07-29 13:01:21,440::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-15::INFO::2014-07-29 13:01:21,440::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-15::DEBUG::2014-07-29 13:01:21,441::task::1191::Storage.TaskManager.Task::(prepare) Task=`00c7b9fa-4c0b-4f8e-a370-445bd256f84e`::finished: {'poollist': []}
>Thread-15::DEBUG::2014-07-29 13:01:21,441::task::595::Storage.TaskManager.Task::(_updateState) Task=`00c7b9fa-4c0b-4f8e-a370-445bd256f84e`::moving from state preparing -> state finished
>Thread-15::DEBUG::2014-07-29 13:01:21,441::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-15::DEBUG::2014-07-29 13:01:21,441::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-15::DEBUG::2014-07-29 13:01:21,441::task::993::Storage.TaskManager.Task::(_decref) Task=`00c7b9fa-4c0b-4f8e-a370-445bd256f84e`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 13:01:34,531::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56819
>Detector thread::DEBUG::2014-07-29 13:01:34,532::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56819
>Detector thread::DEBUG::2014-07-29 13:01:34,532::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56819
>Detector thread::DEBUG::2014-07-29 13:01:34,532::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56819)
>Thread-16::DEBUG::2014-07-29 13:01:34,573::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-07-29 13:01:34,574::task::595::Storage.TaskManager.Task::(_updateState) Task=`716e4b37-eb3d-4202-a40e-997dfaf68864`::moving from state init -> state preparing
>Thread-16::INFO::2014-07-29 13:01:34,575::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-16::DEBUG::2014-07-29 13:01:34,576::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=new (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,597::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-07-29 13:01:34,598::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,612::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-07-29 13:01:34,614::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,653::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-07-29 13:01:34,654::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,676::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-07-29 13:01:34,677::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --discover (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,690::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::DEBUG::2014-07-29 13:01:34,704::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.34.131.193:3260 --op=delete (cwd None)
>Thread-16::DEBUG::2014-07-29 13:01:34,714::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-16::INFO::2014-07-29 13:01:34,715::logUtils::47::dispatcher::(wrapper) Run and protect: discoverSendTargets, Return response: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-16::DEBUG::2014-07-29 13:01:34,716::task::1191::Storage.TaskManager.Task::(prepare) Task=`716e4b37-eb3d-4202-a40e-997dfaf68864`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-16::DEBUG::2014-07-29 13:01:34,717::task::595::Storage.TaskManager.Task::(_updateState) Task=`716e4b37-eb3d-4202-a40e-997dfaf68864`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-07-29 13:01:34,718::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-07-29 13:01:34,719::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-07-29 13:01:34,719::task::993::Storage.TaskManager.Task::(_decref) Task=`716e4b37-eb3d-4202-a40e-997dfaf68864`::ref 0 aborting False
>Detector thread::DEBUG::2014-07-29 13:01:35,661::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56821
>Detector thread::DEBUG::2014-07-29 13:01:35,661::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56821
>Detector thread::DEBUG::2014-07-29 13:01:35,661::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56821
>Detector thread::DEBUG::2014-07-29 13:01:35,661::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56821)
>Thread-17::DEBUG::2014-07-29 13:01:35,701::BindingXMLRPC::318::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-07-29 13:01:35,701::task::595::Storage.TaskManager.Task::(_updateState) Task=`ca6730ed-4e7f-4573-943d-37752234bc3b`::moving from state init -> state preparing
>Thread-17::INFO::2014-07-29 13:01:35,701::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-17::DEBUG::2014-07-29 13:01:35,701::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-17::DEBUG::2014-07-29 13:01:35,702::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-17::DEBUG::2014-07-29 13:01:35,702::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-17::DEBUG::2014-07-29 13:01:35,702::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>Thread-17::DEBUG::2014-07-29 13:01:35,702::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-17::DEBUG::2014-07-29 13:01:35,702::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>Thread-17::DEBUG::2014-07-29 13:01:35,718::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-17::DEBUG::2014-07-29 13:01:35,718::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>Thread-17::DEBUG::2014-07-29 13:01:35,797::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 13:01:35,798::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,798::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,798::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,798::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,799::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,799::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,799::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>Thread-17::DEBUG::2014-07-29 13:01:35,799::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,801::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>Thread-17::DEBUG::2014-07-29 13:01:35,926::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-29 13:01:35,927::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-17::DEBUG::2014-07-29 13:01:35,968::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvcreate --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --test --metadatasize 128m --metadatacopies 2 --metadataignore y /dev/mapper/33000000100000001 (cwd None)
>Thread-17::DEBUG::2014-07-29 13:01:36,095::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n'; <rc> = 0
>Thread-17::INFO::2014-07-29 13:01:36,095::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'free', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': '******', 'port': '3260'}], 'logicalblocksize': '512', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'physicalblocksize': '4096', 'pvUUID': '', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-17::DEBUG::2014-07-29 13:01:36,099::task::1191::Storage.TaskManager.Task::(prepare) Task=`ca6730ed-4e7f-4573-943d-37752234bc3b`::finished: {'devList': [{'status': 'free', 'fwrev': '0001', 'vgUUID': '', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'logicalblocksize': '512', 'devtype': 'iSCSI', 'physicalblocksize': '4096', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK', 'vendorID': 'IET', 'capacity': '52428800000', 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'pvUUID': ''}]}
>Thread-17::DEBUG::2014-07-29 13:01:36,099::task::595::Storage.TaskManager.Task::(_updateState) Task=`ca6730ed-4e7f-4573-943d-37752234bc3b`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-07-29 13:01:36,099::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-07-29 13:01:36,099::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-07-29 13:01:36,100::task::993::Storage.TaskManager.Task::(_decref) Task=`ca6730ed-4e7f-4573-943d-37752234bc3b`::ref 0 aborting False
>MainThread::DEBUG::2014-07-29 13:03:52,106::vdsm::58::vds::(sigtermHandler) Received signal 15
>MainThread::DEBUG::2014-07-29 13:03:52,107::protocoldetector::133::vds.MultiProtocolAcceptor::(stop) Stopping Acceptor
>MainThread::INFO::2014-07-29 13:03:52,107::__init__::557::jsonrpc.JsonRpcServer::(stop) Stopping JsonRPC Server
>Detector thread::DEBUG::2014-07-29 13:03:52,107::protocoldetector::104::vds.MultiProtocolAcceptor::(_cleanup) Cleaning Acceptor
>MainThread::INFO::2014-07-29 13:03:52,108::vmchannels::188::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-29 13:03:52,108::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-07-29 13:03:52,109::task::595::Storage.TaskManager.Task::(_updateState) Task=`6e50c7a4-f28b-4e85-acf3-1115009c793c`::moving from state init -> state preparing
>MainThread::INFO::2014-07-29 13:03:52,109::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-07-29 13:03:52,110::storageServer::706::Storage.ConnectionMonitor::(_monitorConnections) Monitoring stopped
>MainThread::INFO::2014-07-29 13:03:52,147::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::DEBUG::2014-07-29 13:03:52,147::taskManager::90::Storage.TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-07-29 13:03:52,147::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-07-29 13:03:52,147::task::1191::Storage.TaskManager.Task::(prepare) Task=`6e50c7a4-f28b-4e85-acf3-1115009c793c`::finished: None
>MainThread::DEBUG::2014-07-29 13:03:52,147::task::595::Storage.TaskManager.Task::(_updateState) Task=`6e50c7a4-f28b-4e85-acf3-1115009c793c`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 13:03:52,147::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 13:03:52,147::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 13:03:52,147::task::993::Storage.TaskManager.Task::(_decref) Task=`6e50c7a4-f28b-4e85-acf3-1115009c793c`::ref 0 aborting False
>MainThread::INFO::2014-07-29 13:03:52,147::vdsm::137::vds::(run) VDSM main thread ended. Waiting for 16 other threads...
>MainThread::INFO::2014-07-29 13:03:52,147::vdsm::141::vds::(run) <_MainThread(MainThread, started 140251286423296)>
>MainThread::INFO::2014-07-29 13:03:52,147::vdsm::141::vds::(run) <Thread(libvirtEventLoop, started daemon 140251193726720)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-4, started daemon 140250949089024)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <HostMonitor(HostMonitor, started daemon 140249875347200)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-9, started daemon 140250896639744)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-8, started daemon 140250907129600)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-7, started daemon 140250917619456)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-6, started daemon 140250928109312)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140249822897920)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-10, started daemon 140250479326976)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <GuestManager(GuestManager, started daemon 140249854367488)>
>MainThread::INFO::2014-07-29 13:03:52,148::vmchannels::188::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <Listener(VM Channels Listener, started daemon 140250102822656)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-3, started daemon 140251162257152)>
>MainThread::INFO::2014-07-29 13:03:52,148::vdsm::141::vds::(run) <WorkerThread(Thread-2, started daemon 140251172747008)>
>MainThread::INFO::2014-07-29 13:03:52,149::vdsm::141::vds::(run) <WorkerThread(Thread-5, started daemon 140250938599168)>
>MainThread::INFO::2014-07-29 13:03:52,149::vdsm::141::vds::(run) <WorkerThread(Thread-1, started daemon 140251183236864)>
>MainThread::INFO::2014-07-29 13:03:52,149::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-07-29 13:03:52,149::vdsm::141::vds::(run) <MomThread(MOM, started 140250123802368)>
>VM Channels Listener::INFO::2014-07-29 13:03:52,268::vmchannels::183::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-07-29 13:03:58,358::vdsm::131::vds::(run) (PID: 38275) I am the actual vdsm 4.16.1-1.git13255aa.el6 dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-29 13:03:58,359::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-29 13:03:58,359::threadPool::35::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-07-29 13:03:58,361::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::WARNING::2014-07-29 13:03:58,362::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-29 13:03:58,401::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-29 13:03:58,412::multipath::141::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-29 13:03:58,412::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type (cwd None)
>MainThread::DEBUG::2014-07-29 13:03:58,521::hsm::418::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 13:03:58,522::hsm::442::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-29 13:03:58,524::hsm::474::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-29 13:03:58,524::hsm::475::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-29 13:03:58,524::hsm::477::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-29 13:03:58,525::hsm::520::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-29 13:03:58,526::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-29 13:03:58,529::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-29 13:03:58,529::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 13:03:58,572::misc::741::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-29 13:03:58,572::misc::743::Storage.SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-29 13:03:58,572::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-29 13:03:58,572::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
>MainThread::DEBUG::2014-07-29 13:03:58,579::task::595::Storage.TaskManager.Task::(_updateState) Task=`fe6a56e5-fe02-4abc-93f2-0890aabee13f`::moving from state init -> state preparing
>MainThread::INFO::2014-07-29 13:03:58,580::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF object at 0x237a290>>)
>MainThread::INFO::2014-07-29 13:03:58,580::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-29 13:03:58,580::task::1191::Storage.TaskManager.Task::(prepare) Task=`fe6a56e5-fe02-4abc-93f2-0890aabee13f`::finished: None
>MainThread::DEBUG::2014-07-29 13:03:58,580::task::595::Storage.TaskManager.Task::(_updateState) Task=`fe6a56e5-fe02-4abc-93f2-0890aabee13f`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-29 13:03:58,580::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-29 13:03:58,581::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-29 13:03:58,581::task::993::Storage.TaskManager.Task::(_decref) Task=`fe6a56e5-fe02-4abc-93f2-0890aabee13f`::ref 0 aborting False
>MainThread::INFO::2014-07-29 13:03:58,581::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-29 13:03:58,584::vmchannels::192::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-29 13:03:58,587::vmchannels::175::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-29 13:03:58,587::libvirtconnection::150::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-29 13:03:58,591::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 13:03:58,592::multipath::109::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /sbin/multipath (cwd None)
>MainThread::DEBUG::2014-07-29 13:03:58,607::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <rpc.BindingXMLRPC.XmlDetector instance at 0x253a0e0>
>storageRefresh::DEBUG::2014-07-29 13:03:58,674::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-29 13:03:58,675::protocoldetector::129::vds.MultiProtocolAcceptor::(add_detector) adding detector: <yajsonrpc.stompReactor.StompDetector instance at 0x7fb9780d2758>
>storageRefresh::DEBUG::2014-07-29 13:03:58,675::lvm::489::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,675::lvm::491::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>JsonRpcServer::DEBUG::2014-07-29 13:03:58,676::__init__::498::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
>storageRefresh::DEBUG::2014-07-29 13:03:58,676::lvm::500::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,677::lvm::502::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,678::lvm::520::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Detector thread::DEBUG::2014-07-29 13:03:58,678::protocoldetector::68::vds.MultiProtocolAcceptor::(serve_forever) Acceptor running
>storageRefresh::DEBUG::2014-07-29 13:03:58,679::lvm::522::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Detector thread::DEBUG::2014-07-29 13:03:58,681::protocoldetector::70::vds.MultiProtocolAcceptor::(serve_forever) Using required_size=11
>storageRefresh::DEBUG::2014-07-29 13:03:58,682::misc::751::Storage.SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-29 13:03:58,684::lvm::317::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,691::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:03:58,804::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:03:58,805::lvm::342::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,806::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,807::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:03:58,907::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:03:58,908::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:58,908::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm lvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:03:59,004::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:03:59,004::lvm::365::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:59,004::lvm::288::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /sbin/lvm vgs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ '\''a|/dev/mapper/33000000100000001|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name (cwd None)
>storageRefresh::DEBUG::2014-07-29 13:03:59,099::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-29 13:03:59,100::lvm::407::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-29 13:03:59,100::hsm::387::Storage.HSM::(storageRefresh) HSM is ready
>Detector thread::DEBUG::2014-07-29 13:03:59,224::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56823
>Detector thread::DEBUG::2014-07-29 13:03:59,224::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56823
>Detector thread::DEBUG::2014-07-29 13:03:59,225::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56823
>Detector thread::DEBUG::2014-07-29 13:03:59,225::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56823)
>Thread-13::DEBUG::2014-07-29 13:03:59,264::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-29 13:03:59,267::BindingXMLRPC::1134::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Detector thread::DEBUG::2014-07-29 13:03:59,278::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56824
>Detector thread::DEBUG::2014-07-29 13:03:59,278::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56824
>Detector thread::DEBUG::2014-07-29 13:03:59,278::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56824
>Detector thread::DEBUG::2014-07-29 13:03:59,278::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56824)
>Thread-14::DEBUG::2014-07-29 13:03:59,318::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
>Thread-14::DEBUG::2014-07-29 13:03:59,396::utils::738::root::(execCmd) /sbin/ip route show to 0.0.0.0/0 table all (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,403::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,426::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/bonding_masters (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,437::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,438::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,450::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,466::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,477::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,478::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,489::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,491::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,501::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,503::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,513::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,515::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,525::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,527::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/HXrI4sBudMqo1QM/bonding/mode (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,537::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,539::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/bin/tee /sys/class/net/bonding_masters (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,577::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,585::utils::738::root::(execCmd) /usr/bin/sudo -n /usr/sbin/dmidecode -s system-uuid (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,599::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,617::caps::614::root::(get) VirtioRNG DISABLED: libvirt version 0.10.2-29.el6_5.9 required >= 0.10.2-31
>Thread-14::DEBUG::2014-07-29 13:03:59,621::utils::738::root::(execCmd) numactl --hardware (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,626::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,626::utils::738::root::(execCmd) sysctl -n -e kernel.numa_balancing (cwd None)
>Thread-14::DEBUG::2014-07-29 13:03:59,631::utils::758::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-14::DEBUG::2014-07-29 13:03:59,636::BindingXMLRPC::1134::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:431ee67f14b2'}], 'FC': []}, 'packages2': {'kernel': {'release': '431.el6.x86_64', 'buildtime': 1385086509.0, 'version': '2.6.32'}, 'spice-server': {'release': '6.el6_5.2', 'buildtime': 1402324637L, 'version': '0.12.4'}, 'vdsm': {'release': '1.git13255aa.el6', 'buildtime': 1406617960L, 'version': '4.16.1'}, 'qemu-kvm': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'libvirt': {'release': '29.el6_5.9', 'buildtime': 1402404612L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.415.el6_5.10', 'buildtime': 1402435700L, 'version': '0.12.1.2'}, 'mom': {'release': '2.el6', 'buildtime': 1403794344L, 'version': '0.4.1'}}, 'numaNodeDistance': {'0': [10]}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1220 V2 @ 3.10GHz', 'hooks': {'before_vm_start': {'50_hostedengine': {'md5': '45dde62155b5412eafbfff5ef265acc2'}}}, 'cpuSockets': '1', 'vmTypes': ['kvm'], 'selinux': {'mode': '1'}, 'kdumpStatus': 0, 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'bridges': {}, 'uuid': '30303734-3536-5A43-3133-343330305746_a4:5d:36:11:e4:80', 'lastClientIface': 'lo', 'nics': {'eth1': {'addr': '', 'cfg': {'UUID': 'f4c325df-ca04-4813-98ae-e1bf9e82a0bb', 'NM_CONTROLLED': 'yes', 'HWADDR': 'A4:5D:36:11:E4:81', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth1', 'TYPE': 'Ethernet', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': 'a4:5d:36:11:e4:81', 'speed': 0}, 'eth0': {'addr': '10.34.63.108', 'cfg': {'IPV6INIT': 'no', 'NM_CONTROLLED': 'yes', 'MTU': '1500', 'HWADDR': 'A4:5D:36:11:E4:80', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth0', 'TYPE': 'Ethernet', 'ONBOOT': 'yes', 'UUID': '5ea6e70f-cacd-47a5-8171-9257b8384183'}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '255.255.252.0', 'ipv4addrs': ['10.34.63.108/22'], 'hwaddr': 'a4:5d:36:11:e4:80', 'speed': 1000}}, 'software_revision': '1', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], '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,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:431ee67f14b2', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4', '3.5'], 'autoNumaBalancing': 2, 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'ipv4addrs': [], 'hwaddr': '00:00:00:00:00:00', 'slaves': [], 'opts': {}}, 'bond1': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond2': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond3': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}}, 'software_version': '4.16', 'memSize': '15782', 'cpuSpeed': '2128.000', 'numaNodes': {u'0': {'totalMemory': '15782', 'cpus': [0, 1, 2, 3]}}, 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'cpuThreads': '4', 'emulatedMachines': [u'rhel6.5.0', u'pc', u'rhel6.4.0', 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': '5.el6.centos.11.1', 'version': '6', 'name': 'RHEL'}, 'lastClient': '127.0.0.1'}}
>Detector thread::DEBUG::2014-07-29 13:03:59,734::protocoldetector::160::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:56825
>Detector thread::DEBUG::2014-07-29 13:03:59,735::protocoldetector::171::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:56825
>Detector thread::DEBUG::2014-07-29 13:03:59,735::protocoldetector::197::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 127.0.0.1:56825
>Detector thread::DEBUG::2014-07-29 13:03:59,735::BindingXMLRPC::1167::XmlDetector::(handleSocket) xml over http detected from ('127.0.0.1', 56825)
>Thread-15::DEBUG::2014-07-29 13:03:59,775::BindingXMLRPC::1127::vds::(wrapper) client [127.0.0.1]::call addNetwork with ('ovirtmgmt', '', '', ['eth0'], {'blockingdhcp': 'true', 'bootproto': 'dhcp', 'force': 'False', 'ONBOOT': 'yes', 'bridged': 'True'}) {}
>Thread-15::ERROR::2014-07-29 13:03:59,847::BindingXMLRPC::1146::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/rpc/BindingXMLRPC.py", line 1130, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/rpc/BindingXMLRPC.py", line 541, in addNetwork
>    return api.addNetwork(bridge, vlan, bond, nics, options)
>  File "/usr/share/vdsm/API.py", line 1361, in addNetwork
>    supervdsm.getProxy().addNetwork(bridge, options)
>  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
>    return callMethod()
>  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
>    **kwargs)
>  File "<string>", line 2, in addNetwork
>  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 726, in _callmethod
>    kind, result = conn.recv()
>EOFError
>PolicyEngine::DEBUG::2014-07-29 13:04:08,896::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm

Actions: View

Attachments on bug 1124372: 922110 | 922127 | 922187 | 922863