Attachment 897947 Details for Bug 1099882 – vdsm log

vdsm log

vdsm.log (text/plain), 149.79 KB, created by Jiri Moskovcak on 2014-05-21 12:02:23 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jiri Moskovcak

Created: 2014-05-21 12:02:23 UTC

Size: 149.79 KB

patch

obsolete

>MainThread::DEBUG::2014-05-21 12:50:47,679::fileUtils::192::Storage.fileUtils::(chown) Changing owner for /var/log/vdsm/upgrade.log, to (36:36)
>MainThread::WARNING::2014-05-21 12:50:48,455::vdsmDebugPlugin::40::DebugInterpreter::(__turnOnDebugPlugin) Starting Debug Interpreter. Tread lightly!
>MainThread::INFO::2014-05-21 12:50:48,484::vdsm::129::vds::(run) (PID: 58998) I am the actual vdsm 4.14.10-0.el6 localhost.localdomain (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-05-21 12:50:48,484::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-05-21 12:50:48,485::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-05-21 12:50:48,487::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::DEBUG::2014-05-21 12:50:48,547::multipath::151::Storage.Multipath::(isEnabled) multipath Defaulting to False
>MainThread::DEBUG::2014-05-21 12:50:48,547::multipath::169::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /bin/cp /tmp/tmpjHSOpd /etc/multipath.conf' (cwd None)
>MainThread::DEBUG::2014-05-21 12:50:48,556::multipath::169::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-05-21 12:50:48,558::multipath::175::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
>MainThread::DEBUG::2014-05-21 12:50:48,574::multipath::175::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-05-21 12:50:48,575::multipath::178::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /usr/bin/vdsm-tool service-reload multipathd' (cwd None)
>MainThread::DEBUG::2014-05-21 12:50:48,710::multipath::178::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-05-21 12:50:48,710::hsm::415::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-05-21 12:50:48,833::hsm::415::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-05-21 12:50:48,833::hsm::439::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-05-21 12:50:48,837::hsm::471::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-05-21 12:50:48,837::hsm::472::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-05-21 12:50:48,837::hsm::474::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-05-21 12:50:48,838::hsm::517::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-05-21 12:50:48,838::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-05-21 12:50:48,840::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-05-21 12:50:48,860::misc::762::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-05-21 12:50:48,861::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-05-21 12:50:48,861::misc::762::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-05-21 12:50:48,861::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-05-21 12:50:48,861::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>MainThread::DEBUG::2014-05-21 12:50:48,890::task::595::TaskManager.Task::(_updateState) Task=`a823d8b0-a6a3-4aec-ad39-d9227bce64f1`::moving from state init -> state preparing
>storageRefresh::DEBUG::2014-05-21 12:50:48,890::misc::770::SamplingMethod::(__call__) Returning last result
>MainThread::INFO::2014-05-21 12:50:48,891::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x22f1a28>>)
>storageRefresh::DEBUG::2014-05-21 12:50:48,891::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::INFO::2014-05-21 12:50:48,891::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-05-21 12:50:48,894::task::1188::TaskManager.Task::(prepare) Task=`a823d8b0-a6a3-4aec-ad39-d9227bce64f1`::finished: None
>MainThread::DEBUG::2014-05-21 12:50:48,895::task::595::TaskManager.Task::(_updateState) Task=`a823d8b0-a6a3-4aec-ad39-d9227bce64f1`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-05-21 12:50:48,895::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-05-21 12:50:48,895::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-05-21 12:50:48,895::task::993::TaskManager.Task::(_decref) Task=`a823d8b0-a6a3-4aec-ad39-d9227bce64f1`::ref 0 aborting False
>MainThread::DEBUG::2014-05-21 12:50:48,896::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::INFO::2014-05-21 12:50:48,924::momIF::47::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-05-21 12:50:48,929::vmchannels::188::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-05-21 12:50:48,931::vmchannels::171::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-05-21 12:50:48,942::libvirtconnection::146::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-05-21 12:50:48,943::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:50:48,943::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,943::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,943::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,944::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,944::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,944::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,944::misc::770::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-05-21 12:50:48,944::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:48,945::lvm::289::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-05-21 12:50:49,052::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:50:49,054::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:49,055::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:49,057::lvm::289::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-05-21 12:50:49,154::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:50:49,154::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:49,155::lvm::289::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)
>storageRefresh::DEBUG::2014-05-21 12:50:49,250::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:50:49,250::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:49,251::lvm::289::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-14::DEBUG::2014-05-21 12:50:49,326::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-05-21 12:50:49,326::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-05-21 12:50:49,345::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:50:49,345::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:50:49,345::hsm::384::Storage.HSM::(storageRefresh) HSM is ready
>Thread-15::DEBUG::2014-05-21 12:50:50,376::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-15::DEBUG::2014-05-21 12:50:50,414::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemSerialNumber': 'CZ134300VX', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '30303734-3536-5A43-3133-343330305658', 'systemManufacturer': 'HP'}}
>Thread-17::DEBUG::2014-05-21 12:50:50,545::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-05-21 12:50:50,545::task::595::TaskManager.Task::(_updateState) Task=`05376f0b-0f14-428e-9251-8f412b3356cd`::moving from state init -> state preparing
>Thread-17::INFO::2014-05-21 12:50:50,546::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-17::INFO::2014-05-21 12:50:50,546::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-17::DEBUG::2014-05-21 12:50:50,546::task::1188::TaskManager.Task::(prepare) Task=`05376f0b-0f14-428e-9251-8f412b3356cd`::finished: {'poollist': []}
>Thread-17::DEBUG::2014-05-21 12:50:50,546::task::595::TaskManager.Task::(_updateState) Task=`05376f0b-0f14-428e-9251-8f412b3356cd`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-05-21 12:50:50,546::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-05-21 12:50:50,546::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-05-21 12:50:50,547::task::993::TaskManager.Task::(_decref) Task=`05376f0b-0f14-428e-9251-8f412b3356cd`::ref 0 aborting False
>Thread-18::DEBUG::2014-05-21 12:52:59,948::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-18::DEBUG::2014-05-21 12:52:59,958::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemSerialNumber': 'CZ134300VX', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '30303734-3536-5A43-3133-343330305658', 'systemManufacturer': 'HP'}}
>Thread-20::DEBUG::2014-05-21 12:53:00,067::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-05-21 12:53:00,067::task::595::TaskManager.Task::(_updateState) Task=`01cae6fd-a148-4af1-b61b-9a307475e874`::moving from state init -> state preparing
>Thread-20::INFO::2014-05-21 12:53:00,067::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-20::INFO::2014-05-21 12:53:00,068::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-20::DEBUG::2014-05-21 12:53:00,068::task::1188::TaskManager.Task::(prepare) Task=`01cae6fd-a148-4af1-b61b-9a307475e874`::finished: {'poollist': []}
>Thread-20::DEBUG::2014-05-21 12:53:00,068::task::595::TaskManager.Task::(_updateState) Task=`01cae6fd-a148-4af1-b61b-9a307475e874`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-05-21 12:53:00,068::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-20::DEBUG::2014-05-21 12:53:00,068::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-05-21 12:53:00,068::task::993::TaskManager.Task::(_decref) Task=`01cae6fd-a148-4af1-b61b-9a307475e874`::ref 0 aborting False
>Thread-21::DEBUG::2014-05-21 12:53:02,979::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-21::DEBUG::2014-05-21 12:53:02,979::task::595::TaskManager.Task::(_updateState) Task=`978a81c9-7647-4991-ab0f-9fec489991db`::moving from state init -> state preparing
>Thread-21::INFO::2014-05-21 12:53:02,980::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-21::DEBUG::2014-05-21 12:53:02,980::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-21::DEBUG::2014-05-21 12:53:03,025::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-05-21 12:53:03,025::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-21::DEBUG::2014-05-21 12:53:03,042::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-05-21 12:53:03,043::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-21::DEBUG::2014-05-21 12:53:03,077::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-05-21 12:53:03,077::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-21::DEBUG::2014-05-21 12:53:03,101::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-05-21 12:53:03,101::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-21::DEBUG::2014-05-21 12:53:03,116::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-05-21 12:53:03,117::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-21::DEBUG::2014-05-21 12:53:03,129::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::INFO::2014-05-21 12:53:03,129::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-21::DEBUG::2014-05-21 12:53:03,134::task::1188::TaskManager.Task::(prepare) Task=`978a81c9-7647-4991-ab0f-9fec489991db`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-21::DEBUG::2014-05-21 12:53:03,134::task::595::TaskManager.Task::(_updateState) Task=`978a81c9-7647-4991-ab0f-9fec489991db`::moving from state preparing -> state finished
>Thread-21::DEBUG::2014-05-21 12:53:03,134::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21::DEBUG::2014-05-21 12:53:03,135::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21::DEBUG::2014-05-21 12:53:03,135::task::993::TaskManager.Task::(_decref) Task=`978a81c9-7647-4991-ab0f-9fec489991db`::ref 0 aborting False
>Thread-22::DEBUG::2014-05-21 12:53:03,184::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-22::DEBUG::2014-05-21 12:53:03,184::task::595::TaskManager.Task::(_updateState) Task=`fa6bf4e7-4870-49e0-98a6-648df76c2fff`::moving from state init -> state preparing
>Thread-22::INFO::2014-05-21 12:53:03,184::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-22::DEBUG::2014-05-21 12:53:03,185::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-22::DEBUG::2014-05-21 12:53:03,185::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-22::DEBUG::2014-05-21 12:53:03,185::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-22::DEBUG::2014-05-21 12:53:03,185::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-22::DEBUG::2014-05-21 12:53:03,185::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-22::DEBUG::2014-05-21 12:53:03,185::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-22::DEBUG::2014-05-21 12:53:03,196::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-22::DEBUG::2014-05-21 12:53:03,196::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-22::DEBUG::2014-05-21 12:53:03,280::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-22::DEBUG::2014-05-21 12:53:03,281::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,281::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,281::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,281::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,282::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,282::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,282::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-22::DEBUG::2014-05-21 12:53:03,282::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,284::lvm::289::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-22::DEBUG::2014-05-21 12:53:03,417::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-22::DEBUG::2014-05-21 12:53:03,417::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-22::DEBUG::2014-05-21 12:53:03,453::lvm::289::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-22::DEBUG::2014-05-21 12:53:03,545::lvm::289::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-22::DEBUG::2014-05-21 12:53:03,546::lvm::865::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-22::INFO::2014-05-21 12:53:03,546::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': []}
>Thread-22::DEBUG::2014-05-21 12:53:03,546::task::1188::TaskManager.Task::(prepare) Task=`fa6bf4e7-4870-49e0-98a6-648df76c2fff`::finished: {'devList': []}
>Thread-22::DEBUG::2014-05-21 12:53:03,546::task::595::TaskManager.Task::(_updateState) Task=`fa6bf4e7-4870-49e0-98a6-648df76c2fff`::moving from state preparing -> state finished
>Thread-22::DEBUG::2014-05-21 12:53:03,547::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-22::DEBUG::2014-05-21 12:53:03,547::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-22::DEBUG::2014-05-21 12:53:03,547::task::993::TaskManager.Task::(_decref) Task=`fa6bf4e7-4870-49e0-98a6-648df76c2fff`::ref 0 aborting False
>Thread-23::DEBUG::2014-05-21 12:53:03,604::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-23::DEBUG::2014-05-21 12:53:03,604::task::595::TaskManager.Task::(_updateState) Task=`8e451895-0b76-4e2b-8c65-b6d5f9f861ac`::moving from state init -> state preparing
>Thread-23::INFO::2014-05-21 12:53:03,605::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-23::DEBUG::2014-05-21 12:53:03,605::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-23::DEBUG::2014-05-21 12:53:03,618::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::DEBUG::2014-05-21 12:53:03,618::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-23::DEBUG::2014-05-21 12:53:03,630::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::DEBUG::2014-05-21 12:53:03,630::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-23::DEBUG::2014-05-21 12:53:03,642::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::DEBUG::2014-05-21 12:53:03,643::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-23::DEBUG::2014-05-21 12:53:03,655::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::DEBUG::2014-05-21 12:53:03,655::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-23::DEBUG::2014-05-21 12:53:03,670::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::DEBUG::2014-05-21 12:53:03,670::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-23::DEBUG::2014-05-21 12:53:03,685::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-23::INFO::2014-05-21 12:53:03,686::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-23::DEBUG::2014-05-21 12:53:03,686::task::1188::TaskManager.Task::(prepare) Task=`8e451895-0b76-4e2b-8c65-b6d5f9f861ac`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-23::DEBUG::2014-05-21 12:53:03,686::task::595::TaskManager.Task::(_updateState) Task=`8e451895-0b76-4e2b-8c65-b6d5f9f861ac`::moving from state preparing -> state finished
>Thread-23::DEBUG::2014-05-21 12:53:03,686::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-23::DEBUG::2014-05-21 12:53:03,686::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-23::DEBUG::2014-05-21 12:53:03,687::task::993::TaskManager.Task::(_decref) Task=`8e451895-0b76-4e2b-8c65-b6d5f9f861ac`::ref 0 aborting False
>Thread-24::DEBUG::2014-05-21 12:53:03,736::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-24::DEBUG::2014-05-21 12:53:03,737::task::595::TaskManager.Task::(_updateState) Task=`ff0be7ae-cb2d-4729-8d75-02174cb1c640`::moving from state init -> state preparing
>Thread-24::INFO::2014-05-21 12:53:03,737::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-24::DEBUG::2014-05-21 12:53:03,737::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-24::DEBUG::2014-05-21 12:53:03,756::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:03,757::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-24::DEBUG::2014-05-21 12:53:03,768::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:03,769::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-24::DEBUG::2014-05-21 12:53:03,780::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:03,781::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-24::DEBUG::2014-05-21 12:53:03,827::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:03,827::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-24::DEBUG::2014-05-21 12:53:05,118::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:05,118::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-24::DEBUG::2014-05-21 12:53:05,130::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:05,130::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-24::DEBUG::2014-05-21 12:53:05,131::lvm::289::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-24::DEBUG::2014-05-21 12:53:05,226::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-24::DEBUG::2014-05-21 12:53:05,226::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-24::DEBUG::2014-05-21 12:53:05,226::hsm::2315::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-24::DEBUG::2014-05-21 12:53:05,226::hsm::2371::Storage.HSM::(connectStorageServer) knownSDs: {}
>Thread-24::INFO::2014-05-21 12:53:05,227::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-24::DEBUG::2014-05-21 12:53:05,227::task::1188::TaskManager.Task::(prepare) Task=`ff0be7ae-cb2d-4729-8d75-02174cb1c640`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-24::DEBUG::2014-05-21 12:53:05,227::task::595::TaskManager.Task::(_updateState) Task=`ff0be7ae-cb2d-4729-8d75-02174cb1c640`::moving from state preparing -> state finished
>Thread-24::DEBUG::2014-05-21 12:53:05,227::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-24::DEBUG::2014-05-21 12:53:05,227::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-24::DEBUG::2014-05-21 12:53:05,227::task::993::TaskManager.Task::(_decref) Task=`ff0be7ae-cb2d-4729-8d75-02174cb1c640`::ref 0 aborting False
>Thread-25::DEBUG::2014-05-21 12:53:06,285::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-25::DEBUG::2014-05-21 12:53:06,285::task::595::TaskManager.Task::(_updateState) Task=`ad334270-21d1-4357-8d9b-6450e95c44e5`::moving from state init -> state preparing
>Thread-25::INFO::2014-05-21 12:53:06,286::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-25::DEBUG::2014-05-21 12:53:06,286::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-25::DEBUG::2014-05-21 12:53:06,286::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-25::DEBUG::2014-05-21 12:53:06,286::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-25::DEBUG::2014-05-21 12:53:06,286::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-25::DEBUG::2014-05-21 12:53:06,287::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-25::DEBUG::2014-05-21 12:53:06,287::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-25::DEBUG::2014-05-21 12:53:06,311::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-25::DEBUG::2014-05-21 12:53:06,311::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-25::DEBUG::2014-05-21 12:53:06,539::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-25::DEBUG::2014-05-21 12:53:06,540::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,540::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,540::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,541::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,541::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,541::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,541::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-25::DEBUG::2014-05-21 12:53:06,542::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,543::lvm::289::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-25::DEBUG::2014-05-21 12:53:06,667::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-25::DEBUG::2014-05-21 12:53:06,667::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 12:53:06,714::lvm::289::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-25::DEBUG::2014-05-21 12:53:06,840::lvm::289::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff\n'; <rc> = 5
>Thread-25::DEBUG::2014-05-21 12:53:06,841::lvm::865::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/33000000100000001'])
>Thread-25::INFO::2014-05-21 12:53:06,841::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-25::DEBUG::2014-05-21 12:53:06,846::task::1188::TaskManager.Task::(prepare) Task=`ad334270-21d1-4357-8d9b-6450e95c44e5`::finished: {'devList': [{'status': 'used', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr'}]}
>Thread-25::DEBUG::2014-05-21 12:53:06,847::task::595::TaskManager.Task::(_updateState) Task=`ad334270-21d1-4357-8d9b-6450e95c44e5`::moving from state preparing -> state finished
>Thread-25::DEBUG::2014-05-21 12:53:06,847::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-25::DEBUG::2014-05-21 12:53:06,847::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-25::DEBUG::2014-05-21 12:53:06,847::task::993::TaskManager.Task::(_decref) Task=`ad334270-21d1-4357-8d9b-6450e95c44e5`::ref 0 aborting False
>Thread-26::DEBUG::2014-05-21 12:53:07,904::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-26::DEBUG::2014-05-21 12:53:07,904::task::595::TaskManager.Task::(_updateState) Task=`b1de531c-6704-40cf-bc22-0427271f41be`::moving from state init -> state preparing
>Thread-26::INFO::2014-05-21 12:53:07,904::logUtils::44::dispatcher::(wrapper) Run and protect: getVGInfo(vgUUID='A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', options=None)
>Thread-26::DEBUG::2014-05-21 12:53:07,905::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-26::DEBUG::2014-05-21 12:53:07,905::lvm::289::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)
>Thread-26::DEBUG::2014-05-21 12:53:08,025::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-26::DEBUG::2014-05-21 12:53:08,025::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-26::INFO::2014-05-21 12:53:08,043::logUtils::47::dispatcher::(wrapper) Run and protect: getVGInfo, Return response: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-26::DEBUG::2014-05-21 12:53:08,043::task::1188::TaskManager.Task::(prepare) Task=`b1de531c-6704-40cf-bc22-0427271f41be`::finished: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-26::DEBUG::2014-05-21 12:53:08,043::task::595::TaskManager.Task::(_updateState) Task=`b1de531c-6704-40cf-bc22-0427271f41be`::moving from state preparing -> state finished
>Thread-26::DEBUG::2014-05-21 12:53:08,043::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-26::DEBUG::2014-05-21 12:53:08,043::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-26::DEBUG::2014-05-21 12:53:08,044::task::993::TaskManager.Task::(_decref) Task=`b1de531c-6704-40cf-bc22-0427271f41be`::ref 0 aborting False
>Thread-27::DEBUG::2014-05-21 12:53:08,094::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-27::DEBUG::2014-05-21 12:53:08,094::task::595::TaskManager.Task::(_updateState) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::moving from state init -> state preparing
>Thread-27::INFO::2014-05-21 12:53:08,094::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='23a755d5-7279-452d-a01c-58506a3ad040', options=None)
>Thread-27::ERROR::2014-05-21 12:53:08,095::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 23a755d5-7279-452d-a01c-58506a3ad040
>Thread-27::ERROR::2014-05-21 12:53:08,095::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 23a755d5-7279-452d-a01c-58506a3ad040
>Thread-27::DEBUG::2014-05-21 12:53:08,096::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-27::DEBUG::2014-05-21 12:53:08,096::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 23a755d5-7279-452d-a01c-58506a3ad040/metadata' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:08,310::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:08,310::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,310::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,311::blockSD::335::Storage.Misc.excCmd::(readlines) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/23a755d5-7279-452d-a01c-58506a3ad040/metadata count=1' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:08,317::blockSD::335::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000757011 s, 2.7 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:08,317::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000757011 s, 2.7 MB/s'], size: 2048
>Thread-27::DEBUG::2014-05-21 12:53:08,318::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-27::WARNING::2014-05-21 12:53:08,318::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-27::DEBUG::2014-05-21 12:53:08,318::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-27::DEBUG::2014-05-21 12:53:08,318::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,319::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,319::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,319::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,319::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,320::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:08,433::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:08,433::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,434::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-27::DEBUG::2014-05-21 12:53:08,435::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 23a755d5-7279-452d-a01c-58506a3ad040/ids' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:08,633::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:08,634::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,634::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,635::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 23a755d5-7279-452d-a01c-58506a3ad040/leases' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:08,836::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:08,837::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,837::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:08,838::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 23a755d5-7279-452d-a01c-58506a3ad040/inbox 23a755d5-7279-452d-a01c-58506a3ad040/outbox 23a755d5-7279-452d-a01c-58506a3ad040/master' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:09,055::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:09,056::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,056::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,057::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_imageNS'
>Thread-27::DEBUG::2014-05-21 12:53:09,057::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_volumeNS'
>Thread-27::DEBUG::2014-05-21 12:53:09,057::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_lvmActivationNS'
>Thread-27::INFO::2014-05-21 12:53:09,058::blockSD::841::Storage.StorageDomain::(validate) sdUUID=23a755d5-7279-452d-a01c-58506a3ad040
>Thread-27::DEBUG::2014-05-21 12:53:09,058::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --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 } " 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:09,172::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:09,172::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,173::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,173::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,173::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,173::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,174::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-27::DEBUG::2014-05-21 12:53:09,286::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 12:53:09,287::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 12:53:09,287::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-27::DEBUG::2014-05-21 12:53:09,288::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`9a9f45ce-53fa-4aec-8583-ea0fd95c6f0f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2731' at 'getStorageDomainInfo'
>Thread-27::DEBUG::2014-05-21 12:53:09,288::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' for lock type 'shared'
>Thread-27::DEBUG::2014-05-21 12:53:09,289::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free. Now locking as 'shared' (1 active user)
>Thread-27::DEBUG::2014-05-21 12:53:09,289::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`9a9f45ce-53fa-4aec-8583-ea0fd95c6f0f`::Granted request
>Thread-27::DEBUG::2014-05-21 12:53:09,289::task::827::TaskManager.Task::(resourceAcquired) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::_resourcesAcquired: Storage.23a755d5-7279-452d-a01c-58506a3ad040 (shared)
>Thread-27::DEBUG::2014-05-21 12:53:09,289::task::993::TaskManager.Task::(_decref) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::ref 1 aborting False
>Thread-27::INFO::2014-05-21 12:53:09,290::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-27::DEBUG::2014-05-21 12:53:09,290::task::1188::TaskManager.Task::(prepare) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::finished: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-27::DEBUG::2014-05-21 12:53:09,290::task::595::TaskManager.Task::(_updateState) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::moving from state preparing -> state finished
>Thread-27::DEBUG::2014-05-21 12:53:09,290::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.23a755d5-7279-452d-a01c-58506a3ad040': < ResourceRef 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', isValid: 'True' obj: 'None'>}
>Thread-27::DEBUG::2014-05-21 12:53:09,291::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-27::DEBUG::2014-05-21 12:53:09,291::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040'
>Thread-27::DEBUG::2014-05-21 12:53:09,291::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' (0 active users)
>Thread-27::DEBUG::2014-05-21 12:53:09,291::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free, finding out if anyone is waiting for it.
>Thread-27::DEBUG::2014-05-21 12:53:09,291::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', Clearing records.
>Thread-27::DEBUG::2014-05-21 12:53:09,292::task::993::TaskManager.Task::(_decref) Task=`d6b157d6-d628-4a01-999e-6061f2b83b6e`::ref 0 aborting False
>Thread-28::DEBUG::2014-05-21 12:54:53,272::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-28::DEBUG::2014-05-21 12:54:53,278::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemSerialNumber': 'CZ134300VX', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '30303734-3536-5A43-3133-343330305658', 'systemManufacturer': 'HP'}}
>Thread-30::DEBUG::2014-05-21 12:54:53,388::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-30::DEBUG::2014-05-21 12:54:53,388::task::595::TaskManager.Task::(_updateState) Task=`5de2369b-dc1d-404a-9743-ad61f5ba5287`::moving from state init -> state preparing
>Thread-30::INFO::2014-05-21 12:54:53,388::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-30::INFO::2014-05-21 12:54:53,389::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-30::DEBUG::2014-05-21 12:54:53,389::task::1188::TaskManager.Task::(prepare) Task=`5de2369b-dc1d-404a-9743-ad61f5ba5287`::finished: {'poollist': []}
>Thread-30::DEBUG::2014-05-21 12:54:53,389::task::595::TaskManager.Task::(_updateState) Task=`5de2369b-dc1d-404a-9743-ad61f5ba5287`::moving from state preparing -> state finished
>Thread-30::DEBUG::2014-05-21 12:54:53,389::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-30::DEBUG::2014-05-21 12:54:53,389::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-30::DEBUG::2014-05-21 12:54:53,389::task::993::TaskManager.Task::(_decref) Task=`5de2369b-dc1d-404a-9743-ad61f5ba5287`::ref 0 aborting False
>Thread-31::DEBUG::2014-05-21 12:55:10,019::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-31::DEBUG::2014-05-21 12:55:10,020::task::595::TaskManager.Task::(_updateState) Task=`3278ad82-357d-468e-b88d-4389959a89d5`::moving from state init -> state preparing
>Thread-31::INFO::2014-05-21 12:55:10,020::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-31::DEBUG::2014-05-21 12:55:10,020::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-31::DEBUG::2014-05-21 12:55:10,049::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-05-21 12:55:10,049::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-31::DEBUG::2014-05-21 12:55:10,062::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-05-21 12:55:10,062::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-31::DEBUG::2014-05-21 12:55:10,106::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-05-21 12:55:10,107::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-31::DEBUG::2014-05-21 12:55:10,135::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-05-21 12:55:10,135::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-31::DEBUG::2014-05-21 12:55:10,150::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::DEBUG::2014-05-21 12:55:10,151::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-31::DEBUG::2014-05-21 12:55:10,162::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-31::INFO::2014-05-21 12:55:10,163::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-31::DEBUG::2014-05-21 12:55:10,163::task::1188::TaskManager.Task::(prepare) Task=`3278ad82-357d-468e-b88d-4389959a89d5`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-31::DEBUG::2014-05-21 12:55:10,163::task::595::TaskManager.Task::(_updateState) Task=`3278ad82-357d-468e-b88d-4389959a89d5`::moving from state preparing -> state finished
>Thread-31::DEBUG::2014-05-21 12:55:10,163::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-31::DEBUG::2014-05-21 12:55:10,164::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-31::DEBUG::2014-05-21 12:55:10,164::task::993::TaskManager.Task::(_decref) Task=`3278ad82-357d-468e-b88d-4389959a89d5`::ref 0 aborting False
>Thread-32::DEBUG::2014-05-21 12:55:11,427::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-32::DEBUG::2014-05-21 12:55:11,427::task::595::TaskManager.Task::(_updateState) Task=`fa8b6f41-ab61-4d20-bacb-6c55bb48e686`::moving from state init -> state preparing
>Thread-32::INFO::2014-05-21 12:55:11,427::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-32::DEBUG::2014-05-21 12:55:11,428::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-32::DEBUG::2014-05-21 12:55:11,428::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-32::DEBUG::2014-05-21 12:55:11,428::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-32::DEBUG::2014-05-21 12:55:11,428::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-32::DEBUG::2014-05-21 12:55:11,428::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-32::DEBUG::2014-05-21 12:55:11,428::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-32::DEBUG::2014-05-21 12:55:11,444::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-32::DEBUG::2014-05-21 12:55:11,444::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-32::DEBUG::2014-05-21 12:55:11,711::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-32::DEBUG::2014-05-21 12:55:11,712::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,717::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,717::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,717::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,718::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,718::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,718::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-32::DEBUG::2014-05-21 12:55:11,718::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,721::lvm::289::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-32::DEBUG::2014-05-21 12:55:11,860::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-32::DEBUG::2014-05-21 12:55:11,861::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-32::DEBUG::2014-05-21 12:55:11,904::lvm::289::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-32::DEBUG::2014-05-21 12:55:12,033::lvm::289::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff\n'; <rc> = 5
>Thread-32::DEBUG::2014-05-21 12:55:12,035::lvm::865::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/33000000100000001'])
>Thread-32::INFO::2014-05-21 12:55:12,035::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-32::DEBUG::2014-05-21 12:55:12,036::task::1188::TaskManager.Task::(prepare) Task=`fa8b6f41-ab61-4d20-bacb-6c55bb48e686`::finished: {'devList': [{'status': 'used', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr'}]}
>Thread-32::DEBUG::2014-05-21 12:55:12,036::task::595::TaskManager.Task::(_updateState) Task=`fa8b6f41-ab61-4d20-bacb-6c55bb48e686`::moving from state preparing -> state finished
>Thread-32::DEBUG::2014-05-21 12:55:12,036::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-32::DEBUG::2014-05-21 12:55:12,036::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-32::DEBUG::2014-05-21 12:55:12,036::task::993::TaskManager.Task::(_decref) Task=`fa8b6f41-ab61-4d20-bacb-6c55bb48e686`::ref 0 aborting False
>Thread-33::DEBUG::2014-05-21 12:55:13,097::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-33::DEBUG::2014-05-21 12:55:13,097::task::595::TaskManager.Task::(_updateState) Task=`4c35ea66-53f3-4e73-9fed-bf66b0ef55d0`::moving from state init -> state preparing
>Thread-33::INFO::2014-05-21 12:55:13,097::logUtils::44::dispatcher::(wrapper) Run and protect: getVGInfo(vgUUID='A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', options=None)
>Thread-33::DEBUG::2014-05-21 12:55:13,098::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-33::DEBUG::2014-05-21 12:55:13,098::lvm::289::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)
>Thread-33::DEBUG::2014-05-21 12:55:13,214::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-33::DEBUG::2014-05-21 12:55:13,215::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-33::INFO::2014-05-21 12:55:13,232::logUtils::47::dispatcher::(wrapper) Run and protect: getVGInfo, Return response: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-33::DEBUG::2014-05-21 12:55:13,232::task::1188::TaskManager.Task::(prepare) Task=`4c35ea66-53f3-4e73-9fed-bf66b0ef55d0`::finished: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-33::DEBUG::2014-05-21 12:55:13,233::task::595::TaskManager.Task::(_updateState) Task=`4c35ea66-53f3-4e73-9fed-bf66b0ef55d0`::moving from state preparing -> state finished
>Thread-33::DEBUG::2014-05-21 12:55:13,233::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-33::DEBUG::2014-05-21 12:55:13,233::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-33::DEBUG::2014-05-21 12:55:13,233::task::993::TaskManager.Task::(_decref) Task=`4c35ea66-53f3-4e73-9fed-bf66b0ef55d0`::ref 0 aborting False
>Thread-34::DEBUG::2014-05-21 12:55:13,284::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-34::DEBUG::2014-05-21 12:55:13,284::task::595::TaskManager.Task::(_updateState) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::moving from state init -> state preparing
>Thread-34::INFO::2014-05-21 12:55:13,284::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='23a755d5-7279-452d-a01c-58506a3ad040', options=None)
>Thread-34::INFO::2014-05-21 12:55:13,285::blockSD::841::Storage.StorageDomain::(validate) sdUUID=23a755d5-7279-452d-a01c-58506a3ad040
>Thread-34::DEBUG::2014-05-21 12:55:13,285::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --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 } " 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-34::DEBUG::2014-05-21 12:55:13,398::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-34::DEBUG::2014-05-21 12:55:13,398::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,398::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,398::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,398::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,399::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,399::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-34::DEBUG::2014-05-21 12:55:13,511::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-34::DEBUG::2014-05-21 12:55:13,512::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-34::DEBUG::2014-05-21 12:55:13,512::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-34::DEBUG::2014-05-21 12:55:13,513::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`30d811cd-f025-41e5-860a-13fba156e0e0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2731' at 'getStorageDomainInfo'
>Thread-34::DEBUG::2014-05-21 12:55:13,513::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' for lock type 'shared'
>Thread-34::DEBUG::2014-05-21 12:55:13,514::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free. Now locking as 'shared' (1 active user)
>Thread-34::DEBUG::2014-05-21 12:55:13,514::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`30d811cd-f025-41e5-860a-13fba156e0e0`::Granted request
>Thread-34::DEBUG::2014-05-21 12:55:13,514::task::827::TaskManager.Task::(resourceAcquired) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::_resourcesAcquired: Storage.23a755d5-7279-452d-a01c-58506a3ad040 (shared)
>Thread-34::DEBUG::2014-05-21 12:55:13,514::task::993::TaskManager.Task::(_decref) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::ref 1 aborting False
>Thread-34::INFO::2014-05-21 12:55:13,515::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-34::DEBUG::2014-05-21 12:55:13,515::task::1188::TaskManager.Task::(prepare) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::finished: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-34::DEBUG::2014-05-21 12:55:13,515::task::595::TaskManager.Task::(_updateState) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::moving from state preparing -> state finished
>Thread-34::DEBUG::2014-05-21 12:55:13,515::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.23a755d5-7279-452d-a01c-58506a3ad040': < ResourceRef 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', isValid: 'True' obj: 'None'>}
>Thread-34::DEBUG::2014-05-21 12:55:13,516::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-34::DEBUG::2014-05-21 12:55:13,516::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040'
>Thread-34::DEBUG::2014-05-21 12:55:13,516::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' (0 active users)
>Thread-34::DEBUG::2014-05-21 12:55:13,516::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free, finding out if anyone is waiting for it.
>Thread-34::DEBUG::2014-05-21 12:55:13,516::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', Clearing records.
>Thread-34::DEBUG::2014-05-21 12:55:13,516::task::993::TaskManager.Task::(_decref) Task=`c478b551-1e38-498b-8811-91ec64175cf1`::ref 0 aborting False
>MainThread::DEBUG::2014-05-21 12:56:11,775::vdsm::56::vds::(sigtermHandler) Received signal 15
>MainThread::INFO::2014-05-21 12:56:12,308::vmchannels::184::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-05-21 12:56:12,308::momIF::84::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-05-21 12:56:12,309::task::595::TaskManager.Task::(_updateState) Task=`52e49425-f0e4-49f8-9228-4f0e2e740ba1`::moving from state init -> state preparing
>MainThread::INFO::2014-05-21 12:56:12,309::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-12::DEBUG::2014-05-21 12:56:12,310::storageServer::699::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>MainThread::INFO::2014-05-21 12:56:12,330::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::DEBUG::2014-05-21 12:56:12,331::taskManager::81::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-05-21 12:56:12,331::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-05-21 12:56:12,331::task::1188::TaskManager.Task::(prepare) Task=`52e49425-f0e4-49f8-9228-4f0e2e740ba1`::finished: None
>MainThread::DEBUG::2014-05-21 12:56:12,331::task::595::TaskManager.Task::(_updateState) Task=`52e49425-f0e4-49f8-9228-4f0e2e740ba1`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-05-21 12:56:12,331::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-05-21 12:56:12,331::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-05-21 12:56:12,331::task::993::TaskManager.Task::(_decref) Task=`52e49425-f0e4-49f8-9228-4f0e2e740ba1`::ref 0 aborting False
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::135::vds::(run) VDSM main thread ended. Waiting for 17 other threads...
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <_MainThread(MainThread, started 140323815048960)>
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <Thread(Thread-1, started daemon 140323548440320)>
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <WorkerThread(Thread-11, started daemon 140322755573504)>
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140321816049408)>
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <GuestManager(GuestManager, started daemon 140322254202624)>
>MainThread::INFO::2014-05-21 12:56:12,332::vdsm::139::vds::(run) <HostMonitor(HostMonitor, started daemon 140322264692480)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <WorkerThread(Thread-8, started daemon 140323126757120)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <WorkerThread(Thread-7, started daemon 140323137246976)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <WorkerThread(Thread-5, started daemon 140323158226688)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <WorkerThread(Thread-2, started daemon 140323527460608)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <Thread(libvirtEventLoop, started daemon 140323537950464)>
>MainThread::INFO::2014-05-21 12:56:12,333::momIF::84::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <MomThread(MOM, started 140322710927104)>
>MainThread::INFO::2014-05-21 12:56:12,333::vdsm::139::vds::(run) <WorkerThread(Thread-3, started daemon 140323516970752)>
>MainThread::INFO::2014-05-21 12:56:12,334::vmchannels::184::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-05-21 12:56:12,334::vdsm::139::vds::(run) <Listener(VM Channels Listener, started daemon 140322285811456)>
>MainThread::INFO::2014-05-21 12:56:12,334::vdsm::139::vds::(run) <WorkerThread(Thread-9, started daemon 140323116267264)>
>MainThread::INFO::2014-05-21 12:56:12,334::vdsm::139::vds::(run) <WorkerThread(Thread-10, started daemon 140323105777408)>
>MainThread::INFO::2014-05-21 12:56:12,334::vdsm::139::vds::(run) <WorkerThread(Thread-6, started daemon 140323147736832)>
>MainThread::INFO::2014-05-21 12:56:12,334::vdsm::139::vds::(run) <WorkerThread(Thread-4, started daemon 140323506480896)>
>VM Channels Listener::INFO::2014-05-21 12:56:13,291::vmchannels::179::vds::(run) VM channels listener thread has ended.
>MainThread::WARNING::2014-05-21 12:56:22,609::vdsmDebugPlugin::40::DebugInterpreter::(__turnOnDebugPlugin) Starting Debug Interpreter. Tread lightly!
>MainThread::INFO::2014-05-21 12:56:22,611::vdsm::129::vds::(run) (PID: 583) I am the actual vdsm 4.14.10-0.el6 localhost.localdomain (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-05-21 12:56:22,612::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-05-21 12:56:22,612::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10, waitTimeout: 3, maxTasks: 500
>MainThread::DEBUG::2014-05-21 12:56:22,614::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /rhev/data-center/mnt
>MainThread::WARNING::2014-05-21 12:56:22,614::fileUtils::149::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-05-21 12:56:22,644::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-05-21 12:56:22,650::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-05-21 12:56:22,651::hsm::415::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-05-21 12:56:22,753::hsm::415::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-05-21 12:56:22,753::hsm::439::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-05-21 12:56:22,756::hsm::471::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-05-21 12:56:22,756::hsm::472::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-05-21 12:56:22,756::hsm::474::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-05-21 12:56:22,758::hsm::517::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-05-21 12:56:22,758::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-05-21 12:56:22,760::dispatcher::46::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-05-21 12:56:22,781::misc::762::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-05-21 12:56:22,781::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-05-21 12:56:22,782::misc::762::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-05-21 12:56:22,782::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-05-21 12:56:22,782::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-05-21 12:56:22,796::misc::770::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-05-21 12:56:22,796::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::DEBUG::2014-05-21 12:56:22,811::task::595::TaskManager.Task::(_updateState) Task=`7edc9adc-c9ce-4258-9424-e5c0ca5e16c2`::moving from state init -> state preparing
>MainThread::INFO::2014-05-21 12:56:22,811::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1674b00>>)
>MainThread::INFO::2014-05-21 12:56:22,811::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-05-21 12:56:22,811::task::1188::TaskManager.Task::(prepare) Task=`7edc9adc-c9ce-4258-9424-e5c0ca5e16c2`::finished: None
>MainThread::DEBUG::2014-05-21 12:56:22,811::task::595::TaskManager.Task::(_updateState) Task=`7edc9adc-c9ce-4258-9424-e5c0ca5e16c2`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-05-21 12:56:22,812::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-05-21 12:56:22,812::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-05-21 12:56:22,812::task::993::TaskManager.Task::(_decref) Task=`7edc9adc-c9ce-4258-9424-e5c0ca5e16c2`::ref 0 aborting False
>MainThread::INFO::2014-05-21 12:56:22,815::momIF::47::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-05-21 12:56:22,818::vmchannels::188::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-05-21 12:56:22,821::vmchannels::171::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-05-21 12:56:22,841::libvirtconnection::146::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-05-21 12:56:23,126::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:56:23,127::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,127::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,127::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,127::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,128::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,128::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,128::misc::770::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-05-21 12:56:23,128::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,130::lvm::289::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-05-21 12:56:23,296::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:56:23,297::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,297::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,298::lvm::289::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-05-21 12:56:23,417::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:56:23,417::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,418::lvm::289::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-05-21 12:56:23,538::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::INFO::2014-05-21 12:56:23,539::lvm::662::Storage.LVM::(bootstrap) Activating lvs: vg=23a755d5-7279-452d-a01c-58506a3ad040 lvs=['ha_agent-hosted-engine.metadata', 'ha_agent-hosted-engine.lockspace']
>storageRefresh::DEBUG::2014-05-21 12:56:23,539::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 23a755d5-7279-452d-a01c-58506a3ad040/ha_agent-hosted-engine.metadata 23a755d5-7279-452d-a01c-58506a3ad040/ha_agent-hosted-engine.lockspace' (cwd None)
>storageRefresh::DEBUG::2014-05-21 12:56:23,750::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:56:23,751::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,751::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,751::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:23,751::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::INFO::2014-05-21 12:56:23,752::lvm::681::Storage.LVM::(bootstrap) Refreshing lvs: vg=23a755d5-7279-452d-a01c-58506a3ad040 lvs=['ids', 'outbox', 'leases', 'metadata', 'inbox', 'master']
>storageRefresh::DEBUG::2014-05-21 12:56:23,752::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/33000000100000001|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --refresh 23a755d5-7279-452d-a01c-58506a3ad040/ids 23a755d5-7279-452d-a01c-58506a3ad040/outbox 23a755d5-7279-452d-a01c-58506a3ad040/leases 23a755d5-7279-452d-a01c-58506a3ad040/metadata 23a755d5-7279-452d-a01c-58506a3ad040/inbox 23a755d5-7279-452d-a01c-58506a3ad040/master' (cwd None)
>storageRefresh::DEBUG::2014-05-21 12:56:24,055::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-05-21 12:56:24,055::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:24,056::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-05-21 12:56:24,056::hsm::384::Storage.HSM::(storageRefresh) HSM is ready
>Thread-14::DEBUG::2014-05-21 12:59:59,894::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-05-21 12:59:59,901::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemSerialNumber': 'CZ134300VX', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '30303734-3536-5A43-3133-343330305658', 'systemManufacturer': 'HP'}}
>Thread-16::DEBUG::2014-05-21 13:00:00,010::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-05-21 13:00:00,010::task::595::TaskManager.Task::(_updateState) Task=`b013e16e-5f71-4bd0-a57a-93c570dbb53b`::moving from state init -> state preparing
>Thread-16::INFO::2014-05-21 13:00:00,010::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-16::INFO::2014-05-21 13:00:00,011::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-16::DEBUG::2014-05-21 13:00:00,011::task::1188::TaskManager.Task::(prepare) Task=`b013e16e-5f71-4bd0-a57a-93c570dbb53b`::finished: {'poollist': []}
>Thread-16::DEBUG::2014-05-21 13:00:00,011::task::595::TaskManager.Task::(_updateState) Task=`b013e16e-5f71-4bd0-a57a-93c570dbb53b`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-05-21 13:00:00,011::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-05-21 13:00:00,011::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-05-21 13:00:00,012::task::993::TaskManager.Task::(_decref) Task=`b013e16e-5f71-4bd0-a57a-93c570dbb53b`::ref 0 aborting False
>Thread-17::DEBUG::2014-05-21 13:00:15,784::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-05-21 13:00:15,785::task::595::TaskManager.Task::(_updateState) Task=`a6774742-c77f-4814-a0a5-aad72caef489`::moving from state init -> state preparing
>Thread-17::INFO::2014-05-21 13:00:15,785::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-05-21 13:00:15,785::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-05-21 13:00:15,811::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-05-21 13:00:15,811::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-05-21 13:00:15,822::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-05-21 13:00:15,823::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-05-21 13:00:15,872::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-05-21 13:00:15,873::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-05-21 13:00:15,899::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-05-21 13:00:15,899::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-05-21 13:00:15,913::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-05-21 13:00:15,914::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-05-21 13:00:15,924::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::INFO::2014-05-21 13:00:15,925::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-05-21 13:00:15,925::task::1188::TaskManager.Task::(prepare) Task=`a6774742-c77f-4814-a0a5-aad72caef489`::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-05-21 13:00:15,925::task::595::TaskManager.Task::(_updateState) Task=`a6774742-c77f-4814-a0a5-aad72caef489`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-05-21 13:00:15,925::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-05-21 13:00:15,926::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-05-21 13:00:15,926::task::993::TaskManager.Task::(_decref) Task=`a6774742-c77f-4814-a0a5-aad72caef489`::ref 0 aborting False
>Thread-18::DEBUG::2014-05-21 13:00:16,900::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-18::DEBUG::2014-05-21 13:00:16,900::task::595::TaskManager.Task::(_updateState) Task=`22c89e2b-c293-406d-a7dc-6d87275bdb28`::moving from state init -> state preparing
>Thread-18::INFO::2014-05-21 13:00:16,900::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-18::DEBUG::2014-05-21 13:00:16,901::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-18::DEBUG::2014-05-21 13:00:16,901::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-05-21 13:00:16,901::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-18::DEBUG::2014-05-21 13:00:16,901::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-05-21 13:00:16,901::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-18::DEBUG::2014-05-21 13:00:16,902::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-18::DEBUG::2014-05-21 13:00:16,916::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-05-21 13:00:16,917::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-18::DEBUG::2014-05-21 13:00:17,189::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-18::DEBUG::2014-05-21 13:00:17,190::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,190::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,190::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,191::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,191::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,191::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,191::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-05-21 13:00:17,191::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,194::lvm::289::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-18::DEBUG::2014-05-21 13:00:17,338::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-18::DEBUG::2014-05-21 13:00:17,338::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-18::DEBUG::2014-05-21 13:00:17,385::lvm::289::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-18::DEBUG::2014-05-21 13:00:17,504::lvm::289::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff\n'; <rc> = 5
>Thread-18::DEBUG::2014-05-21 13:00:17,505::lvm::865::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/33000000100000001'])
>Thread-18::INFO::2014-05-21 13:00:17,506::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-18::DEBUG::2014-05-21 13:00:17,506::task::1188::TaskManager.Task::(prepare) Task=`22c89e2b-c293-406d-a7dc-6d87275bdb28`::finished: {'devList': [{'status': 'used', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr'}]}
>Thread-18::DEBUG::2014-05-21 13:00:17,506::task::595::TaskManager.Task::(_updateState) Task=`22c89e2b-c293-406d-a7dc-6d87275bdb28`::moving from state preparing -> state finished
>Thread-18::DEBUG::2014-05-21 13:00:17,507::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-18::DEBUG::2014-05-21 13:00:17,507::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-05-21 13:00:17,507::task::993::TaskManager.Task::(_decref) Task=`22c89e2b-c293-406d-a7dc-6d87275bdb28`::ref 0 aborting False
>Thread-19::DEBUG::2014-05-21 13:00:18,570::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-19::DEBUG::2014-05-21 13:00:18,570::task::595::TaskManager.Task::(_updateState) Task=`887381cc-114c-4948-907e-3cfddfbd7aa8`::moving from state init -> state preparing
>Thread-19::INFO::2014-05-21 13:00:18,571::logUtils::44::dispatcher::(wrapper) Run and protect: getVGInfo(vgUUID='A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', options=None)
>Thread-19::DEBUG::2014-05-21 13:00:18,571::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-19::DEBUG::2014-05-21 13:00:18,572::lvm::289::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)
>Thread-19::DEBUG::2014-05-21 13:00:18,692::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-19::DEBUG::2014-05-21 13:00:18,693::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-19::INFO::2014-05-21 13:00:18,709::logUtils::47::dispatcher::(wrapper) Run and protect: getVGInfo, Return response: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-19::DEBUG::2014-05-21 13:00:18,709::task::1188::TaskManager.Task::(prepare) Task=`887381cc-114c-4948-907e-3cfddfbd7aa8`::finished: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-19::DEBUG::2014-05-21 13:00:18,709::task::595::TaskManager.Task::(_updateState) Task=`887381cc-114c-4948-907e-3cfddfbd7aa8`::moving from state preparing -> state finished
>Thread-19::DEBUG::2014-05-21 13:00:18,709::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-19::DEBUG::2014-05-21 13:00:18,709::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-19::DEBUG::2014-05-21 13:00:18,710::task::993::TaskManager.Task::(_decref) Task=`887381cc-114c-4948-907e-3cfddfbd7aa8`::ref 0 aborting False
>Thread-20::DEBUG::2014-05-21 13:00:18,761::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-05-21 13:00:18,761::task::595::TaskManager.Task::(_updateState) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::moving from state init -> state preparing
>Thread-20::INFO::2014-05-21 13:00:18,761::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='23a755d5-7279-452d-a01c-58506a3ad040', options=None)
>Thread-20::ERROR::2014-05-21 13:00:18,762::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 23a755d5-7279-452d-a01c-58506a3ad040
>Thread-20::ERROR::2014-05-21 13:00:18,762::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 23a755d5-7279-452d-a01c-58506a3ad040
>Thread-20::DEBUG::2014-05-21 13:00:18,762::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with LvMetadataRW backend
>Thread-20::DEBUG::2014-05-21 13:00:18,762::blockSD::335::Storage.Misc.excCmd::(readlines) '/bin/dd iflag=direct skip=0 bs=2048 if=/dev/23a755d5-7279-452d-a01c-58506a3ad040/metadata count=1' (cwd None)
>Thread-20::DEBUG::2014-05-21 13:00:18,768::blockSD::335::Storage.Misc.excCmd::(readlines) SUCCESS: <err> = '1+0 records in\n1+0 records out\n2048 bytes (2.0 kB) copied, 0.000789123 s, 2.6 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-05-21 13:00:18,768::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '2048 bytes (2.0 kB) copied, 0.000789123 s, 2.6 MB/s'], size: 2048
>Thread-20::DEBUG::2014-05-21 13:00:18,768::persistentDict::234::Storage.PersistentDict::(refresh) read lines (LvMetadataRW)=[]
>Thread-20::WARNING::2014-05-21 13:00:18,768::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-20::DEBUG::2014-05-21 13:00:18,768::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with VGTagMetadataRW backend
>Thread-20::DEBUG::2014-05-21 13:00:18,769::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,769::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,769::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,769::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,770::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,770::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-20::DEBUG::2014-05-21 13:00:18,882::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-05-21 13:00:18,883::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,883::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-20::DEBUG::2014-05-21 13:00:18,884::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_imageNS'
>Thread-20::DEBUG::2014-05-21 13:00:18,885::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_volumeNS'
>Thread-20::DEBUG::2014-05-21 13:00:18,885::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '23a755d5-7279-452d-a01c-58506a3ad040_lvmActivationNS'
>Thread-20::INFO::2014-05-21 13:00:18,885::blockSD::841::Storage.StorageDomain::(validate) sdUUID=23a755d5-7279-452d-a01c-58506a3ad040
>Thread-20::DEBUG::2014-05-21 13:00:18,886::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --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 } " 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-20::DEBUG::2014-05-21 13:00:18,998::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-05-21 13:00:18,999::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,999::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:18,999::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:19,000::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:19,000::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:19,000::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-20::DEBUG::2014-05-21 13:00:19,113::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-05-21 13:00:19,113::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-20::DEBUG::2014-05-21 13:00:19,114::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-20::DEBUG::2014-05-21 13:00:19,115::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`90db48d5-7b85-46e0-9dc1-a83122cc99ab`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2731' at 'getStorageDomainInfo'
>Thread-20::DEBUG::2014-05-21 13:00:19,115::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' for lock type 'shared'
>Thread-20::DEBUG::2014-05-21 13:00:19,115::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free. Now locking as 'shared' (1 active user)
>Thread-20::DEBUG::2014-05-21 13:00:19,115::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`90db48d5-7b85-46e0-9dc1-a83122cc99ab`::Granted request
>Thread-20::DEBUG::2014-05-21 13:00:19,116::task::827::TaskManager.Task::(resourceAcquired) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::_resourcesAcquired: Storage.23a755d5-7279-452d-a01c-58506a3ad040 (shared)
>Thread-20::DEBUG::2014-05-21 13:00:19,116::task::993::TaskManager.Task::(_decref) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::ref 1 aborting False
>Thread-20::INFO::2014-05-21 13:00:19,116::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-20::DEBUG::2014-05-21 13:00:19,117::task::1188::TaskManager.Task::(prepare) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::finished: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-20::DEBUG::2014-05-21 13:00:19,117::task::595::TaskManager.Task::(_updateState) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-05-21 13:00:19,117::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.23a755d5-7279-452d-a01c-58506a3ad040': < ResourceRef 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', isValid: 'True' obj: 'None'>}
>Thread-20::DEBUG::2014-05-21 13:00:19,117::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-05-21 13:00:19,117::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040'
>Thread-20::DEBUG::2014-05-21 13:00:19,118::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' (0 active users)
>Thread-20::DEBUG::2014-05-21 13:00:19,118::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free, finding out if anyone is waiting for it.
>Thread-20::DEBUG::2014-05-21 13:00:19,118::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', Clearing records.
>Thread-20::DEBUG::2014-05-21 13:00:19,118::task::993::TaskManager.Task::(_decref) Task=`fd730045-1831-456a-8baa-96b8f2f24543`::ref 0 aborting False
>Thread-21::DEBUG::2014-05-21 13:58:21,316::BindingXMLRPC::1056::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-21::DEBUG::2014-05-21 13:58:21,332::BindingXMLRPC::1063::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemSerialNumber': 'CZ134300VX', 'systemFamily': 'ProLiant', 'systemVersion': 'Not Specified', 'systemUUID': '30303734-3536-5A43-3133-343330305658', 'systemManufacturer': 'HP'}}
>Thread-23::DEBUG::2014-05-21 13:58:21,443::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-23::DEBUG::2014-05-21 13:58:21,443::task::595::TaskManager.Task::(_updateState) Task=`48e69c66-0321-49ea-88cd-7f777c30c129`::moving from state init -> state preparing
>Thread-23::INFO::2014-05-21 13:58:21,443::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-23::INFO::2014-05-21 13:58:21,444::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-23::DEBUG::2014-05-21 13:58:21,444::task::1188::TaskManager.Task::(prepare) Task=`48e69c66-0321-49ea-88cd-7f777c30c129`::finished: {'poollist': []}
>Thread-23::DEBUG::2014-05-21 13:58:21,444::task::595::TaskManager.Task::(_updateState) Task=`48e69c66-0321-49ea-88cd-7f777c30c129`::moving from state preparing -> state finished
>Thread-23::DEBUG::2014-05-21 13:58:21,444::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-23::DEBUG::2014-05-21 13:58:21,444::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-23::DEBUG::2014-05-21 13:58:21,444::task::993::TaskManager.Task::(_decref) Task=`48e69c66-0321-49ea-88cd-7f777c30c129`::ref 0 aborting False
>Thread-24::DEBUG::2014-05-21 13:58:38,717::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-24::DEBUG::2014-05-21 13:58:38,718::task::595::TaskManager.Task::(_updateState) Task=`770f12e9-fe47-4eee-9aa5-d479e39c2a98`::moving from state init -> state preparing
>Thread-24::INFO::2014-05-21 13:58:38,718::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '10.34.131.193', 'password': '******', 'port': '3260', 'user': 'engine'}, options=None)
>Thread-24::DEBUG::2014-05-21 13:58:38,718::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-24::DEBUG::2014-05-21 13:58:38,750::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 13:58:38,750::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-24::DEBUG::2014-05-21 13:58:38,761::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 13:58:38,762::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-24::DEBUG::2014-05-21 13:58:38,775::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 13:58:38,776::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-24::DEBUG::2014-05-21 13:58:38,787::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 13:58:38,787::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-24::DEBUG::2014-05-21 13:58:38,829::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::DEBUG::2014-05-21 13:58:38,830::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-24::DEBUG::2014-05-21 13:58:38,839::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-24::INFO::2014-05-21 13:58:38,840::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-24::DEBUG::2014-05-21 13:58:38,840::task::1188::TaskManager.Task::(prepare) Task=`770f12e9-fe47-4eee-9aa5-d479e39c2a98`::finished: {'fullTargets': ['10.34.131.193:3260,1 iqn.2009-02.com.example:for.all'], 'targets': ['iqn.2009-02.com.example:for.all']}
>Thread-24::DEBUG::2014-05-21 13:58:38,840::task::595::TaskManager.Task::(_updateState) Task=`770f12e9-fe47-4eee-9aa5-d479e39c2a98`::moving from state preparing -> state finished
>Thread-24::DEBUG::2014-05-21 13:58:38,840::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-24::DEBUG::2014-05-21 13:58:38,840::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-24::DEBUG::2014-05-21 13:58:38,841::task::993::TaskManager.Task::(_decref) Task=`770f12e9-fe47-4eee-9aa5-d479e39c2a98`::ref 0 aborting False
>Thread-25::DEBUG::2014-05-21 13:58:40,266::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-25::DEBUG::2014-05-21 13:58:40,266::task::595::TaskManager.Task::(_updateState) Task=`6a40f056-99de-48c5-a27b-e378f531c5d6`::moving from state init -> state preparing
>Thread-25::INFO::2014-05-21 13:58:40,267::logUtils::44::dispatcher::(wrapper) Run and protect: getDeviceList(storageType=3, options={})
>Thread-25::DEBUG::2014-05-21 13:58:40,267::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-25::DEBUG::2014-05-21 13:58:40,267::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-25::DEBUG::2014-05-21 13:58:40,267::misc::760::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-25::DEBUG::2014-05-21 13:58:40,267::misc::762::SamplingMethod::(__call__) Got in to sampling method
>Thread-25::DEBUG::2014-05-21 13:58:40,267::iscsi::403::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-25::DEBUG::2014-05-21 13:58:40,268::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-25::DEBUG::2014-05-21 13:58:40,281::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-25::DEBUG::2014-05-21 13:58:40,281::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-25::DEBUG::2014-05-21 13:58:40,589::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-25::DEBUG::2014-05-21 13:58:40,589::lvm::490::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,590::lvm::492::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,590::lvm::501::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,590::lvm::503::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,590::lvm::521::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,591::lvm::523::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,591::misc::770::SamplingMethod::(__call__) Returning last result
>Thread-25::DEBUG::2014-05-21 13:58:40,591::lvm::318::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,593::lvm::289::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-25::DEBUG::2014-05-21 13:58:40,741::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-25::DEBUG::2014-05-21 13:58:40,741::lvm::343::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>Thread-25::DEBUG::2014-05-21 13:58:40,785::lvm::289::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-25::DEBUG::2014-05-21 13:58:40,909::lvm::289::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.\n  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff\n'; <rc> = 5
>Thread-25::DEBUG::2014-05-21 13:58:40,911::lvm::865::Storage.LVM::(testPVCreate) rc: 5, out: [], err: ['  TEST MODE: Metadata will NOT be updated and volumes will not be (de)activated.', '  Can\'t initialize physical volume "/dev/mapper/33000000100000001" of volume group "23a755d5-7279-452d-a01c-58506a3ad040" without -ff'], unusedDevs: set([]), usedDevs: set(['/dev/mapper/33000000100000001'])
>Thread-25::INFO::2014-05-21 13:58:40,912::logUtils::47::dispatcher::(wrapper) Run and protect: getDeviceList, Return response: {'devList': [{'status': 'used', 'vendorID': 'IET', 'capacity': '52428800000', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'productID': 'VIRTUAL-DISK'}]}
>Thread-25::DEBUG::2014-05-21 13:58:40,912::task::1188::TaskManager.Task::(prepare) Task=`6a40f056-99de-48c5-a27b-e378f531c5d6`::finished: {'devList': [{'status': 'used', 'fwrev': '0001', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', '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': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr'}]}
>Thread-25::DEBUG::2014-05-21 13:58:40,913::task::595::TaskManager.Task::(_updateState) Task=`6a40f056-99de-48c5-a27b-e378f531c5d6`::moving from state preparing -> state finished
>Thread-25::DEBUG::2014-05-21 13:58:40,913::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-25::DEBUG::2014-05-21 13:58:40,913::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-25::DEBUG::2014-05-21 13:58:40,913::task::993::TaskManager.Task::(_decref) Task=`6a40f056-99de-48c5-a27b-e378f531c5d6`::ref 0 aborting False
>Thread-26::DEBUG::2014-05-21 13:58:41,970::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-26::DEBUG::2014-05-21 13:58:41,970::task::595::TaskManager.Task::(_updateState) Task=`cc227a5f-2f0a-4ab8-962d-ffafdb034f51`::moving from state init -> state preparing
>Thread-26::INFO::2014-05-21 13:58:41,970::logUtils::44::dispatcher::(wrapper) Run and protect: getVGInfo(vgUUID='A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', options=None)
>Thread-26::DEBUG::2014-05-21 13:58:41,971::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-26::DEBUG::2014-05-21 13:58:41,971::lvm::289::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)
>Thread-26::DEBUG::2014-05-21 13:58:42,092::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-26::DEBUG::2014-05-21 13:58:42,092::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-26::INFO::2014-05-21 13:58:42,126::logUtils::47::dispatcher::(wrapper) Run and protect: getVGInfo, Return response: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-26::DEBUG::2014-05-21 13:58:42,126::task::1188::TaskManager.Task::(prepare) Task=`cc227a5f-2f0a-4ab8-962d-ffafdb034f51`::finished: {'info': {'state': 'OK', 'vgsize': '52076478464', 'name': '23a755d5-7279-452d-a01c-58506a3ad040', 'vgfree': '20803747840', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pvlist': [{'vendorID': 'IET', 'capacity': '52076478464', 'fwrev': '0000', 'vgUUID': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'pathlist': [{'initiatorname': 'default', 'connection': '10.34.131.193', 'iqn': 'iqn.2009-02.com.example:for.all', 'portal': '1', 'user': 'engine', 'password': 'kokotice', 'port': '3260'}], 'pathstatus': [{'physdev': 'sdc', 'type': 'iSCSI', 'state': 'active', 'lun': '1'}], 'devtype': 'iSCSI', 'pvUUID': 'jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr', 'serial': 'SIET_VIRTUAL-DISK', 'GUID': '33000000100000001', 'devcapacity': '52428800000', 'productID': 'VIRTUAL-DISK'}], 'type': 3, 'attr': {'allocation': 'n', 'partial': '-', 'exported': '-', 'permission': 'w', 'clustered': '-', 'resizeable': 'z'}}}
>Thread-26::DEBUG::2014-05-21 13:58:42,126::task::595::TaskManager.Task::(_updateState) Task=`cc227a5f-2f0a-4ab8-962d-ffafdb034f51`::moving from state preparing -> state finished
>Thread-26::DEBUG::2014-05-21 13:58:42,126::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-26::DEBUG::2014-05-21 13:58:42,127::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-26::DEBUG::2014-05-21 13:58:42,127::task::993::TaskManager.Task::(_decref) Task=`cc227a5f-2f0a-4ab8-962d-ffafdb034f51`::ref 0 aborting False
>Thread-27::DEBUG::2014-05-21 13:58:42,182::BindingXMLRPC::249::vds::(wrapper) client [127.0.0.1]
>Thread-27::DEBUG::2014-05-21 13:58:42,182::task::595::TaskManager.Task::(_updateState) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::moving from state init -> state preparing
>Thread-27::INFO::2014-05-21 13:58:42,182::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='23a755d5-7279-452d-a01c-58506a3ad040', options=None)
>Thread-27::INFO::2014-05-21 13:58:42,183::blockSD::841::Storage.StorageDomain::(validate) sdUUID=23a755d5-7279-452d-a01c-58506a3ad040
>Thread-27::DEBUG::2014-05-21 13:58:42,183::lvm::289::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --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 } " 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-27::DEBUG::2014-05-21 13:58:42,294::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 13:58:42,294::lvm::496::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,294::lvm::498::OperationMutex::(_invalidatevgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,294::lvm::506::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,295::lvm::518::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,295::lvm::366::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,295::lvm::289::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 23a755d5-7279-452d-a01c-58506a3ad040' (cwd None)
>Thread-27::DEBUG::2014-05-21 13:58:42,409::lvm::289::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-27::DEBUG::2014-05-21 13:58:42,410::lvm::408::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-27::DEBUG::2014-05-21 13:58:42,410::persistentDict::234::Storage.PersistentDict::(refresh) read lines (VGTagMetadataRW)=['VGUUID=A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'LEASETIMESEC=60', 'SDUUID=23a755d5-7279-452d-a01c-58506a3ad040', 'VERSION=3', 'DESCRIPTION=hosted_storage', 'LOGBLKSIZE=512', 'TYPE=ISCSI', u'PV0=pv:33000000100000001,uuid:jxm6QF-Pm1L-y8sB-1u3H-E5jX-WOaf-DR3Okr,pestart:0,pecount:388,mapoffset:0', 'LEASERETRIES=3', 'IOOPTIMEOUTSEC=10', 'LOCKRENEWALINTERVALSEC=5', 'CLASS=Data', 'PHYBLKSIZE=4096', 'LOCKPOLICY=ON', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=23a755d5-7279-452d-a01c-58506a3ad040:Active', 'ROLE=Master', 'POOL_UUID=7734ccd9-0b3c-465e-ac3a-4df7760867ff', 'POOL_SPM_LVER=0', 'POOL_SPM_ID=-1', '_SHA_CKSUM=75ed8533048e215866e5fbed5c930eb6c94bc789']
>Thread-27::DEBUG::2014-05-21 13:58:42,411::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`dcfdb744-ea34-4f83-ac2c-0a976e4c4cce`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2731' at 'getStorageDomainInfo'
>Thread-27::DEBUG::2014-05-21 13:58:42,411::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' for lock type 'shared'
>Thread-27::DEBUG::2014-05-21 13:58:42,412::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free. Now locking as 'shared' (1 active user)
>Thread-27::DEBUG::2014-05-21 13:58:42,412::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.23a755d5-7279-452d-a01c-58506a3ad040`ReqID=`dcfdb744-ea34-4f83-ac2c-0a976e4c4cce`::Granted request
>Thread-27::DEBUG::2014-05-21 13:58:42,412::task::827::TaskManager.Task::(resourceAcquired) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::_resourcesAcquired: Storage.23a755d5-7279-452d-a01c-58506a3ad040 (shared)
>Thread-27::DEBUG::2014-05-21 13:58:42,413::task::993::TaskManager.Task::(_decref) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::ref 1 aborting False
>Thread-27::INFO::2014-05-21 13:58:42,413::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-27::DEBUG::2014-05-21 13:58:42,413::task::1188::TaskManager.Task::(prepare) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::finished: {'info': {'uuid': '23a755d5-7279-452d-a01c-58506a3ad040', 'vguuid': 'A96G0Y-rIJh-AarE-EQrg-G8Ea-FcvG-7UuAsS', 'state': 'OK', 'version': '3', 'role': 'Master', 'type': 'ISCSI', 'class': 'Data', 'pool': ['7734ccd9-0b3c-465e-ac3a-4df7760867ff'], 'name': 'hosted_storage'}}
>Thread-27::DEBUG::2014-05-21 13:58:42,413::task::595::TaskManager.Task::(_updateState) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::moving from state preparing -> state finished
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.23a755d5-7279-452d-a01c-58506a3ad040': < ResourceRef 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', isValid: 'True' obj: 'None'>}
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040'
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' (0 active users)
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040' is free, finding out if anyone is waiting for it.
>Thread-27::DEBUG::2014-05-21 13:58:42,414::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.23a755d5-7279-452d-a01c-58506a3ad040', Clearing records.
>Thread-27::DEBUG::2014-05-21 13:58:42,415::task::993::TaskManager.Task::(_decref) Task=`b03cb0f4-7517-4b24-be58-1ab7d55166ad`::ref 0 aborting False

Actions: View

Attachments on bug 1099882: 897947 | 897948