VDSM logs doesn't show me anythingMainThread::INFO::2015-09-01 23:34:49,551::vdsm::166::vds::(run) <WorkerThread(Thread-4, started daemon 139990108333824)>
MainThread::INFO::2015-09-01 23:34:49,552::vdsm::166::vds::(run) <WorkerThread(Thread-3, started daemon 139990116726528)>
MainThread::INFO::2015-09-02 16:07:49,510::vdsm::156::vds::(run) (PID: 1554) I am the actual vdsm 4.17.3-12.git7288ef7.fc22 noveria.wodel.wd (4.1.6-200.fc22.x86_64)
MainThread::DEBUG::2015-09-02 16:07:49,524::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2015-09-02 16:07:49,524::threadPool::29::Storage.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
MainThread::DEBUG::2015-09-02 16:07:49,526::fileUtils::143::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt mode: None
MainThread::WARNING::2015-09-02 16:07:49,526::fileUtils::152::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2015-09-02 16:07:49,564::hsm::403::Storage.Misc.excCmd::(__validateLvmLockingType) /usr/bin/sudo -n /usr/sbin/lvm dumpconfig global/locking_type (cwd None)
MainThread::DEBUG::2015-09-02 16:07:49,611::hsm::403::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2015-09-02 16:07:49,611::hsm::427::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2015-09-02 16:07:49,614::hsm::459::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2015-09-02 16:07:49,614::hsm::460::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2015-09-02 16:07:49,614::hsm::462::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2015-09-02 16:07:49,615::hsm::505::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2015-09-02 16:07:49,616::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2015-09-02 16:07:49,617::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2015-09-02 16:07:49,620::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2015-09-02 16:07:49,792::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2015-09-02 16:07:49,793::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2015-09-02 16:07:49,793::iscsi::431::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2015-09-02 16:07:49,924::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
MainThread::DEBUG::2015-09-02 16:07:49,924::task::595::Storage.TaskManager.Task::(_updateState) Task=`68d01d7d-b426-4465-829e-174e2cb47e9e`::moving from state init -> state preparing
MainThread::INFO::2015-09-02 16:07:49,924::logUtils::48::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<functools.partial object at 0x7fc2f03fa6d8>)
MainThread::INFO::2015-09-02 16:07:49,924::logUtils::51::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2015-09-02 16:07:49,927::task::1191::Storage.TaskManager.Task::(prepare) Task=`68d01d7d-b426-4465-829e-174e2cb47e9e`::finished: None
MainThread::DEBUG::2015-09-02 16:07:49,927::task::595::Storage.TaskManager.Task::(_updateState) Task=`68d01d7d-b426-4465-829e-174e2cb47e9e`::moving from state preparing -> state finished
MainThread::DEBUG::2015-09-02 16:07:49,927::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2015-09-02 16:07:49,927::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2015-09-02 16:07:49,928::task::993::Storage.TaskManager.Task::(_decref) Task=`68d01d7d-b426-4465-829e-174e2cb47e9e`::ref 0 aborting False
MainThread::INFO::2015-09-02 16:07:49,928::momIF::46::MOM::(__init__) Preparing MOM interface
MainThread::INFO::2015-09-02 16:07:49,929::momIF::55::MOM::(__init__) Using named unix socket /var/run/vdsm/mom-vdsm.sock
MainThread::INFO::2015-09-02 16:07:49,929::secret::90::root::(clear) Unregistering all secrests
MainThread::DEBUG::2015-09-02 16:07:49,929::libvirtconnection::160::root::(get) trying to connect libvirt
MainThread::INFO::2015-09-02 16:07:49,933::vmchannels::196::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::DEBUG::2015-09-02 16:07:49,934::vmchannels::178::vds::(run) Starting VM channels listener thread.
MainThread::INFO::2015-09-02 16:07:49,935::protocoldetector::172::vds.MultiProtocolAcceptor::(__init__) Listening at
0.0.0.0:54321MainThread::DEBUG::2015-09-02 16:07:50,063::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <rpc.bindingxmlrpc.XmlDetector instance at 0x7fc2f00dc440>
storageRefresh::DEBUG::2015-09-02 16:07:50,063::misc::743::Storage.SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2015-09-02 16:07:50,080::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
storageRefresh::DEBUG::2015-09-02 16:07:50,081::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2015-09-02 16:07:50,081::hba::56::Storage.HBA::(rescan) Starting scan
storageRefresh::DEBUG::2015-09-02 16:07:50,081::supervdsm::76::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2015-09-02 16:07:50,157::protocoldetector::199::vds.MultiProtocolAcceptor::(add_detector) Adding detector <yajsonrpc.stompreactor.StompDetector instance at 0x7fc2e01332d8>
BindingXMLRPC::INFO::2015-09-02 16:07:50,158::bindingxmlrpc::62::vds::(threaded_start) XMLRPC server running
MainThread::DEBUG::2015-09-02 16:07:50,158::schedule::98::Scheduler::(start) Starting scheduler periodic-sched
periodic-sched::DEBUG::2015-09-02 16:07:50,159::schedule::142::Scheduler::(_run) started
MainThread::DEBUG::2015-09-02 16:07:50,159::executor::69::Executor::(start) Starting executor
MainThread::DEBUG::2015-09-02 16:07:50,159::executor::157::Executor::(__init__) Starting worker periodic/0
periodic/0::DEBUG::2015-09-02 16:07:50,159::executor::171::Executor::(_run) Worker started
MainThread::DEBUG::2015-09-02 16:07:50,159::executor::157::Executor::(__init__) Starting worker periodic/1
periodic/1::DEBUG::2015-09-02 16:07:50,160::executor::171::Executor::(_run) Worker started
MainThread::DEBUG::2015-09-02 16:07:50,160::executor::157::Executor::(__init__) Starting worker periodic/2
periodic/2::DEBUG::2015-09-02 16:07:50,160::executor::171::Executor::(_run) Worker started
MainThread::DEBUG::2015-09-02 16:07:50,160::executor::157::Executor::(__init__) Starting worker periodic/3
periodic/3::DEBUG::2015-09-02 16:07:50,160::executor::171::Executor::(_run) Worker started
MainThread::DEBUG::2015-09-02 16:07:50,160::libvirtconnection::160::root::(get) trying to connect libvirt
MainThread::DEBUG::2015-09-02 16:07:50,163::periodic::157::virt.periodic.Operation::(start) starting operation VmDispatcher(<class 'virt.periodic.UpdateVolumes'>)
MainThread::DEBUG::2015-09-02 16:07:50,164::periodic::157::virt.periodic.Operation::(start) starting operation VmDispatcher(<class 'virt.periodic.NumaInfoMonitor'>)
MainThread::DEBUG::2015-09-02 16:07:50,164::periodic::157::virt.periodic.Operation::(start) starting operation VmDispatcher(<class 'virt.periodic.BlockjobMonitor'>)
MainThread::DEBUG::2015-09-02 16:07:50,164::periodic::157::virt.periodic.Operation::(start) starting operation <virt.sampling.VMBulkSampler object at 0x7fc2e0151d10>
MainThread::DEBUG::2015-09-02 16:07:50,164::periodic::157::virt.periodic.Operation::(start) starting operation VmDispatcher(<class 'virt.periodic.DriveWatermarkMonitor'>)
storageRefresh::DEBUG::2015-09-02 16:07:50,167::hba::62::Storage.HBA::(rescan) Scan finished
storageRefresh::DEBUG::2015-09-02 16:07:50,167::misc::743::Storage.SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2015-09-02 16:07:50,167::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
storageRefresh::DEBUG::2015-09-02 16:07:50,513::multipath::77::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:50,513::utils::661::root::(execCmd) /sbin/udevadm settle --timeout=5 (cwd None)
Reactor thread::INFO::2015-09-02 16:07:50,590::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from
127.0.0.1:56311Reactor thread::DEBUG::2015-09-02 16:07:50,596::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-09-02 16:07:50,596::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from
127.0.0.1:56311Reactor thread::DEBUG::2015-09-02 16:07:50,596::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 56311)
BindingXMLRPC::INFO::2015-09-02 16:07:50,596::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for
127.0.0.1:56311Thread-13::INFO::2015-09-02 16:07:50,597::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56311 started
Thread-13::DEBUG::2015-09-02 16:07:50,597::bindingxmlrpc::1256::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-13::DEBUG::2015-09-02 16:07:50,597::bindingxmlrpc::1263::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
Thread-13::INFO::2015-09-02 16:07:50,599::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56311 stopped
Reactor thread::INFO::2015-09-02 16:07:51,607::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from
127.0.0.1:56312Reactor thread::DEBUG::2015-09-02 16:07:51,613::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-09-02 16:07:51,613::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from
127.0.0.1:56312Reactor thread::DEBUG::2015-09-02 16:07:51,613::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 56312)
BindingXMLRPC::INFO::2015-09-02 16:07:51,613::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for
127.0.0.1:56312Thread-14::INFO::2015-09-02 16:07:51,613::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56312 started
Thread-14::DEBUG::2015-09-02 16:07:51,614::bindingxmlrpc::1256::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-14::DEBUG::2015-09-02 16:07:51,614::bindingxmlrpc::1263::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
Thread-14::INFO::2015-09-02 16:07:51,615::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56312 stopped
storageRefresh::DEBUG::2015-09-02 16:07:51,924::utils::679::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::498::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::500::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::509::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::511::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::529::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::531::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,926::misc::743::Storage.SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2015-09-02 16:07:51,926::lvm::320::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:51,927::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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::2015-09-02 16:07:52,341::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:52,341::lvm::348::Storage.OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:52,341::lvm::371::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:52,341::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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::2015-09-02 16:07:52,405::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:52,405::lvm::416::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:52,406::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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::2015-09-02 16:07:52,458::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:52,458::lvm::371::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:52,459::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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::2015-09-02 16:07:52,491::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2015-09-02 16:07:52,491::lvm::416::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2015-09-02 16:07:52,491::hsm::373::Storage.HSM::(storageRefresh) HSM is ready
Reactor thread::INFO::2015-09-02 16:07:52,624::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from
127.0.0.1:56313Reactor thread::DEBUG::2015-09-02 16:07:52,629::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-09-02 16:07:52,629::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from
127.0.0.1:56313Reactor thread::DEBUG::2015-09-02 16:07:52,629::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 56313)
BindingXMLRPC::INFO::2015-09-02 16:07:52,629::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for
127.0.0.1:56313Thread-15::INFO::2015-09-02 16:07:52,630::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56313 started
Thread-15::DEBUG::2015-09-02 16:07:52,630::bindingxmlrpc::1256::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-15::DEBUG::2015-09-02 16:07:52,719::bindingxmlrpc::1263::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'System Product Name', 'systemSerialNumber': 'System Serial Number', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': 'System Version', 'systemUUID': '267A6B80-D7DA-11DD-81CF-C860009B3CD9', 'systemManufacturer': 'System manufacturer'}}
Thread-15::INFO::2015-09-02 16:07:52,721::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56313 stopped
Reactor thread::INFO::2015-09-02 16:07:52,730::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from
127.0.0.1:56314Reactor thread::DEBUG::2015-09-02 16:07:52,735::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-09-02 16:07:52,735::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from
127.0.0.1:56314Reactor thread::DEBUG::2015-09-02 16:07:52,735::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 56314)
BindingXMLRPC::INFO::2015-09-02 16:07:52,735::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for
127.0.0.1:56314Thread-16::INFO::2015-09-02 16:07:52,735::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56314 started
Thread-16::DEBUG::2015-09-02 16:07:52,736::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-16::DEBUG::2015-09-02 16:07:52,736::task::595::Storage.TaskManager.Task::(_updateState) Task=`c4a18001-912b-47dc-9713-7d50e5133b59`::moving from state init -> state preparing
Thread-16::INFO::2015-09-02 16:07:52,736::logUtils::48::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=3, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'id': '57bc98c0-560f-4e61-9d86-df92ad468d3b', 'connection': '192.168.1.50', 'iqn': 'iqn.2015-08.openSuse.wodel:target00', 'portal': '1', 'user': 'iscsiuser', 'password': '********', 'port': '3260'}], options=None)
Thread-16::DEBUG::2015-09-02 16:07:52,737::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 --op=new (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:52,789::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:52,789::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 -n node.session.auth.authmethod -v '****' --op=update (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:52,811::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:52,812::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 -n node.session.auth.username -v '****' --op=update (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:52,846::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:52,847::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 -n node.session.auth.password -v '****' --op=update (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:52,868::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:52,868::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m iface -I default (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:52,905::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::INFO::2015-09-02 16:07:52,905::iscsi::564::Storage.ISCSI::(setRpFilterIfNeeded) iSCSI iface.net_ifacename not provided. Skipping.
Thread-16::DEBUG::2015-09-02 16:07:52,906::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 -l (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,027::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:53,028::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2015-08.openSuse.wodel:target00 -I default -p
192.168.1.50:3260,1 -n node.startup -v manual --op=update (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,088::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:53,088::utils::661::root::(execCmd) /sbin/udevadm settle --timeout=5 (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,182::utils::679::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:53,182::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-16::DEBUG::2015-09-02 16:07:53,182::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-16::DEBUG::2015-09-02 16:07:53,182::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-16::DEBUG::2015-09-02 16:07:53,182::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-16::DEBUG::2015-09-02 16:07:53,182::iscsi::431::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-16::DEBUG::2015-09-02 16:07:53,182::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,229::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-16::DEBUG::2015-09-02 16:07:53,229::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
Thread-16::DEBUG::2015-09-02 16:07:53,229::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-16::DEBUG::2015-09-02 16:07:53,229::hba::56::Storage.HBA::(rescan) Starting scan
Thread-16::DEBUG::2015-09-02 16:07:53,300::hba::62::Storage.HBA::(rescan) Scan finished
Thread-16::DEBUG::2015-09-02 16:07:53,300::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-16::DEBUG::2015-09-02 16:07:53,300::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,435::multipath::77::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:53,435::utils::661::root::(execCmd) /sbin/udevadm settle --timeout=5 (cwd None)
Thread-16::DEBUG::2015-09-02 16:07:53,919::utils::679::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:53,921::lvm::498::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,921::lvm::500::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,922::lvm::509::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,922::lvm::511::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,922::lvm::529::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,922::lvm::531::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,922::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-16::DEBUG::2015-09-02 16:07:53,922::lvm::371::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:53,923::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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|/dev/mapper/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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-16::DEBUG::2015-09-02 16:07:54,058::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-16::DEBUG::2015-09-02 16:07:54,059::lvm::416::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-16::DEBUG::2015-09-02 16:07:54,059::hsm::2418::Storage.HSM::(__prefetchDomains) Found SD uuids: ('8b25f3be-7574-4f7a-8851-363129704e52',)
Thread-16::DEBUG::2015-09-02 16:07:54,059::hsm::2478::Storage.HSM::(connectStorageServer) knownSDs: {8b25f3be-7574-4f7a-8851-363129704e52: storage.blockSD.findDomain}
Thread-16::INFO::2015-09-02 16:07:54,059::logUtils::51::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '57bc98c0-560f-4e61-9d86-df92ad468d3b'}]}
Thread-16::DEBUG::2015-09-02 16:07:54,059::task::1191::Storage.TaskManager.Task::(prepare) Task=`c4a18001-912b-47dc-9713-7d50e5133b59`::finished: {'statuslist': [{'status': 0, 'id': '57bc98c0-560f-4e61-9d86-df92ad468d3b'}]}
Thread-16::DEBUG::2015-09-02 16:07:54,059::task::595::Storage.TaskManager.Task::(_updateState) Task=`c4a18001-912b-47dc-9713-7d50e5133b59`::moving from state preparing -> state finished
Thread-16::DEBUG::2015-09-02 16:07:54,060::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-16::DEBUG::2015-09-02 16:07:54,060::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-16::DEBUG::2015-09-02 16:07:54,060::task::993::Storage.TaskManager.Task::(_decref) Task=`c4a18001-912b-47dc-9713-7d50e5133b59`::ref 0 aborting False
Thread-16::INFO::2015-09-02 16:07:54,062::xmlrpc::92::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56314 stopped
Reactor thread::INFO::2015-09-02 16:07:54,070::protocoldetector::72::ProtocolDetector.AcceptorImpl::(handle_accept) Accepting connection from
127.0.0.1:56316Reactor thread::DEBUG::2015-09-02 16:07:54,075::protocoldetector::82::ProtocolDetector.Detector::(__init__) Using required_size=11
Reactor thread::INFO::2015-09-02 16:07:54,076::protocoldetector::118::ProtocolDetector.Detector::(handle_read) Detected protocol xml from
127.0.0.1:56316Reactor thread::DEBUG::2015-09-02 16:07:54,076::bindingxmlrpc::1296::XmlDetector::(handle_socket) xml over http detected from ('127.0.0.1', 56316)
BindingXMLRPC::INFO::2015-09-02 16:07:54,076::xmlrpc::73::vds.XMLRPCServer::(handle_request) Starting request handler for
127.0.0.1:56316Thread-17::INFO::2015-09-02 16:07:54,076::xmlrpc::84::vds.XMLRPCServer::(_process_requests) Request handler for
127.0.0.1:56316 started
Thread-17::DEBUG::2015-09-02 16:07:54,077::bindingxmlrpc::325::vds::(wrapper) client [127.0.0.1]
Thread-17::DEBUG::2015-09-02 16:07:54,077::task::595::Storage.TaskManager.Task::(_updateState) Task=`7936300e-8a1a-47f5-83c4-16ed19853e36`::moving from state init -> state preparing
Thread-17::INFO::2015-09-02 16:07:54,077::logUtils::48::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='8b25f3be-7574-4f7a-8851-363129704e52', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='bf3bdae1-7318-4443-a19b-7371de30b982', leafUUID='cbb10cf0-9600-465e-aed9-412f7157706b')
Thread-17::DEBUG::2015-09-02 16:07:54,077::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.8b25f3be-7574-4f7a-8851-363129704e52`ReqID=`fc59b8b4-51c5-4a15-9716-aedbb6de62e6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3194' at 'prepareImage'
Thread-17::DEBUG::2015-09-02 16:07:54,078::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.8b25f3be-7574-4f7a-8851-363129704e52' for lock type 'shared'
Thread-17::DEBUG::2015-09-02 16:07:54,078::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.8b25f3be-7574-4f7a-8851-363129704e52' is free. Now locking as 'shared' (1 active user)
Thread-17::DEBUG::2015-09-02 16:07:54,078::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.8b25f3be-7574-4f7a-8851-363129704e52`ReqID=`fc59b8b4-51c5-4a15-9716-aedbb6de62e6`::Granted request
Thread-17::DEBUG::2015-09-02 16:07:54,078::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`7936300e-8a1a-47f5-83c4-16ed19853e36`::_resourcesAcquired: Storage.8b25f3be-7574-4f7a-8851-363129704e52 (shared)
Thread-17::DEBUG::2015-09-02 16:07:54,078::task::993::Storage.TaskManager.Task::(_decref) Task=`7936300e-8a1a-47f5-83c4-16ed19853e36`::ref 1 aborting False
Thread-17::DEBUG::2015-09-02 16:07:54,078::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-17::DEBUG::2015-09-02 16:07:54,078::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-17::DEBUG::2015-09-02 16:07:54,078::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-17::DEBUG::2015-09-02 16:07:54,078::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-17::DEBUG::2015-09-02 16:07:54,078::iscsi::431::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-17::DEBUG::2015-09-02 16:07:54,078::iscsiadm::97::Storage.Misc.excCmd::(_runCmd) /usr/bin/sudo -n /sbin/iscsiadm -m session -R (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,130::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-17::DEBUG::2015-09-02 16:07:54,130::misc::733::Storage.SamplingMethod::(__call__) Trying to enter sampling method (storage.hba.rescan)
Thread-17::DEBUG::2015-09-02 16:07:54,130::misc::736::Storage.SamplingMethod::(__call__) Got in to sampling method
Thread-17::DEBUG::2015-09-02 16:07:54,130::hba::56::Storage.HBA::(rescan) Starting scan
Thread-17::DEBUG::2015-09-02 16:07:54,197::hba::62::Storage.HBA::(rescan) Scan finished
Thread-17::DEBUG::2015-09-02 16:07:54,197::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-17::DEBUG::2015-09-02 16:07:54,197::multipath::77::Storage.Misc.excCmd::(rescan) /usr/bin/sudo -n /usr/sbin/multipath (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,298::multipath::77::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2015-09-02 16:07:54,299::utils::661::root::(execCmd) /sbin/udevadm settle --timeout=5 (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,307::utils::679::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-17::DEBUG::2015-09-02 16:07:54,309::lvm::498::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::500::Storage.OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::509::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::511::Storage.OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::529::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::531::Storage.OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,310::misc::743::Storage.SamplingMethod::(__call__) Returning last result
Thread-17::DEBUG::2015-09-02 16:07:54,310::lvm::371::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,312::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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|/dev/mapper/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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 8b25f3be-7574-4f7a-8851-363129704e52 (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,478::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-17::DEBUG::2015-09-02 16:07:54,478::lvm::416::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,479::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
Thread-17::DEBUG::2015-09-02 16:07:54,479::blockSD::337::Storage.Misc.excCmd::(readlines) /usr/bin/dd iflag=direct skip=0 bs=2048 if=/dev/8b25f3be-7574-4f7a-8851-363129704e52/metadata count=1 (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,553::blockSD::337::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.00107202 s, 1.9 MB/s\n'; <rc> = 0
Thread-17::DEBUG::2015-09-02 16:07:54,553::misc::260::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.00107202 s, 1.9 MB/s'], size: 2048
Thread-17::DEBUG::2015-09-02 16:07:54,553::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
Thread-17::DEBUG::2015-09-02 16:07:54,553::persistentDict::252::Storage.PersistentDict::(refresh) Empty metadata
Thread-17::DEBUG::2015-09-02 16:07:54,553::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::504::Storage.OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::506::Storage.OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::514::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::526::Storage.OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::371::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,554::lvm::291::Storage.Misc.excCmd::(cmd) /usr/bin/sudo -n /usr/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|/dev/mapper/Hitachi_HDS721010DLE630_MSK523Y209VK0B|'\'', '\''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 8b25f3be-7574-4f7a-8851-363129704e52 (cwd None)
Thread-17::DEBUG::2015-09-02 16:07:54,685::lvm::291::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
Thread-17::DEBUG::2015-09-02 16:07:54,686::lvm::416::Storage.OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-17::DEBUG::2015-09-02 16:07:54,686::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'LOGBLKSIZE=512', 'PHYBLKSIZE=4096', 'POOL_UUID=', u'PV0=pv:33000000100000001,uuid:kTaQQh-4LCD-OghQ-cP5D-R7MM-aj6e-kTdQf0,pestart:0,pecount:397,mapoffset:0', 'ROLE=Regular', 'SDUUID=8b25f3be-7574-4f7a-8851-363129704e52', 'TYPE=ISCSI', 'VERSION=3', 'VGUUID=tJKiwH-Cn7v-QCxd-YQrg-MUxA-fbdC-kdga8m', '_SHA_CKSUM=4a100ce5195650f43971d849835a8b3d8c0343da']
Thread-17::DEBUG::2015-09-02 16:07:54,687::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace '8b25f3be-7574-4f7a-8851-363129704e52_imageNS'
Thread-17::DEBUG::2015-09-02 16:07:54,687::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace '8b25f3be-7574-4f7a-8851-363129704e52_volumeNS'
Thread-17::DEBUG::2015-09-02 16:07:54,687::resourceManager::421::Storage.ResourceManager::(registerNamespace) Registering namespace '8b25f3be-7574-4f7a-8851-363129704e52_lvmActivationNS'
Thread-17::DEBUG::2015-09-02 16:07:54,687::lvm::428::Storage.OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex