Attachment 916035 Details for Bug 1116785 – vdsm log

vdsm log

vdsm.log (text/plain), 217.44 KB, created by Jiri Moskovcak on 2014-07-07 10:50:08 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jiri Moskovcak

Created: 2014-07-07 10:50:08 UTC

Size: 217.44 KB

patch

obsolete

>MainThread::INFO::2014-07-07 11:57:00,859::vdsm::119::vds::(run) (PID: 30545) I am the actual vdsm 4.14.7-4.el6ev dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-07 11:57:00,860::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-07 11:57:00,860::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::DEBUG::2014-07-07 11:57:01,161::multipath::150::Storage.Multipath::(isEnabled) multipath Defaulting to False
>MainThread::DEBUG::2014-07-07 11:57:01,161::multipath::168::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /bin/cp /tmp/tmp0gPQmJ /etc/multipath.conf' (cwd None)
>MainThread::DEBUG::2014-07-07 11:57:01,172::multipath::168::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-07 11:57:01,173::multipath::174::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
>MainThread::DEBUG::2014-07-07 11:57:01,193::multipath::174::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-07 11:57:01,193::multipath::177::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /usr/bin/vdsm-tool service-reload multipathd' (cwd None)
>MainThread::DEBUG::2014-07-07 11:57:01,338::multipath::177::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-07 11:57:01,339::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-07-07 11:57:01,459::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-07 11:57:01,459::hsm::458::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-07 11:57:01,462::hsm::490::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-07 11:57:01,462::hsm::491::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-07 11:57:01,462::hsm::493::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-07 11:57:01,463::hsm::536::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-07 11:57:01,463::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-07 11:57:01,464::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-07 11:57:01,484::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-07 11:57:01,484::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-07 11:57:01,485::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-07 11:57:01,485::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-07 11:57:01,485::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-07-07 11:57:01,501::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-07 11:57:01,501::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>MainThread::DEBUG::2014-07-07 11:57:01,521::task::595::TaskManager.Task::(_updateState) Task=`8f936fca-8358-405b-951b-9d8ea3c35869`::moving from state init -> state preparing
>MainThread::INFO::2014-07-07 11:57:01,521::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1b42320>>)
>MainThread::INFO::2014-07-07 11:57:01,521::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-07 11:57:01,521::task::1185::TaskManager.Task::(prepare) Task=`8f936fca-8358-405b-951b-9d8ea3c35869`::finished: None
>MainThread::DEBUG::2014-07-07 11:57:01,522::task::595::TaskManager.Task::(_updateState) Task=`8f936fca-8358-405b-951b-9d8ea3c35869`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-07 11:57:01,522::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-07 11:57:01,522::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-07 11:57:01,522::task::990::TaskManager.Task::(_decref) Task=`8f936fca-8358-405b-951b-9d8ea3c35869`::ref 0 aborting False
>MainThread::INFO::2014-07-07 11:57:01,530::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-07 11:57:01,533::vmChannels::191::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-07 11:57:01,534::vmChannels::174::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-07 11:57:01,548::libvirtconnection::145::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-07 11:57:01,549::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 11:57:01,549::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,550::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-07 11:57:01,551::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,552::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>storageRefresh::DEBUG::2014-07-07 11:57:01,653::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 11:57:01,654::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,659::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,661::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-13::DEBUG::2014-07-07 11:57:01,717::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-07 11:57:01,718::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-07-07 11:57:01,756::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 11:57:01,756::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,756::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>storageRefresh::DEBUG::2014-07-07 11:57:01,845::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 11:57:01,845::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,846::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>storageRefresh::DEBUG::2014-07-07 11:57:01,934::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 11:57:01,934::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 11:57:01,935::hsm::393::Storage.HSM::(storageRefresh) HSM is ready
>Thread-14::DEBUG::2014-07-07 11:57:02,770::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-07-07 11:57:02,771::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>Thread-14::DEBUG::2014-07-07 11:57:02,823::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Thread-16::DEBUG::2014-07-07 11:57:02,949::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-07-07 11:57:02,950::task::595::TaskManager.Task::(_updateState) Task=`2dd04cf2-13c8-4025-99e9-e24b45da8a56`::moving from state init -> state preparing
>Thread-16::INFO::2014-07-07 11:57:02,950::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-16::INFO::2014-07-07 11:57:02,950::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-16::DEBUG::2014-07-07 11:57:02,951::task::1185::TaskManager.Task::(prepare) Task=`2dd04cf2-13c8-4025-99e9-e24b45da8a56`::finished: {'poollist': []}
>Thread-16::DEBUG::2014-07-07 11:57:02,951::task::595::TaskManager.Task::(_updateState) Task=`2dd04cf2-13c8-4025-99e9-e24b45da8a56`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-07-07 11:57:02,951::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-07-07 11:57:02,951::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-07-07 11:57:02,951::task::990::TaskManager.Task::(_decref) Task=`2dd04cf2-13c8-4025-99e9-e24b45da8a56`::ref 0 aborting False
>Thread-17::DEBUG::2014-07-07 11:58:55,624::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-07-07 11:58:55,625::task::595::TaskManager.Task::(_updateState) Task=`a42887da-a8a1-49fc-a21e-a2ddb1db5d35`::moving from state init -> state preparing
>Thread-17::INFO::2014-07-07 11:58:55,625::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}], options=None)
>Thread-17::DEBUG::2014-07-07 11:58:55,628::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04 /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04' (cwd None)
>Thread-17::DEBUG::2014-07-07 11:58:55,789::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04
>Thread-17::DEBUG::2014-07-07 11:58:55,792::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-17::DEBUG::2014-07-07 11:58:55,792::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {}
>Thread-17::INFO::2014-07-07 11:58:55,793::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-17::DEBUG::2014-07-07 11:58:55,793::task::1185::TaskManager.Task::(prepare) Task=`a42887da-a8a1-49fc-a21e-a2ddb1db5d35`::finished: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-17::DEBUG::2014-07-07 11:58:55,793::task::595::TaskManager.Task::(_updateState) Task=`a42887da-a8a1-49fc-a21e-a2ddb1db5d35`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-07-07 11:58:55,793::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-07-07 11:58:55,793::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-07-07 11:58:55,794::task::990::TaskManager.Task::(_decref) Task=`a42887da-a8a1-49fc-a21e-a2ddb1db5d35`::ref 0 aborting False
>Thread-18::DEBUG::2014-07-07 11:58:55,846::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-18::DEBUG::2014-07-07 11:58:55,847::task::595::TaskManager.Task::(_updateState) Task=`496efe8c-64f4-4e9b-9618-f064d0df1cb0`::moving from state init -> state preparing
>Thread-18::INFO::2014-07-07 11:58:55,847::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000', domainClass=None, storageType=None, remotePath=None, options=None)
>Thread-18::DEBUG::2014-07-07 11:58:55,847::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-18::DEBUG::2014-07-07 11:58:55,847::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-07-07 11:58:55,848::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-18::DEBUG::2014-07-07 11:58:55,848::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-18::DEBUG::2014-07-07 11:58:55,848::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-18::DEBUG::2014-07-07 11:58:55,848::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-18::DEBUG::2014-07-07 11:58:55,859::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-07-07 11:58:55,859::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-18::DEBUG::2014-07-07 11:58:55,941::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-18::DEBUG::2014-07-07 11:58:55,942::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,942::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,942::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,942::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,942::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,943::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,943::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-18::DEBUG::2014-07-07 11:58:55,943::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-18::DEBUG::2014-07-07 11:58:55,945::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-18::DEBUG::2014-07-07 11:58:56,061::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-18::DEBUG::2014-07-07 11:58:56,062::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-18::INFO::2014-07-07 11:58:56,155::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': []}
>Thread-18::DEBUG::2014-07-07 11:58:56,155::task::1185::TaskManager.Task::(prepare) Task=`496efe8c-64f4-4e9b-9618-f064d0df1cb0`::finished: {'domlist': []}
>Thread-18::DEBUG::2014-07-07 11:58:56,155::task::595::TaskManager.Task::(_updateState) Task=`496efe8c-64f4-4e9b-9618-f064d0df1cb0`::moving from state preparing -> state finished
>Thread-18::DEBUG::2014-07-07 11:58:56,156::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-18::DEBUG::2014-07-07 11:58:56,156::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-07-07 11:58:56,156::task::990::TaskManager.Task::(_decref) Task=`496efe8c-64f4-4e9b-9618-f064d0df1cb0`::ref 0 aborting False
>Thread-20::DEBUG::2014-07-07 11:58:56,214::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-07-07 11:58:56,214::task::595::TaskManager.Task::(_updateState) Task=`2efd5289-c024-4834-b769-c9806c830d29`::moving from state init -> state preparing
>Thread-20::INFO::2014-07-07 11:58:56,214::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}], options=None)
>Thread-20::DEBUG::2014-07-07 11:58:56,215::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04' (cwd None)
>Thread-20::DEBUG::2014-07-07 11:58:56,250::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-20::DEBUG::2014-07-07 11:58:56,250::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-20::DEBUG::2014-07-07 11:58:56,250::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-20::DEBUG::2014-07-07 11:58:56,251::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-20::DEBUG::2014-07-07 11:58:56,251::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-20::DEBUG::2014-07-07 11:58:56,251::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-20::DEBUG::2014-07-07 11:58:56,262::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-20::DEBUG::2014-07-07 11:58:56,263::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-20::DEBUG::2014-07-07 11:58:56,291::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-07 11:58:56,291::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,291::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,292::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,292::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,292::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,292::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 11:58:56,292::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-20::INFO::2014-07-07 11:58:56,293::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-20::DEBUG::2014-07-07 11:58:56,293::task::1185::TaskManager.Task::(prepare) Task=`2efd5289-c024-4834-b769-c9806c830d29`::finished: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-20::DEBUG::2014-07-07 11:58:56,293::task::595::TaskManager.Task::(_updateState) Task=`2efd5289-c024-4834-b769-c9806c830d29`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-07-07 11:58:56,293::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-20::DEBUG::2014-07-07 11:58:56,293::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-07-07 11:58:56,294::task::990::TaskManager.Task::(_decref) Task=`2efd5289-c024-4834-b769-c9806c830d29`::ref 0 aborting False
>MainThread::DEBUG::2014-07-07 12:00:51,085::vdsm::55::vds::(sigtermHandler) Received signal 15
>MainThread::INFO::2014-07-07 12:00:51,297::vmChannels::187::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-07 12:00:51,298::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-07-07 12:00:51,299::task::595::TaskManager.Task::(_updateState) Task=`467fceec-b866-402b-abae-033c20726b47`::moving from state init -> state preparing
>MainThread::INFO::2014-07-07 12:00:51,299::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-07-07 12:00:51,300::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>MainThread::INFO::2014-07-07 12:00:51,652::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::DEBUG::2014-07-07 12:00:51,653::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-07-07 12:00:51,656::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-07-07 12:00:51,656::task::1185::TaskManager.Task::(prepare) Task=`467fceec-b866-402b-abae-033c20726b47`::finished: None
>MainThread::DEBUG::2014-07-07 12:00:51,656::task::595::TaskManager.Task::(_updateState) Task=`467fceec-b866-402b-abae-033c20726b47`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-07 12:00:51,656::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-07 12:00:51,656::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-07 12:00:51,657::task::990::TaskManager.Task::(_decref) Task=`467fceec-b866-402b-abae-033c20726b47`::ref 0 aborting False
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 16 other threads...
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <_MainThread(MainThread, started 139952926885632)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 139952747362048)>
>MainThread::INFO::2014-07-07 12:00:51,657::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <MomThread(MOM, started 139951710664448)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 139952180426496)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 139952597739264)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 139952618718976)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 139952159446784)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 139952169936640)>
>MainThread::INFO::2014-07-07 12:00:51,657::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 139952650188544)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <WorkerThread(Thread-1, started daemon 139952736872192)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 139952608229120)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <HostMonitor(HostMonitor, started daemon 139951660230400)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <GuestManager(GuestManager, started daemon 139951240902400)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 139952639698688)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 139951230412544)>
>MainThread::INFO::2014-07-07 12:00:51,658::vmChannels::187::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <Listener(VM Channels Listener, started daemon 139951689684736)>
>MainThread::INFO::2014-07-07 12:00:51,658::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 139952629208832)>
>VM Channels Listener::INFO::2014-07-07 12:00:51,794::vmChannels::182::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-07-07 12:00:54,929::vdsm::119::vds::(run) (PID: 31111) I am the actual vdsm 4.14.7-4.el6ev dev-27.rhev.lab.eng.brq.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-07-07 12:00:54,930::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-07 12:00:54,930::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::WARNING::2014-07-07 12:00:54,933::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-07 12:00:55,210::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-07 12:00:55,214::multipath::141::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-07 12:00:55,215::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-07-07 12:00:55,332::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-07 12:00:55,333::hsm::458::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-07 12:00:55,336::hsm::490::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-07 12:00:55,336::hsm::491::Storage.HSM::(__cleanStorageRepository) Mount list: []
>MainThread::DEBUG::2014-07-07 12:00:55,336::hsm::493::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-07 12:00:55,338::hsm::536::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-07 12:00:55,338::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-07 12:00:55,339::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-07 12:00:55,340::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-07 12:00:55,362::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-07 12:00:55,362::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-07 12:00:55,363::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-07 12:00:55,364::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-07-07 12:00:55,373::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-07 12:00:55,373::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>MainThread::DEBUG::2014-07-07 12:00:55,382::task::595::TaskManager.Task::(_updateState) Task=`91fdda9b-a48f-4ae2-8227-bf02f151cbce`::moving from state init -> state preparing
>MainThread::INFO::2014-07-07 12:00:55,382::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1ea3638>>)
>MainThread::INFO::2014-07-07 12:00:55,383::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-07 12:00:55,383::task::1185::TaskManager.Task::(prepare) Task=`91fdda9b-a48f-4ae2-8227-bf02f151cbce`::finished: None
>MainThread::DEBUG::2014-07-07 12:00:55,383::task::595::TaskManager.Task::(_updateState) Task=`91fdda9b-a48f-4ae2-8227-bf02f151cbce`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-07 12:00:55,383::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-07 12:00:55,383::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-07 12:00:55,383::task::990::TaskManager.Task::(_decref) Task=`91fdda9b-a48f-4ae2-8227-bf02f151cbce`::ref 0 aborting False
>MainThread::INFO::2014-07-07 12:00:55,391::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-07 12:00:55,396::vmChannels::191::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-07 12:00:55,409::vmChannels::174::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-07 12:00:55,413::libvirtconnection::145::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-07-07 12:00:55,459::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 12:00:55,464::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,467::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,471::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,474::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,476::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,479::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,480::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-07 12:00:55,482::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,495::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>storageRefresh::DEBUG::2014-07-07 12:00:55,608::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 12:00:55,609::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,613::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,613::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>storageRefresh::DEBUG::2014-07-07 12:00:55,706::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 12:00:55,707::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,707::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>storageRefresh::DEBUG::2014-07-07 12:00:55,796::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 12:00:55,796::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-07 12:00:55,796::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-13::DEBUG::2014-07-07 12:00:55,828::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-07 12:00:55,829::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-07-07 12:00:55,884::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-07 12:00:55,884::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::WARNING::2014-07-07 12:00:55,885::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
>storageRefresh::DEBUG::2014-07-07 12:00:55,885::hsm::393::Storage.HSM::(storageRefresh) HSM is ready
>Thread-14::DEBUG::2014-07-07 12:00:56,879::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-07-07 12:00:56,887::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'ProLiant DL320e Gen8', 'systemUUID': '30303734-3536-5A43-3133-343330305746', 'systemSerialNumber': 'CZ134300WF', 'systemFamily': 'ProLiant', 'systemManufacturer': 'HP'}}
>Thread-15::DEBUG::2014-07-07 12:00:56,937::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
>Thread-15::DEBUG::2014-07-07 12:00:57,008::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
>Thread-15::DEBUG::2014-07-07 12:00:57,022::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-15::DEBUG::2014-07-07 12:00:57,082::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:fdf6e93f880'}], 'FC': []}, 'packages2': {'kernel': {'release': '431.el6.x86_64', 'buildtime': 1385086509.0, 'version': '2.6.32'}, 'spice-server': {'release': '6.el6_5.2', 'buildtime': 1402324637L, 'version': '0.12.4'}, 'vdsm': {'release': '4.el6ev', 'buildtime': 1403687001L, 'version': '4.14.7'}, 'qemu-kvm': {'release': '2.415.el6_5.11', 'buildtime': 1403019242L, 'version': '0.12.1.2'}, 'libvirt': {'release': '29.el6_5.9', 'buildtime': 1402404612L, 'version': '0.10.2'}, 'qemu-img': {'release': '2.415.el6_5.11', 'buildtime': 1403019242L, 'version': '0.12.1.2'}, 'mom': {'release': '2.el6', 'buildtime': 1403794344L, 'version': '0.4.1'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E3-1220 V2 @ 3.10GHz', 'hooks': {'before_vm_start': {'50_hostedengine': {'md5': '45dde62155b5412eafbfff5ef265acc2'}}}, 'cpuSockets': '1', 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {}, 'bridges': {';vdsmdummy;': {'addr': '', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ipv6gateway': '::', 'gateway': '', 'ports': []}}, 'uuid': '30303734-3536-5A43-3133-343330305746_a4:5d:36:11:e4:80', 'lastClientIface': 'lo', 'nics': {'eth1': {'netmask': '', 'addr': '', 'hwaddr': 'a4:5d:36:11:e4:81', 'cfg': {'UUID': '05144631-4917-43ba-b356-385026c82c5c', 'NM_CONTROLLED': 'yes', 'HWADDR': 'A4:5D:36:11:E4:81', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth1', 'TYPE': 'Ethernet', 'ONBOOT': 'no'}, 'ipv6addrs': [], 'speed': 0, 'mtu': '1500'}, 'eth0': {'netmask': '255.255.252.0', 'addr': '10.34.63.108', 'hwaddr': 'a4:5d:36:11:e4:80', 'cfg': {'IPV6INIT': 'no', 'NM_CONTROLLED': 'yes', 'MTU': '1500', 'HWADDR': 'A4:5D:36:11:E4:80', 'BOOTPROTO': 'dhcp', 'DEVICE': 'eth0', 'TYPE': 'Ethernet', 'ONBOOT': 'yes', 'UUID': '401af6f4-1f18-4318-8bf0-ab276e7a27ed'}, 'ipv6addrs': [], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '4', 'management_ip': '0.0.0.0', 'clusterLevels': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,xtopology,nonstop_tsc,aperfmperf,pni,pclmulqdq,dtes64,monitor,ds_cpl,vmx,smx,est,tm2,ssse3,cx16,xtpr,pdcm,pcid,sse4_1,sse4_2,x2apic,popcnt,tsc_deadline_timer,aes,xsave,avx,f16c,rdrand,lahf_lm,ida,arat,epb,xsaveopt,pln,pts,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,fsgsbase,smep,erms,model_Nehalem,model_Conroe,model_coreduo,model_core2duo,model_Penryn,model_Westmere,model_n270,model_SandyBridge', 'ISCSIInitiatorName': 'iqn.1994-05.com.redhat:fdf6e93f880', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond4': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond1': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond2': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}, 'bond3': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '15782', 'cpuSpeed': '2128.000', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0'], 'cpuThreads': '4', 'emulatedMachines': [u'rhel6.5.0', u'pc', u'rhel6.4.0', u'rhel6.3.0', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'rngSources': ['random'], 'operatingSystem': {'release': '5.el6.centos.11.1', 'version': '6', 'name': 'RHEL'}, 'lastClient': '127.0.0.1'}}
>Thread-16::DEBUG::2014-07-07 12:00:57,233::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call addNetwork with ('rhevm', '', '', ['eth0'], {'blockingdhcp': 'true', 'bootproto': 'dhcp', 'force': 'False', 'ONBOOT': 'yes', 'bridged': 'True'}) {}
>Thread-16::DEBUG::2014-07-07 12:01:08,180::BindingXMLRPC::1074::vds::(wrapper) return addNetwork with {'status': {'message': 'Done', 'code': 0}}
>Thread-17::DEBUG::2014-07-07 12:01:08,263::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call setSafeNetworkConfig with () {}
>Thread-17::DEBUG::2014-07-07 12:01:08,272::BindingXMLRPC::1074::vds::(wrapper) return setSafeNetworkConfig with {'status': {'message': 'Done', 'code': 0}}
>Thread-18::DEBUG::2014-07-07 12:01:21,246::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-18::DEBUG::2014-07-07 12:01:21,251::task::595::TaskManager.Task::(_updateState) Task=`367aeb7b-a1cb-4edb-b2ff-ea62419b8ee6`::moving from state init -> state preparing
>Thread-18::INFO::2014-07-07 12:01:21,252::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-18::INFO::2014-07-07 12:01:21,252::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-18::DEBUG::2014-07-07 12:01:21,252::task::1185::TaskManager.Task::(prepare) Task=`367aeb7b-a1cb-4edb-b2ff-ea62419b8ee6`::finished: {'poollist': []}
>Thread-18::DEBUG::2014-07-07 12:01:21,252::task::595::TaskManager.Task::(_updateState) Task=`367aeb7b-a1cb-4edb-b2ff-ea62419b8ee6`::moving from state preparing -> state finished
>Thread-18::DEBUG::2014-07-07 12:01:21,252::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-18::DEBUG::2014-07-07 12:01:21,253::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-07-07 12:01:21,253::task::990::TaskManager.Task::(_decref) Task=`367aeb7b-a1cb-4edb-b2ff-ea62419b8ee6`::ref 0 aborting False
>Thread-19::DEBUG::2014-07-07 12:01:21,302::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-19::DEBUG::2014-07-07 12:01:21,302::task::595::TaskManager.Task::(_updateState) Task=`d6258925-bac0-4a4d-babc-c0856d6b2181`::moving from state init -> state preparing
>Thread-19::INFO::2014-07-07 12:01:21,302::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}], options=None)
>Thread-19::DEBUG::2014-07-07 12:01:21,307::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04 /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04' (cwd None)
>Thread-19::DEBUG::2014-07-07 12:01:21,478::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04
>Thread-19::DEBUG::2014-07-07 12:01:21,480::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-19::DEBUG::2014-07-07 12:01:21,481::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {}
>Thread-19::INFO::2014-07-07 12:01:21,481::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-19::DEBUG::2014-07-07 12:01:21,481::task::1185::TaskManager.Task::(prepare) Task=`d6258925-bac0-4a4d-babc-c0856d6b2181`::finished: {'statuslist': [{'status': 0, 'id': '768406d6-267a-4dc0-99e2-c3ef2d8c10f9'}]}
>Thread-19::DEBUG::2014-07-07 12:01:21,481::task::595::TaskManager.Task::(_updateState) Task=`d6258925-bac0-4a4d-babc-c0856d6b2181`::moving from state preparing -> state finished
>Thread-19::DEBUG::2014-07-07 12:01:21,481::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-19::DEBUG::2014-07-07 12:01:21,482::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-19::DEBUG::2014-07-07 12:01:21,482::task::990::TaskManager.Task::(_decref) Task=`d6258925-bac0-4a4d-babc-c0856d6b2181`::ref 0 aborting False
>Thread-20::DEBUG::2014-07-07 12:01:21,534::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-07-07 12:01:21,535::task::595::TaskManager.Task::(_updateState) Task=`d687a38e-1cfd-40f1-af35-de5ad3f234b0`::moving from state init -> state preparing
>Thread-20::INFO::2014-07-07 12:01:21,535::logUtils::44::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=1, sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', domainName='hosted_storage', typeSpecificArg='str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', domClass=1, domVersion=3, options=None)
>Thread-20::DEBUG::2014-07-07 12:01:21,535::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-20::DEBUG::2014-07-07 12:01:21,535::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-20::DEBUG::2014-07-07 12:01:21,536::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-20::DEBUG::2014-07-07 12:01:21,536::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-20::DEBUG::2014-07-07 12:01:21,536::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-20::DEBUG::2014-07-07 12:01:21,536::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-20::DEBUG::2014-07-07 12:01:21,548::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-20::DEBUG::2014-07-07 12:01:21,549::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-20::DEBUG::2014-07-07 12:01:21,616::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-20::DEBUG::2014-07-07 12:01:21,616::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,617::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,617::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,617::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,617::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,618::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,618::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-20::ERROR::2014-07-07 12:01:21,618::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-20::ERROR::2014-07-07 12:01:21,618::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-20::DEBUG::2014-07-07 12:01:21,618::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-20::DEBUG::2014-07-07 12:01:21,621::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name 62ad18aa-e99a-4139-b11f-3ecd3e188a68' (cwd None)
>Thread-20::DEBUG::2014-07-07 12:01:21,745::lvm::296::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "62ad18aa-e99a-4139-b11f-3ecd3e188a68" not found\n  Skipping volume group 62ad18aa-e99a-4139-b11f-3ecd3e188a68\n'; <rc> = 5
>Thread-20::WARNING::2014-07-07 12:01:21,746::lvm::378::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "62ad18aa-e99a-4139-b11f-3ecd3e188a68" not found', '  Skipping volume group 62ad18aa-e99a-4139-b11f-3ecd3e188a68']
>Thread-20::DEBUG::2014-07-07 12:01:21,746::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-20::ERROR::2014-07-07 12:01:21,844::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 not found
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
>    dom = findMethod(sdUUID)
>  File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
>    raise se.StorageDomainDoesNotExist(sdUUID)
>StorageDomainDoesNotExist: Storage domain does not exist: ('62ad18aa-e99a-4139-b11f-3ecd3e188a68',)
>Thread-20::INFO::2014-07-07 12:01:21,844::nfsSD::69::Storage.StorageDomain::(create) sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68 domainName=hosted_storage remotePath=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04 domClass=1
>Thread-20::DEBUG::2014-07-07 12:01:22,024::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-20::DEBUG::2014-07-07 12:01:22,026::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
>Thread-20::WARNING::2014-07-07 12:01:22,026::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-20::DEBUG::2014-07-07 12:01:22,026::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-20::DEBUG::2014-07-07 12:01:22,026::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-20::DEBUG::2014-07-07 12:01:22,026::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5eb2f0cd3348df811ee3be0d8f25f29765c6903b']
>Thread-20::DEBUG::2014-07-07 12:01:22,031::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-20::DEBUG::2014-07-07 12:01:22,033::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-20::DEBUG::2014-07-07 12:01:22,035::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-20::DEBUG::2014-07-07 12:01:22,038::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5eb2f0cd3348df811ee3be0d8f25f29765c6903b']
>Thread-20::DEBUG::2014-07-07 12:01:22,041::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-20::DEBUG::2014-07-07 12:01:22,041::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS'
>Thread-20::DEBUG::2014-07-07 12:01:22,042::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '62ad18aa-e99a-4139-b11f-3ecd3e188a68_volumeNS'
>Thread-20::DEBUG::2014-07-07 12:01:22,042::clusterlock::144::initSANLock::(initSANLock) Initializing SANLock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-20::DEBUG::2014-07-07 12:01:22,107::sd::434::Storage.StorageDomain::(initSPMlease) lease initialized successfully
>Thread-20::DEBUG::2014-07-07 12:01:22,108::hsm::2647::Storage.HSM::(createStorageDomain) knownSDs: {62ad18aa-e99a-4139-b11f-3ecd3e188a68: storage.nfsSD.findDomain}
>Thread-20::INFO::2014-07-07 12:01:22,108::logUtils::47::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
>Thread-20::DEBUG::2014-07-07 12:01:22,108::task::1185::TaskManager.Task::(prepare) Task=`d687a38e-1cfd-40f1-af35-de5ad3f234b0`::finished: None
>Thread-20::DEBUG::2014-07-07 12:01:22,108::task::595::TaskManager.Task::(_updateState) Task=`d687a38e-1cfd-40f1-af35-de5ad3f234b0`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-07-07 12:01:22,108::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-20::DEBUG::2014-07-07 12:01:22,108::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-07-07 12:01:22,108::task::990::TaskManager.Task::(_decref) Task=`d687a38e-1cfd-40f1-af35-de5ad3f234b0`::ref 0 aborting False
>Thread-22::DEBUG::2014-07-07 12:01:22,157::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-22::DEBUG::2014-07-07 12:01:22,158::task::595::TaskManager.Task::(_updateState) Task=`19967b9a-dd96-4eec-88f5-d2578d7dc4b2`::moving from state init -> state preparing
>Thread-22::INFO::2014-07-07 12:01:22,158::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-22::INFO::2014-07-07 12:01:22,158::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-22::DEBUG::2014-07-07 12:01:22,158::task::1185::TaskManager.Task::(prepare) Task=`19967b9a-dd96-4eec-88f5-d2578d7dc4b2`::finished: {}
>Thread-22::DEBUG::2014-07-07 12:01:22,158::task::595::TaskManager.Task::(_updateState) Task=`19967b9a-dd96-4eec-88f5-d2578d7dc4b2`::moving from state preparing -> state finished
>Thread-22::DEBUG::2014-07-07 12:01:22,159::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-22::DEBUG::2014-07-07 12:01:22,159::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-22::DEBUG::2014-07-07 12:01:22,159::task::990::TaskManager.Task::(_decref) Task=`19967b9a-dd96-4eec-88f5-d2578d7dc4b2`::ref 0 aborting False
>Thread-23::DEBUG::2014-07-07 12:01:22,207::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-23::DEBUG::2014-07-07 12:01:22,208::task::595::TaskManager.Task::(_updateState) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::moving from state init -> state preparing
>Thread-23::INFO::2014-07-07 12:01:22,208::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', options=None)
>Thread-23::DEBUG::2014-07-07 12:01:22,208::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`f506f865-e49a-4457-8542-b6c3d6ac5aa0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2786' at 'getStorageDomainStats'
>Thread-23::DEBUG::2014-07-07 12:01:22,208::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'shared'
>Thread-23::DEBUG::2014-07-07 12:01:22,209::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'shared' (1 active user)
>Thread-23::DEBUG::2014-07-07 12:01:22,209::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`f506f865-e49a-4457-8542-b6c3d6ac5aa0`::Granted request
>Thread-23::DEBUG::2014-07-07 12:01:22,209::task::827::TaskManager.Task::(resourceAcquired) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::_resourcesAcquired: Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68 (shared)
>Thread-23::DEBUG::2014-07-07 12:01:22,209::task::990::TaskManager.Task::(_decref) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::ref 1 aborting False
>Thread-23::INFO::2014-07-07 12:01:22,210::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '156937748480', 'disktotal': '824377868288', 'mdafree': 0}}
>Thread-23::DEBUG::2014-07-07 12:01:22,211::task::1185::TaskManager.Task::(prepare) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::finished: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '156937748480', 'disktotal': '824377868288', 'mdafree': 0}}
>Thread-23::DEBUG::2014-07-07 12:01:22,211::task::595::TaskManager.Task::(_updateState) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::moving from state preparing -> state finished
>Thread-23::DEBUG::2014-07-07 12:01:22,211::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68': < ResourceRef 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', isValid: 'True' obj: 'None'>}
>Thread-23::DEBUG::2014-07-07 12:01:22,211::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-23::DEBUG::2014-07-07 12:01:22,211::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>Thread-23::DEBUG::2014-07-07 12:01:22,212::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>Thread-23::DEBUG::2014-07-07 12:01:22,212::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>Thread-23::DEBUG::2014-07-07 12:01:22,212::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>Thread-23::DEBUG::2014-07-07 12:01:22,212::task::990::TaskManager.Task::(_decref) Task=`45d7d847-c826-4646-91d4-0f9b6a661032`::ref 0 aborting False
>Thread-24::DEBUG::2014-07-07 12:01:22,261::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-24::DEBUG::2014-07-07 12:01:22,262::task::595::TaskManager.Task::(_updateState) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::moving from state init -> state preparing
>Thread-24::INFO::2014-07-07 12:01:22,262::logUtils::44::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', poolName='hosted_datacenter', masterDom='62ad18aa-e99a-4139-b11f-3ecd3e188a68', domList=['62ad18aa-e99a-4139-b11f-3ecd3e188a68'], masterVersion=1, lockPolicy=None, lockRenewalIntervalSec=None, leaseTimeSec=None, ioOpTimeoutSec=None, leaseRetries=None, options=None)
>Thread-24::INFO::2014-07-07 12:01:22,262::fileSD::350::Storage.StorageDomain::(validate) sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-24::DEBUG::2014-07-07 12:01:22,265::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5eb2f0cd3348df811ee3be0d8f25f29765c6903b']
>Thread-24::DEBUG::2014-07-07 12:01:22,265::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`8cf93df3-b044-4c35-a0aa-172163bbb618`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '980' at 'createStoragePool'
>Thread-24::DEBUG::2014-07-07 12:01:22,266::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-24::DEBUG::2014-07-07 12:01:22,266::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-24::DEBUG::2014-07-07 12:01:22,266::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`8cf93df3-b044-4c35-a0aa-172163bbb618`::Granted request
>Thread-24::DEBUG::2014-07-07 12:01:22,266::task::827::TaskManager.Task::(resourceAcquired) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (exclusive)
>Thread-24::DEBUG::2014-07-07 12:01:22,266::task::990::TaskManager.Task::(_decref) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::ref 1 aborting False
>Thread-24::DEBUG::2014-07-07 12:01:22,267::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`0300e198-5da6-4a58-be83-69372df46f90`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '982' at 'createStoragePool'
>Thread-24::DEBUG::2014-07-07 12:01:22,267::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'exclusive'
>Thread-24::DEBUG::2014-07-07 12:01:22,267::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'exclusive' (1 active user)
>Thread-24::DEBUG::2014-07-07 12:01:22,267::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`0300e198-5da6-4a58-be83-69372df46f90`::Granted request
>Thread-24::DEBUG::2014-07-07 12:01:22,268::task::827::TaskManager.Task::(resourceAcquired) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::_resourcesAcquired: Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68 (exclusive)
>Thread-24::DEBUG::2014-07-07 12:01:22,268::task::990::TaskManager.Task::(_decref) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::ref 1 aborting False
>Thread-24::INFO::2014-07-07 12:01:22,269::sp::133::Storage.StoragePool::(setBackend) updating pool 11a5671c-86ee-47e5-88a1-d66a76a4817f backend from type NoneType instance 0x3fad572210 to type StoragePoolDiskBackend instance 0x7fbcf8055fc8
>Thread-24::INFO::2014-07-07 12:01:22,269::sp::548::Storage.StoragePool::(create) spUUID=11a5671c-86ee-47e5-88a1-d66a76a4817f poolName=hosted_datacenter master_sd=62ad18aa-e99a-4139-b11f-3ecd3e188a68 domList=['62ad18aa-e99a-4139-b11f-3ecd3e188a68'] masterVersion=1 {'LEASETIMESEC': 60, 'LOCKPOLICY': 'ON', 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5}
>Thread-24::INFO::2014-07-07 12:01:22,269::fileSD::350::Storage.StorageDomain::(validate) sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-24::DEBUG::2014-07-07 12:01:22,271::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5eb2f0cd3348df811ee3be0d8f25f29765c6903b']
>Thread-24::DEBUG::2014-07-07 12:01:22,274::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5eb2f0cd3348df811ee3be0d8f25f29765c6903b']
>Thread-24::DEBUG::2014-07-07 12:01:22,274::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-24::DEBUG::2014-07-07 12:01:22,275::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-24::DEBUG::2014-07-07 12:01:22,275::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=cf146b2cba61af0a7b96ec342792c99fa94180d9']
>Thread-24::DEBUG::2014-07-07 12:01:22,280::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-24::INFO::2014-07-07 12:01:22,280::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 250)
>Thread-24::DEBUG::2014-07-07 12:01:43,283::clusterlock::202::SANLock::(acquireHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 250)
>Thread-24::INFO::2014-07-07 12:01:43,288::clusterlock::235::SANLock::(acquire) Acquiring cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 250)
>Thread-24::DEBUG::2014-07-07 12:01:43,322::clusterlock::261::SANLock::(acquire) Cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 250)
>Thread-24::INFO::2014-07-07 12:01:43,322::sp::671::Storage.StoragePool::(createMaster) setting master domain for spUUID 11a5671c-86ee-47e5-88a1-d66a76a4817f on sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-24::DEBUG::2014-07-07 12:01:43,323::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,323::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-24::DEBUG::2014-07-07 12:01:43,323::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=f445a5f162fcb8bc01f1e8e993515865b008a7f8']
>Thread-24::DEBUG::2014-07-07 12:01:43,533::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,536::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Regular', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=f445a5f162fcb8bc01f1e8e993515865b008a7f8']
>Thread-24::DEBUG::2014-07-07 12:01:43,536::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,536::persistentDict::160::Storage.PersistentDict::(transaction) Reusing active transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,537::persistentDict::160::Storage.PersistentDict::(transaction) Reusing active transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,537::persistentDict::160::Storage.PersistentDict::(transaction) Reusing active transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,537::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-24::DEBUG::2014-07-07 12:01:43,537::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-24::DEBUG::2014-07-07 12:01:43,542::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-24::DEBUG::2014-07-07 12:01:43,542::sp::1375::Storage.StoragePool::(setMasterDomain) Master domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 verified, version 1
>Thread-24::DEBUG::2014-07-07 12:01:43,542::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-24::DEBUG::2014-07-07 12:01:43,543::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-24::DEBUG::2014-07-07 12:01:43,546::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-24::INFO::2014-07-07 12:01:43,546::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-25::DEBUG::2014-07-07 12:01:43,546::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-24::DEBUG::2014-07-07 12:01:43,547::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `11a5671c-86ee-47e5-88a1-d66a76a4817f` started monitoring domain `62ad18aa-e99a-4139-b11f-3ecd3e188a68`
>Thread-24::DEBUG::2014-07-07 12:01:43,547::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-24::WARNING::2014-07-07 12:01:43,548::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f already exists
>Thread-24::DEBUG::2014-07-07 12:01:43,554::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-24::DEBUG::2014-07-07 12:01:43,555::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-24::DEBUG::2014-07-07 12:01:43,555::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-25::DEBUG::2014-07-07 12:01:43,645::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-07-07 12:01:43,651::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n514 bytes (514 B) copied, 0.000327611 s, 1.6 MB/s\n'; <rc> = 0
>Thread-24::DEBUG::2014-07-07 12:01:43,653::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-24::DEBUG::2014-07-07 12:01:43,653::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-25::DEBUG::2014-07-07 12:01:43,657::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 changed its status to Valid
>Thread-24::INFO::2014-07-07 12:01:43,658::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68 to /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-27::DEBUG::2014-07-07 12:01:43,659::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-27::DEBUG::2014-07-07 12:01:43,660::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-24::INFO::2014-07-07 12:01:43,660::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68 to /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd
>Thread-27::DEBUG::2014-07-07 12:01:43,661::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-24::INFO::2014-07-07 12:01:43,662::clusterlock::279::SANLock::(release) Releasing cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-24::DEBUG::2014-07-07 12:01:43,665::clusterlock::289::SANLock::(release) Cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully released
>Thread-24::INFO::2014-07-07 12:01:43,665::clusterlock::207::SANLock::(releaseHostId) Releasing host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 250)
>Thread-24::DEBUG::2014-07-07 12:01:45,665::clusterlock::217::SANLock::(releaseHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 released successfully (id: 250)
>Thread-24::INFO::2014-07-07 12:01:45,666::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-25::DEBUG::2014-07-07 12:01:45,666::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-25::INFO::2014-07-07 12:01:45,666::clusterlock::207::SANLock::(releaseHostId) Releasing host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 250)
>Thread-25::DEBUG::2014-07-07 12:01:45,666::clusterlock::217::SANLock::(releaseHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 released successfully (id: 250)
>Thread-24::INFO::2014-07-07 12:01:45,667::logUtils::47::dispatcher::(wrapper) Run and protect: createStoragePool, Return response: True
>Thread-24::DEBUG::2014-07-07 12:01:45,667::task::1185::TaskManager.Task::(prepare) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::finished: True
>Thread-24::DEBUG::2014-07-07 12:01:45,667::task::595::TaskManager.Task::(_updateState) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::moving from state preparing -> state finished
>Thread-24::DEBUG::2014-07-07 12:01:45,667::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68': < ResourceRef 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', isValid: 'True' obj: 'None'>, 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>Thread-24::DEBUG::2014-07-07 12:01:45,667::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-24::DEBUG::2014-07-07 12:01:45,668::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>Thread-24::DEBUG::2014-07-07 12:01:45,668::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>Thread-24::DEBUG::2014-07-07 12:01:45,668::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>Thread-24::DEBUG::2014-07-07 12:01:45,668::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>Thread-24::DEBUG::2014-07-07 12:01:45,669::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-24::DEBUG::2014-07-07 12:01:45,669::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-24::DEBUG::2014-07-07 12:01:45,669::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-24::DEBUG::2014-07-07 12:01:45,669::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-24::DEBUG::2014-07-07 12:01:45,669::task::990::TaskManager.Task::(_decref) Task=`0c34b9ed-5982-428c-84c5-621e6ea66212`::ref 0 aborting False
>Thread-29::DEBUG::2014-07-07 12:01:45,724::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-29::DEBUG::2014-07-07 12:01:45,725::task::595::TaskManager.Task::(_updateState) Task=`c7d1719c-b892-4392-bad6-c5659e075a27`::moving from state init -> state preparing
>Thread-29::INFO::2014-07-07 12:01:45,725::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', hostID=1, msdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', masterVersion=1, domainsMap=None, options=None)
>Thread-29::DEBUG::2014-07-07 12:01:45,725::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`a8edae36-a92c-40c7-91a8-962052f65164`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1018' at 'connectStoragePool'
>Thread-29::DEBUG::2014-07-07 12:01:45,726::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-29::DEBUG::2014-07-07 12:01:45,726::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-29::DEBUG::2014-07-07 12:01:45,726::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`a8edae36-a92c-40c7-91a8-962052f65164`::Granted request
>Thread-29::DEBUG::2014-07-07 12:01:45,727::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`47de30e1-737c-44f3-8d7f-0bf89fec3b07`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1066' at '_connectStoragePool'
>Thread-29::DEBUG::2014-07-07 12:01:45,727::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-29::DEBUG::2014-07-07 12:01:45,727::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-29::DEBUG::2014-07-07 12:01:45,727::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`47de30e1-737c-44f3-8d7f-0bf89fec3b07`::Granted request
>Thread-29::INFO::2014-07-07 12:01:45,727::sp::133::Storage.StoragePool::(setBackend) updating pool 11a5671c-86ee-47e5-88a1-d66a76a4817f backend from type NoneType instance 0x3fad572210 to type StoragePoolDiskBackend instance 0x7fbcf80551b8
>Thread-29::INFO::2014-07-07 12:01:45,728::sp::623::Storage.StoragePool::(connect) Connect host #1 to the storage pool 11a5671c-86ee-47e5-88a1-d66a76a4817f with master domain: 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (ver = 1)
>Thread-29::DEBUG::2014-07-07 12:01:45,728::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,728::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,728::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,728::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,729::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,729::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,729::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-29::DEBUG::2014-07-07 12:01:45,729::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-29::DEBUG::2014-07-07 12:01:45,729::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-29::DEBUG::2014-07-07 12:01:45,730::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-29::DEBUG::2014-07-07 12:01:45,730::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-29::DEBUG::2014-07-07 12:01:45,730::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-29::DEBUG::2014-07-07 12:01:45,742::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-29::DEBUG::2014-07-07 12:01:45,744::multipath::109::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-29::DEBUG::2014-07-07 12:01:45,772::multipath::109::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-29::DEBUG::2014-07-07 12:01:45,800::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,800::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,800::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,800::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,801::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,801::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-29::DEBUG::2014-07-07 12:01:45,801::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-29::DEBUG::2014-07-07 12:01:45,808::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-29::DEBUG::2014-07-07 12:01:45,809::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-29::DEBUG::2014-07-07 12:01:45,811::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-29::DEBUG::2014-07-07 12:01:45,813::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-29::INFO::2014-07-07 12:01:45,813::sd::384::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS already registered
>Thread-29::INFO::2014-07-07 12:01:45,813::sd::392::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 62ad18aa-e99a-4139-b11f-3ecd3e188a68_volumeNS already registered
>Thread-29::DEBUG::2014-07-07 12:01:45,813::sp::1375::Storage.StoragePool::(setMasterDomain) Master domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 verified, version 1
>Thread-29::DEBUG::2014-07-07 12:01:45,813::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-29::DEBUG::2014-07-07 12:01:45,814::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-29::DEBUG::2014-07-07 12:01:45,816::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-29::INFO::2014-07-07 12:01:45,816::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-29::DEBUG::2014-07-07 12:01:45,816::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `11a5671c-86ee-47e5-88a1-d66a76a4817f` started monitoring domain `62ad18aa-e99a-4139-b11f-3ecd3e188a68`
>Thread-31::DEBUG::2014-07-07 12:01:45,816::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-29::DEBUG::2014-07-07 12:01:45,817::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-29::WARNING::2014-07-07 12:01:45,818::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f already exists
>Thread-29::DEBUG::2014-07-07 12:01:45,824::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>Thread-29::DEBUG::2014-07-07 12:01:45,825::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-31::DEBUG::2014-07-07 12:01:45,827::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-29::DEBUG::2014-07-07 12:01:45,836::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name' (cwd None)
>Thread-31::DEBUG::2014-07-07 12:01:45,842::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n514 bytes (514 B) copied, 0.000409224 s, 1.3 MB/s\n'; <rc> = 0
>Thread-31::DEBUG::2014-07-07 12:01:45,844::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 changed its status to Valid
>Thread-32::DEBUG::2014-07-07 12:01:45,845::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-31::INFO::2014-07-07 12:01:45,845::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>Thread-32::DEBUG::2014-07-07 12:01:45,846::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-32::DEBUG::2014-07-07 12:01:45,846::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-32::DEBUG::2014-07-07 12:01:45,847::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-31::DEBUG::2014-07-07 12:01:45,849::clusterlock::202::SANLock::(acquireHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 1)
>Thread-34::INFO::2014-07-07 12:01:45,852::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-29::DEBUG::2014-07-07 12:01:45,936::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-29::DEBUG::2014-07-07 12:01:45,936::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-29::INFO::2014-07-07 12:01:45,938::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68 to /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-29::INFO::2014-07-07 12:01:45,939::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68 to /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd
>Thread-29::DEBUG::2014-07-07 12:01:45,940::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 5.0, waitTimeout: 3, maxTasks: 500.0
>Thread-29::DEBUG::2014-07-07 12:01:45,942::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd if=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/outbox iflag=direct,fullblock bs=512 count=8 skip=8' (cwd None)
>Thread-29::DEBUG::2014-07-07 12:01:45,951::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.00276043 s, 1.5 MB/s\n'; <rc> = 0
>Thread-29::INFO::2014-07-07 12:01:45,951::storage_mailbox::385::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/bin/dd', 'of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=512', 'seek=8']
>Thread-29::DEBUG::2014-07-07 12:01:45,952::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=512 seek=8' (cwd None)
>Thread-29::DEBUG::2014-07-07 12:01:45,968::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.011186 s, 366 kB/s\n'; <rc> = 0
>Thread-29::DEBUG::2014-07-07 12:01:45,968::storage_mailbox::207::Storage.Mailbox.HSM::(__init__) HSM_MailboxMonitor created for pool 11a5671c-86ee-47e5-88a1-d66a76a4817f
>Thread-29::DEBUG::2014-07-07 12:01:45,969::sp::465::Storage.StoragePool::(__createMailboxMonitor) HSM mailbox ready for pool 11a5671c-86ee-47e5-88a1-d66a76a4817f on master domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-29::DEBUG::2014-07-07 12:01:45,969::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-29::DEBUG::2014-07-07 12:01:45,969::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-29::DEBUG::2014-07-07 12:01:45,969::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-29::DEBUG::2014-07-07 12:01:45,970::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-29::DEBUG::2014-07-07 12:01:45,970::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-29::DEBUG::2014-07-07 12:01:45,970::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-29::DEBUG::2014-07-07 12:01:45,970::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-29::DEBUG::2014-07-07 12:01:45,970::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-29::INFO::2014-07-07 12:01:45,971::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>Thread-29::DEBUG::2014-07-07 12:01:45,971::task::1185::TaskManager.Task::(prepare) Task=`c7d1719c-b892-4392-bad6-c5659e075a27`::finished: True
>Thread-29::DEBUG::2014-07-07 12:01:45,971::task::595::TaskManager.Task::(_updateState) Task=`c7d1719c-b892-4392-bad6-c5659e075a27`::moving from state preparing -> state finished
>Thread-29::DEBUG::2014-07-07 12:01:45,971::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-29::DEBUG::2014-07-07 12:01:45,971::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-29::DEBUG::2014-07-07 12:01:45,971::task::990::TaskManager.Task::(_decref) Task=`c7d1719c-b892-4392-bad6-c5659e075a27`::ref 0 aborting False
>Thread-42::DEBUG::2014-07-07 12:01:46,023::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-42::DEBUG::2014-07-07 12:01:46,024::task::595::TaskManager.Task::(_updateState) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::moving from state init -> state preparing
>Thread-42::INFO::2014-07-07 12:01:46,024::logUtils::44::dispatcher::(wrapper) Run and protect: spmStart(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', prevID=-1, prevLVER=-1, maxHostID=250, domVersion=3, options=None)
>Thread-42::DEBUG::2014-07-07 12:01:46,025::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`56caea63-abca-4959-aff4-f1e74d6058b2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '588' at 'spmStart'
>Thread-42::DEBUG::2014-07-07 12:01:46,025::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-42::DEBUG::2014-07-07 12:01:46,025::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-42::DEBUG::2014-07-07 12:01:46,025::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`56caea63-abca-4959-aff4-f1e74d6058b2`::Granted request
>Thread-42::DEBUG::2014-07-07 12:01:46,026::task::827::TaskManager.Task::(resourceAcquired) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (exclusive)
>Thread-42::DEBUG::2014-07-07 12:01:46,026::task::990::TaskManager.Task::(_decref) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::ref 1 aborting False
>Thread-42::INFO::2014-07-07 12:01:46,026::logUtils::47::dispatcher::(wrapper) Run and protect: spmStart, Return response: None
>Thread-42::DEBUG::2014-07-07 12:01:46,026::task::1180::TaskManager.Task::(prepare) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::Prepare: 1 jobs exist, move to acquiring
>Thread-42::DEBUG::2014-07-07 12:01:46,026::task::595::TaskManager.Task::(_updateState) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::moving from state preparing -> state acquiring
>Thread-42::DEBUG::2014-07-07 12:01:46,026::task::595::TaskManager.Task::(_updateState) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::moving from state acquiring -> state queued
>Thread-42::DEBUG::2014-07-07 12:01:46,027::taskManager::50::TaskManager::(_queueTask) queuing task: 509d1bf6-ac74-4887-92b3-84b42b55f255
>Thread-42::DEBUG::2014-07-07 12:01:46,027::taskManager::56::TaskManager::(_queueTask) task queued: 509d1bf6-ac74-4887-92b3-84b42b55f255
>Thread-1::DEBUG::2014-07-07 12:01:46,027::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-42::DEBUG::2014-07-07 12:01:46,027::task::1182::TaskManager.Task::(prepare) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::returning
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,028::threadPool::200::Misc.ThreadPool.WorkerThread::(_processNextTask) Task: 509d1bf6-ac74-4887-92b3-84b42b55f255 running: <bound method Task.commit of <storage.task.Task instance at 0x7fbcf8157a70>> with: None
>Thread-42::DEBUG::2014-07-07 12:01:46,028::task::990::TaskManager.Task::(_decref) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::ref 0 aborting False
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,029::task::1194::TaskManager.Task::(commit) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::committing task: 509d1bf6-ac74-4887-92b3-84b42b55f255
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,029::task::595::TaskManager.Task::(_updateState) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::moving from state queued -> state running
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,030::task::905::TaskManager.Task::(_runJobs) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::Task.run: running job 0: spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x7fbcf812ea10>> (args: (-1, -1, 250, 3) kwargs: {})
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,030::task::331::TaskManager.Task::(run) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::Job.run: running spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x7fbcf812ea10>> (args: (-1, -1, 250, 3) kwargs: {}) callback None
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,031::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,031::misc::758::SamplingMethod::(__call__) Got in to sampling method
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,033::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:01:46,034::misc::766::SamplingMethod::(__call__) Returning last result
>509d1bf6-ac74-4887-92b3-84b42b55f255::INFO::2014-07-07 12:01:46,034::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>Thread-43::DEBUG::2014-07-07 12:01:46,078::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-43::DEBUG::2014-07-07 12:01:46,079::task::595::TaskManager.Task::(_updateState) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::moving from state init -> state preparing
>Thread-43::INFO::2014-07-07 12:01:46,079::logUtils::44::dispatcher::(wrapper) Run and protect: activateStorageDomain(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', options=None)
>Thread-43::DEBUG::2014-07-07 12:01:46,079::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`2c749f0b-98be-4fac-9e9f-334e4ae94f52`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1256' at 'activateStorageDomain'
>Thread-43::DEBUG::2014-07-07 12:01:46,079::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-43::DEBUG::2014-07-07 12:01:46,080::resourceManager::577::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is currently locked, Entering queue (1 in queue)
>Thread-31::DEBUG::2014-07-07 12:01:55,853::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-31::DEBUG::2014-07-07 12:01:55,860::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n514 bytes (514 B) copied, 0.000503199 s, 1.0 MB/s\n'; <rc> = 0
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,036::clusterlock::202::SANLock::(acquireHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 1)
>509d1bf6-ac74-4887-92b3-84b42b55f255::INFO::2014-07-07 12:02:07,037::clusterlock::235::SANLock::(acquire) Acquiring cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,070::clusterlock::261::SANLock::(acquire) Cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 1)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,071::sp::275::Storage.StoragePool::(startSpm) spm lock acquired successfully
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,073::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=5fe4af59832f192f92e83150034e242f06801b90']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,073::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,073::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,074::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=aef8f664ab6729eaa4174958c93de154cc9d9b6a']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,079::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,080::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`cf3039a8-758d-4966-9930-e887e3d8c4f9`::Request was made in '/usr/share/vdsm/storage/sp.py' line '429' at '_upgradePool'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,080::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,080::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,080::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`cf3039a8-758d-4966-9930-e887e3d8c4f9`::Granted request
>509d1bf6-ac74-4887-92b3-84b42b55f255::INFO::2014-07-07 12:02:07,081::sp::435::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `62ad18aa-e99a-4139-b11f-3ecd3e188a68`
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,081::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`8aef4189-78f8-4ee2-858a-464ffc9b5e16`::Request was made in '/usr/share/vdsm/storage/sp.py' line '437' at '_upgradePool'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,081::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'exclusive'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,081::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'exclusive' (1 active user)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,081::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`8aef4189-78f8-4ee2-858a-464ffc9b5e16`::Granted request
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,086::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,087::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,090::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=aef8f664ab6729eaa4174958c93de154cc9d9b6a']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,092::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>509d1bf6-ac74-4887-92b3-84b42b55f255::INFO::2014-07-07 12:02:07,092::sd::384::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS already registered
>509d1bf6-ac74-4887-92b3-84b42b55f255::INFO::2014-07-07 12:02:07,092::sd::392::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 62ad18aa-e99a-4139-b11f-3ecd3e188a68_volumeNS already registered
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,093::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,093::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,093::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,093::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,093::sp::440::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,096::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=aef8f664ab6729eaa4174958c93de154cc9d9b6a']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,096::sp::447::Storage.StoragePool::(_upgradePool) Registering with state change event
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,096::sp::450::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,096::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,096::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,097::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,097::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,129::sd::633::Storage.StorageDomain::(createMasterTree) creating vms dir: /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/master/vms
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,142::sd::636::Storage.StorageDomain::(createMasterTree) creating task dir: /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/master/tasks
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,153::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=aef8f664ab6729eaa4174958c93de154cc9d9b6a']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,157::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 5.0, waitTimeout: 3, maxTasks: 500.0
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,159::storage_mailbox::574::Storage.MailBox.SpmMailMonitor::(__init__) SPM_MailMonitor - clearing outgoing mail, command is: ['dd', 'of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/outbox', 'oflag=direct', 'iflag=fullblock', 'conv=notrunc', 'count=1']
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,159::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) 'dd of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/outbox oflag=direct iflag=fullblock conv=notrunc count=1 bs=1024000' (cwd None)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,211::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0471137 s, 21.7 MB/s\n'; <rc> = 0
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,212::storage_mailbox::582::Storage.MailBox.SpmMailMonitor::(__init__) SPM_MailMonitor created for pool 11a5671c-86ee-47e5-88a1-d66a76a4817f
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,213::sp::322::Storage.StoragePool::(startSpm) SPM mailbox ready for pool 11a5671c-86ee-47e5-88a1-d66a76a4817f on master domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,214::sp::330::Storage.StoragePool::(startSpm) ended.
>Dummy-50::DEBUG::2014-07-07 12:02:07,213::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,215::task::595::TaskManager.Task::(_updateState) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::moving from state running -> state finished
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,221::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,221::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,222::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,222::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,222::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,222::resourceManager::654::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' has 1 requests in queue. Handling top request.
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,222::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`2c749f0b-98be-4fac-9e9f-334e4ae94f52`::Granted request
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,223::resourceManager::686::ResourceManager::(releaseResource) Request 'Request for Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f - exclusive: granted' was granted
>Thread-43::DEBUG::2014-07-07 12:02:07,224::task::827::TaskManager.Task::(resourceAcquired) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (exclusive)
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,224::task::913::TaskManager.Task::(_runJobs) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::Task.run: exit - success: result 
>Thread-43::DEBUG::2014-07-07 12:02:07,225::task::990::TaskManager.Task::(_decref) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::ref 1 aborting False
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,225::task::990::TaskManager.Task::(_decref) Task=`509d1bf6-ac74-4887-92b3-84b42b55f255`::ref 0 aborting False
>509d1bf6-ac74-4887-92b3-84b42b55f255::DEBUG::2014-07-07 12:02:07,226::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Thread-43::DEBUG::2014-07-07 12:02:07,227::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`f1443ed6-e052-4f85-97b1-06092b37d75e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1257' at 'activateStorageDomain'
>Thread-43::DEBUG::2014-07-07 12:02:07,228::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'exclusive'
>Thread-43::DEBUG::2014-07-07 12:02:07,228::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'exclusive' (1 active user)
>Thread-43::DEBUG::2014-07-07 12:02:07,228::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`f1443ed6-e052-4f85-97b1-06092b37d75e`::Granted request
>Thread-43::DEBUG::2014-07-07 12:02:07,228::task::827::TaskManager.Task::(resourceAcquired) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::_resourcesAcquired: Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68 (exclusive)
>Thread-43::DEBUG::2014-07-07 12:02:07,229::task::990::TaskManager.Task::(_decref) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::ref 1 aborting False
>Thread-43::INFO::2014-07-07 12:02:07,229::sp::1024::Storage.StoragePool::(activateSD) sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68 spUUID=11a5671c-86ee-47e5-88a1-d66a76a4817f
>Thread-43::INFO::2014-07-07 12:02:07,231::logUtils::47::dispatcher::(wrapper) Run and protect: activateStorageDomain, Return response: None
>Thread-43::DEBUG::2014-07-07 12:02:07,231::task::1185::TaskManager.Task::(prepare) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::finished: None
>Thread-43::DEBUG::2014-07-07 12:02:07,232::task::595::TaskManager.Task::(_updateState) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::moving from state preparing -> state finished
>Thread-43::DEBUG::2014-07-07 12:02:07,233::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68': < ResourceRef 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', isValid: 'True' obj: 'None'>, 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>Thread-43::DEBUG::2014-07-07 12:02:07,234::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-43::DEBUG::2014-07-07 12:02:07,236::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>Thread-43::DEBUG::2014-07-07 12:02:07,237::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>Thread-43::DEBUG::2014-07-07 12:02:07,238::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>Thread-43::DEBUG::2014-07-07 12:02:07,239::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>Thread-43::DEBUG::2014-07-07 12:02:07,241::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-43::DEBUG::2014-07-07 12:02:07,242::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-43::DEBUG::2014-07-07 12:02:07,243::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-43::DEBUG::2014-07-07 12:02:07,244::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-43::DEBUG::2014-07-07 12:02:07,245::task::990::TaskManager.Task::(_decref) Task=`a8b35687-a852-4e2c-a049-916c5b9a95c1`::ref 0 aborting False
>Dummy-50::DEBUG::2014-07-07 12:02:07,296::storage_mailbox::731::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0530865 s, 19.3 MB/s\n'; <rc> = 0
>Thread-51::DEBUG::2014-07-07 12:02:07,297::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-51::DEBUG::2014-07-07 12:02:07,298::task::595::TaskManager.Task::(_updateState) Task=`b3ef2795-7688-4dc4-b1ee-129e161d2007`::moving from state init -> state preparing
>Thread-51::INFO::2014-07-07 12:02:07,299::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-51::DEBUG::2014-07-07 12:02:07,300::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
>Thread-51::DEBUG::2014-07-07 12:02:07,300::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {}
>Thread-51::INFO::2014-07-07 12:02:07,301::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {}}
>Thread-51::DEBUG::2014-07-07 12:02:07,301::task::1185::TaskManager.Task::(prepare) Task=`b3ef2795-7688-4dc4-b1ee-129e161d2007`::finished: {'allTasksStatus': {}}
>Thread-51::DEBUG::2014-07-07 12:02:07,302::task::595::TaskManager.Task::(_updateState) Task=`b3ef2795-7688-4dc4-b1ee-129e161d2007`::moving from state preparing -> state finished
>Thread-51::DEBUG::2014-07-07 12:02:07,303::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-51::DEBUG::2014-07-07 12:02:07,303::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-51::DEBUG::2014-07-07 12:02:07,304::task::990::TaskManager.Task::(_decref) Task=`b3ef2795-7688-4dc4-b1ee-129e161d2007`::ref 0 aborting False
>Thread-52::DEBUG::2014-07-07 12:02:07,351::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-52::DEBUG::2014-07-07 12:02:07,352::task::595::TaskManager.Task::(_updateState) Task=`ef0fc3ef-8c1d-457e-8ad5-33abc46332db`::moving from state init -> state preparing
>Thread-52::INFO::2014-07-07 12:02:07,352::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', options=None)
>Thread-52::INFO::2014-07-07 12:02:07,352::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-52::DEBUG::2014-07-07 12:02:07,352::task::1185::TaskManager.Task::(prepare) Task=`ef0fc3ef-8c1d-457e-8ad5-33abc46332db`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-52::DEBUG::2014-07-07 12:02:07,352::task::595::TaskManager.Task::(_updateState) Task=`ef0fc3ef-8c1d-457e-8ad5-33abc46332db`::moving from state preparing -> state finished
>Thread-52::DEBUG::2014-07-07 12:02:07,353::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-52::DEBUG::2014-07-07 12:02:07,353::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-52::DEBUG::2014-07-07 12:02:07,353::task::990::TaskManager.Task::(_decref) Task=`ef0fc3ef-8c1d-457e-8ad5-33abc46332db`::ref 0 aborting False
>Thread-53::DEBUG::2014-07-07 12:02:07,401::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-53::DEBUG::2014-07-07 12:02:07,402::task::595::TaskManager.Task::(_updateState) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::moving from state init -> state preparing
>Thread-53::INFO::2014-07-07 12:02:07,402::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', options=None)
>Thread-53::DEBUG::2014-07-07 12:02:07,402::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`3cc718ab-22af-461e-a13b-376ee395c5dd`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-53::DEBUG::2014-07-07 12:02:07,402::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'shared'
>Thread-53::DEBUG::2014-07-07 12:02:07,403::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'shared' (1 active user)
>Thread-53::DEBUG::2014-07-07 12:02:07,403::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`3cc718ab-22af-461e-a13b-376ee395c5dd`::Granted request
>Thread-53::DEBUG::2014-07-07 12:02:07,403::task::827::TaskManager.Task::(resourceAcquired) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (shared)
>Thread-53::DEBUG::2014-07-07 12:02:07,403::task::990::TaskManager.Task::(_decref) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::ref 1 aborting False
>Thread-53::INFO::2014-07-07 12:02:07,406::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'hosted_datacenter', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'master_uuid': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'status': 'Active', 'diskfree': '156937748480', 'isoprefix': '', 'alerts': [], 'disktotal': '824377868288', 'version': 3}}}
>Thread-53::DEBUG::2014-07-07 12:02:07,406::task::1185::TaskManager.Task::(prepare) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::finished: {'info': {'name': 'hosted_datacenter', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'master_uuid': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'version': '3', 'spm_id': 1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'status': 'Active', 'diskfree': '156937748480', 'isoprefix': '', 'alerts': [], 'disktotal': '824377868288', 'version': 3}}}
>Thread-53::DEBUG::2014-07-07 12:02:07,407::task::595::TaskManager.Task::(_updateState) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::moving from state preparing -> state finished
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-53::DEBUG::2014-07-07 12:02:07,407::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-53::DEBUG::2014-07-07 12:02:07,407::task::990::TaskManager.Task::(_decref) Task=`726d8b7f-3d0f-4373-92d1-224097ec7989`::ref 0 aborting False
>Thread-54::DEBUG::2014-07-07 12:02:07,456::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-54::DEBUG::2014-07-07 12:02:07,457::task::595::TaskManager.Task::(_updateState) Task=`296972f5-a360-4b4c-ae41-a295f15bd870`::moving from state init -> state preparing
>Thread-54::INFO::2014-07-07 12:02:07,457::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-54::INFO::2014-07-07 12:02:07,457::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000503199', 'lastCheck': '0.4', 'valid': True}}
>Thread-54::DEBUG::2014-07-07 12:02:07,457::task::1185::TaskManager.Task::(prepare) Task=`296972f5-a360-4b4c-ae41-a295f15bd870`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000503199', 'lastCheck': '0.4', 'valid': True}}
>Thread-54::DEBUG::2014-07-07 12:02:07,457::task::595::TaskManager.Task::(_updateState) Task=`296972f5-a360-4b4c-ae41-a295f15bd870`::moving from state preparing -> state finished
>Thread-54::DEBUG::2014-07-07 12:02:07,457::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-54::DEBUG::2014-07-07 12:02:07,458::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-54::DEBUG::2014-07-07 12:02:07,458::task::990::TaskManager.Task::(_decref) Task=`296972f5-a360-4b4c-ae41-a295f15bd870`::ref 0 aborting False
>Thread-55::DEBUG::2014-07-07 12:02:07,759::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-55::DEBUG::2014-07-07 12:02:07,759::task::595::TaskManager.Task::(_updateState) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::moving from state init -> state preparing
>Thread-55::INFO::2014-07-07 12:02:07,759::logUtils::44::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', imgUUID='2a5a1148-bc39-47a0-9e29-f5b489435996', size=52428800, volFormat=5, preallocate=2, diskType=2, volUUID='b36c97fc-9639-4750-b058-693abedd7217', desc='Hosted Engine Image', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000')
>Thread-55::DEBUG::2014-07-07 12:02:07,760::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`d8cf8d7c-9d0c-4222-9586-4bce1250a836`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1464' at 'createVolume'
>Thread-55::DEBUG::2014-07-07 12:02:07,760::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'shared'
>Thread-55::DEBUG::2014-07-07 12:02:07,760::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'shared' (1 active user)
>Thread-55::DEBUG::2014-07-07 12:02:07,760::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`d8cf8d7c-9d0c-4222-9586-4bce1250a836`::Granted request
>Thread-55::DEBUG::2014-07-07 12:02:07,760::task::827::TaskManager.Task::(resourceAcquired) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_resourcesAcquired: Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68 (shared)
>Thread-55::DEBUG::2014-07-07 12:02:07,761::task::990::TaskManager.Task::(_decref) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::ref 1 aborting False
>Thread-55::DEBUG::2014-07-07 12:02:07,772::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>Thread-55::DEBUG::2014-07-07 12:02:07,786::taskManager::68::TaskManager::(scheduleJob) scheduled job createVolume for task cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 
>Thread-55::INFO::2014-07-07 12:02:07,786::logUtils::47::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
>Thread-55::DEBUG::2014-07-07 12:02:07,786::task::1180::TaskManager.Task::(prepare) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::Prepare: 1 jobs exist, move to acquiring
>Thread-55::DEBUG::2014-07-07 12:02:07,786::task::595::TaskManager.Task::(_updateState) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::moving from state preparing -> state acquiring
>Thread-55::DEBUG::2014-07-07 12:02:07,786::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>Thread-55::DEBUG::2014-07-07 12:02:07,806::task::595::TaskManager.Task::(_updateState) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::moving from state acquiring -> state queued
>Thread-55::DEBUG::2014-07-07 12:02:07,806::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>Thread-55::DEBUG::2014-07-07 12:02:07,826::taskManager::50::TaskManager::(_queueTask) queuing task: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>Thread-55::DEBUG::2014-07-07 12:02:07,826::taskManager::56::TaskManager::(_queueTask) task queued: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>Thread-5::DEBUG::2014-07-07 12:02:07,826::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>Thread-55::DEBUG::2014-07-07 12:02:07,826::task::1182::TaskManager.Task::(prepare) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::returning
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,826::threadPool::200::Misc.ThreadPool.WorkerThread::(_processNextTask) Task: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 running: <bound method Task.commit of <storage.task.Task instance at 0x7fbcf80bd9e0>> with: None
>Thread-55::DEBUG::2014-07-07 12:02:07,827::task::990::TaskManager.Task::(_decref) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::ref 0 aborting False
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,827::task::1194::TaskManager.Task::(commit) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::committing task: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,827::task::595::TaskManager.Task::(_updateState) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::moving from state queued -> state running
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,828::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,848::task::905::TaskManager.Task::(_runJobs) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::Task.run: running job 0: createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7fbcf812ea10>> (args: ('62ad18aa-e99a-4139-b11f-3ecd3e188a68', '2a5a1148-bc39-47a0-9e29-f5b489435996', 52428800, 5, 2, 2, 'b36c97fc-9639-4750-b058-693abedd7217', 'Hosted Engine Image', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {})
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,848::task::331::TaskManager.Task::(run) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::Job.run: running createVolume: <bound method StoragePool.createVolume of <storage.sp.StoragePool object at 0x7fbcf812ea10>> (args: ('62ad18aa-e99a-4139-b11f-3ecd3e188a68', '2a5a1148-bc39-47a0-9e29-f5b489435996', 52428800, 5, 2, 2, 'b36c97fc-9639-4750-b058-693abedd7217', 'Hosted Engine Image', '00000000-0000-0000-0000-000000000000', '00000000-0000-0000-0000-000000000000') kwargs: {}) callback None
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,848::resourceManager::198::ResourceManager.Request::(__init__) ResName=`62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996`ReqID=`8b22790b-8ade-4839-948f-1dd488e00352`::Request was made in '/usr/share/vdsm/storage/sp.py' line '1767' at 'createVolume'
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,848::resourceManager::542::ResourceManager::(registerResource) Trying to register resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996' for lock type 'exclusive'
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,849::resourceFactories::125::Storage.ResourcesFactories::(__getResourceCandidatesList) Image 2a5a1148-bc39-47a0-9e29-f5b489435996 does not exist in domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,850::resourceManager::601::ResourceManager::(registerResource) Resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996' is free. Now locking as 'exclusive' (1 active user)
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,850::resourceManager::238::ResourceManager.Request::(grant) ResName=`62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996`ReqID=`8b22790b-8ade-4839-948f-1dd488e00352`::Granted request
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::INFO::2014-07-07 12:02:07,850::image::123::Storage.Image::(create) Create placeholder /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996 for image's volumes
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,851::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>Thread-56::DEBUG::2014-07-07 12:02:07,874::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-56::DEBUG::2014-07-07 12:02:07,875::task::595::TaskManager.Task::(_updateState) Task=`eafe0b9b-b669-4e75-90cd-ab2d1fcb58a9`::moving from state init -> state preparing
>Thread-56::INFO::2014-07-07 12:02:07,875::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::INFO::2014-07-07 12:02:07,875::volume::443::Storage.Volume::(create) Creating volume b36c97fc-9639-4750-b058-693abedd7217
>Thread-56::DEBUG::2014-07-07 12:02:07,875::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
>Thread-56::DEBUG::2014-07-07 12:02:07,875::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>Thread-56::DEBUG::2014-07-07 12:02:07,876::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,876::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>Thread-56::DEBUG::2014-07-07 12:02:07,876::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}
>Thread-56::INFO::2014-07-07 12:02:07,876::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}}
>Thread-56::DEBUG::2014-07-07 12:02:07,877::task::1185::TaskManager.Task::(prepare) Task=`eafe0b9b-b669-4e75-90cd-ab2d1fcb58a9`::finished: {'allTasksStatus': {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}}
>Thread-56::DEBUG::2014-07-07 12:02:07,877::task::595::TaskManager.Task::(_updateState) Task=`eafe0b9b-b669-4e75-90cd-ab2d1fcb58a9`::moving from state preparing -> state finished
>Thread-56::DEBUG::2014-07-07 12:02:07,877::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-56::DEBUG::2014-07-07 12:02:07,877::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-56::DEBUG::2014-07-07 12:02:07,878::task::990::TaskManager.Task::(_decref) Task=`eafe0b9b-b669-4e75-90cd-ab2d1fcb58a9`::ref 0 aborting False
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,910::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::INFO::2014-07-07 12:02:07,988::fileVolume::144::Storage.Volume::(_create) Request to create RAW volume /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217 with size = 52428800 sectors
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:07,990::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,030::fileVolume::395::Storage.Volume::(newVolumeLease) Initializing volume lease volUUID=b36c97fc-9639-4750-b058-693abedd7217 sdUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68, metaId=('/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217',)
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,071::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,100::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996'
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,100::resourceManager::635::ResourceManager::(releaseResource) Released resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996' (0 active users)
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,100::resourceManager::641::ResourceManager::(releaseResource) Resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996' is free, finding out if anyone is waiting for it.
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,100::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource '62ad18aa-e99a-4139-b11f-3ecd3e188a68_imageNS.2a5a1148-bc39-47a0-9e29-f5b489435996', Clearing records.
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,101::task::595::TaskManager.Task::(_updateState) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::moving from state running -> state finished
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,101::task::752::TaskManager.Task::(_save) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::_save: orig /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250 temp /rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/master/tasks/cdf8bb21-1e0c-4cd1-abd9-53aa63a02250.temp
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,138::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68': < ResourceRef 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', isValid: 'True' obj: 'None'>}
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,138::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,138::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,138::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,138::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,139::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,139::task::913::TaskManager.Task::(_runJobs) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::Task.run: exit - success: result {'uuid': 'b36c97fc-9639-4750-b058-693abedd7217'}
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,139::task::990::TaskManager.Task::(_decref) Task=`cdf8bb21-1e0c-4cd1-abd9-53aa63a02250`::ref 0 aborting False
>cdf8bb21-1e0c-4cd1-abd9-53aa63a02250::DEBUG::2014-07-07 12:02:08,139::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>Thread-57::DEBUG::2014-07-07 12:02:08,927::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-57::DEBUG::2014-07-07 12:02:08,927::task::595::TaskManager.Task::(_updateState) Task=`84471d21-38c0-4174-a4a4-08ad41899520`::moving from state init -> state preparing
>Thread-57::INFO::2014-07-07 12:02:08,928::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-57::DEBUG::2014-07-07 12:02:08,928::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
>Thread-57::DEBUG::2014-07-07 12:02:08,928::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>Thread-57::DEBUG::2014-07-07 12:02:08,928::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}
>Thread-57::DEBUG::2014-07-07 12:02:08,928::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}
>Thread-57::INFO::2014-07-07 12:02:08,928::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}}
>Thread-57::DEBUG::2014-07-07 12:02:08,929::task::1185::TaskManager.Task::(prepare) Task=`84471d21-38c0-4174-a4a4-08ad41899520`::finished: {'allTasksStatus': {'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250': {'code': 0, 'message': '1 jobs completed successfully', 'taskState': 'finished', 'taskResult': 'success', 'taskID': 'cdf8bb21-1e0c-4cd1-abd9-53aa63a02250'}}}
>Thread-57::DEBUG::2014-07-07 12:02:08,929::task::595::TaskManager.Task::(_updateState) Task=`84471d21-38c0-4174-a4a4-08ad41899520`::moving from state preparing -> state finished
>Thread-57::DEBUG::2014-07-07 12:02:08,929::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-57::DEBUG::2014-07-07 12:02:08,929::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-57::DEBUG::2014-07-07 12:02:08,929::task::990::TaskManager.Task::(_decref) Task=`84471d21-38c0-4174-a4a4-08ad41899520`::ref 0 aborting False
>Thread-58::DEBUG::2014-07-07 12:02:08,977::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-58::DEBUG::2014-07-07 12:02:08,977::task::595::TaskManager.Task::(_updateState) Task=`c614036c-4056-4eea-aa5e-f26adc893537`::moving from state init -> state preparing
>Thread-58::INFO::2014-07-07 12:02:08,978::logUtils::44::dispatcher::(wrapper) Run and protect: clearTask(taskID='cdf8bb21-1e0c-4cd1-abd9-53aa63a02250', spUUID=None, options=None)
>Thread-58::DEBUG::2014-07-07 12:02:08,978::taskManager::161::TaskManager::(clearTask) Entry. taskID: cdf8bb21-1e0c-4cd1-abd9-53aa63a02250
>Thread-58::DEBUG::2014-07-07 12:02:08,985::taskManager::166::TaskManager::(clearTask) Return.
>Thread-58::INFO::2014-07-07 12:02:08,985::logUtils::47::dispatcher::(wrapper) Run and protect: clearTask, Return response: None
>Thread-58::DEBUG::2014-07-07 12:02:08,985::task::1185::TaskManager.Task::(prepare) Task=`c614036c-4056-4eea-aa5e-f26adc893537`::finished: None
>Thread-58::DEBUG::2014-07-07 12:02:08,985::task::595::TaskManager.Task::(_updateState) Task=`c614036c-4056-4eea-aa5e-f26adc893537`::moving from state preparing -> state finished
>Thread-58::DEBUG::2014-07-07 12:02:08,986::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-58::DEBUG::2014-07-07 12:02:08,986::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-58::DEBUG::2014-07-07 12:02:08,986::task::990::TaskManager.Task::(_decref) Task=`c614036c-4056-4eea-aa5e-f26adc893537`::ref 0 aborting False
>Thread-59::DEBUG::2014-07-07 12:02:09,035::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-59::DEBUG::2014-07-07 12:02:09,035::task::595::TaskManager.Task::(_updateState) Task=`bbe997d2-9aac-41b0-ba98-121929b50d74`::moving from state init -> state preparing
>Thread-59::INFO::2014-07-07 12:02:09,036::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-59::DEBUG::2014-07-07 12:02:09,036::taskManager::102::TaskManager::(getAllTasksStatuses) Entry.
>Thread-59::DEBUG::2014-07-07 12:02:09,036::taskManager::113::TaskManager::(getAllTasksStatuses) Return: {}
>Thread-59::INFO::2014-07-07 12:02:09,036::logUtils::47::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {}}
>Thread-59::DEBUG::2014-07-07 12:02:09,036::task::1185::TaskManager.Task::(prepare) Task=`bbe997d2-9aac-41b0-ba98-121929b50d74`::finished: {'allTasksStatus': {}}
>Thread-59::DEBUG::2014-07-07 12:02:09,036::task::595::TaskManager.Task::(_updateState) Task=`bbe997d2-9aac-41b0-ba98-121929b50d74`::moving from state preparing -> state finished
>Thread-59::DEBUG::2014-07-07 12:02:09,036::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-59::DEBUG::2014-07-07 12:02:09,037::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-59::DEBUG::2014-07-07 12:02:09,037::task::990::TaskManager.Task::(_decref) Task=`bbe997d2-9aac-41b0-ba98-121929b50d74`::ref 0 aborting False
>Thread-60::DEBUG::2014-07-07 12:02:09,084::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-60::DEBUG::2014-07-07 12:02:09,084::task::595::TaskManager.Task::(_updateState) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::moving from state init -> state preparing
>Thread-60::INFO::2014-07-07 12:02:09,085::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', options=None)
>Thread-60::DEBUG::2014-07-07 12:02:09,085::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`03536671-43f4-4766-ac4e-51df83f8bb09`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '616' at 'spmStop'
>Thread-60::DEBUG::2014-07-07 12:02:09,085::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-60::DEBUG::2014-07-07 12:02:09,085::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-60::DEBUG::2014-07-07 12:02:09,086::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`03536671-43f4-4766-ac4e-51df83f8bb09`::Granted request
>Thread-60::DEBUG::2014-07-07 12:02:09,086::task::827::TaskManager.Task::(resourceAcquired) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (exclusive)
>Thread-60::DEBUG::2014-07-07 12:02:09,086::task::990::TaskManager.Task::(_decref) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::ref 1 aborting False
>Thread-60::DEBUG::2014-07-07 12:02:09,086::sp::340::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process
>Thread-60::DEBUG::2014-07-07 12:02:09,086::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`4d3e2a21-5a73-4bd8-b732-9a9c8c2b4919`::Request was made in '/usr/share/vdsm/storage/sp.py' line '342' at '_shutDownUpgrade'
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`4d3e2a21-5a73-4bd8-b732-9a9c8c2b4919`::Granted request
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-60::DEBUG::2014-07-07 12:02:09,087::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-60::DEBUG::2014-07-07 12:02:09,088::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-60::DEBUG::2014-07-07 12:02:09,088::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-60::DEBUG::2014-07-07 12:02:09,088::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-60::DEBUG::2014-07-07 12:02:09,088::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=62ad18aa-e99a-4139-b11f-3ecd3e188a68:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=11a5671c-86ee-47e5-88a1-d66a76a4817f', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/190/nfs04', 'ROLE=Master', 'SDUUID=62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=a352483d9d02f860d5a60934aa3939b294b2260a']
>Thread-60::DEBUG::2014-07-07 12:02:09,094::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-60::INFO::2014-07-07 12:02:09,094::clusterlock::279::SANLock::(release) Releasing cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-60::DEBUG::2014-07-07 12:02:09,096::clusterlock::289::SANLock::(release) Cluster lock for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully released
>Thread-60::INFO::2014-07-07 12:02:09,097::logUtils::47::dispatcher::(wrapper) Run and protect: spmStop, Return response: None
>Thread-60::DEBUG::2014-07-07 12:02:09,097::task::1185::TaskManager.Task::(prepare) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::finished: None
>Thread-60::DEBUG::2014-07-07 12:02:09,097::task::595::TaskManager.Task::(_updateState) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::moving from state preparing -> state finished
>Thread-60::DEBUG::2014-07-07 12:02:09,097::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>Thread-60::DEBUG::2014-07-07 12:02:09,097::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-60::DEBUG::2014-07-07 12:02:09,097::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-60::DEBUG::2014-07-07 12:02:09,098::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-60::DEBUG::2014-07-07 12:02:09,098::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-60::DEBUG::2014-07-07 12:02:09,098::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-60::DEBUG::2014-07-07 12:02:09,098::task::990::TaskManager.Task::(_decref) Task=`0606fc24-46bf-4e0a-8a5b-ce9ccb82925c`::ref 0 aborting False
>Thread-61::DEBUG::2014-07-07 12:02:09,146::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-61::DEBUG::2014-07-07 12:02:09,147::task::595::TaskManager.Task::(_updateState) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::moving from state init -> state preparing
>Thread-61::INFO::2014-07-07 12:02:09,147::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='11a5671c-86ee-47e5-88a1-d66a76a4817f', hostID=1, remove=False, options=None)
>Thread-61::DEBUG::2014-07-07 12:02:09,147::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`04e702a1-40dc-4d50-8a63-3c0cb1c542d7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1131' at 'disconnectStoragePool'
>Thread-61::DEBUG::2014-07-07 12:02:09,147::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' for lock type 'exclusive'
>Thread-61::DEBUG::2014-07-07 12:02:09,147::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free. Now locking as 'exclusive' (1 active user)
>Thread-61::DEBUG::2014-07-07 12:02:09,148::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f`ReqID=`04e702a1-40dc-4d50-8a63-3c0cb1c542d7`::Granted request
>Thread-61::DEBUG::2014-07-07 12:02:09,148::task::827::TaskManager.Task::(resourceAcquired) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::_resourcesAcquired: Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f (exclusive)
>Thread-61::DEBUG::2014-07-07 12:02:09,148::task::990::TaskManager.Task::(_decref) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::ref 1 aborting False
>Thread-61::DEBUG::2014-07-07 12:02:09,148::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`ecb5aeb3-8a20-43d8-bca4-e9cd77d70ac5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1139' at '_disconnectPool'
>Thread-61::DEBUG::2014-07-07 12:02:09,148::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-61::DEBUG::2014-07-07 12:02:09,149::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-61::DEBUG::2014-07-07 12:02:09,149::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`ecb5aeb3-8a20-43d8-bca4-e9cd77d70ac5`::Granted request
>Thread-61::INFO::2014-07-07 12:02:09,149::sp::649::Storage.StoragePool::(disconnect) Disconnect from the storage pool 11a5671c-86ee-47e5-88a1-d66a76a4817f
>Thread-61::INFO::2014-07-07 12:02:09,943::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-31::DEBUG::2014-07-07 12:02:09,944::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-31::INFO::2014-07-07 12:02:09,944::clusterlock::207::SANLock::(releaseHostId) Releasing host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>Thread-41::INFO::2014-07-07 12:02:09,970::storage_mailbox::509::Storage.MailBox.HsmMailMonitor::(run) HSM_MailboxMonitor - Incoming mail monitoring thread stopped, clearing outgoing mail
>Thread-41::INFO::2014-07-07 12:02:09,970::storage_mailbox::385::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/bin/dd', 'of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=512', 'seek=8']
>Thread-41::DEBUG::2014-07-07 12:02:09,970::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd of=/rhev/data-center/11a5671c-86ee-47e5-88a1-d66a76a4817f/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=512 seek=8' (cwd None)
>Dummy-50::INFO::2014-07-07 12:02:10,159::storage_mailbox::794::Storage.MailBox.SpmMailMonitor::(run) SPM_MailMonitor - Incoming mail monitoring thread stopped
>Thread-31::DEBUG::2014-07-07 12:02:11,944::clusterlock::217::SANLock::(releaseHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 released successfully (id: 1)
>Thread-61::DEBUG::2014-07-07 12:02:11,945::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-61::DEBUG::2014-07-07 12:02:11,945::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-61::DEBUG::2014-07-07 12:02:11,945::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-61::DEBUG::2014-07-07 12:02:11,946::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-61::INFO::2014-07-07 12:02:11,946::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStoragePool, Return response: True
>Thread-61::DEBUG::2014-07-07 12:02:11,946::task::1185::TaskManager.Task::(prepare) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::finished: True
>Thread-61::DEBUG::2014-07-07 12:02:11,946::task::595::TaskManager.Task::(_updateState) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::moving from state preparing -> state finished
>Thread-61::DEBUG::2014-07-07 12:02:11,946::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f': < ResourceRef 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', isValid: 'True' obj: 'None'>}
>Thread-61::DEBUG::2014-07-07 12:02:11,947::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-61::DEBUG::2014-07-07 12:02:11,947::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f'
>Thread-61::DEBUG::2014-07-07 12:02:11,947::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' (0 active users)
>Thread-61::DEBUG::2014-07-07 12:02:11,947::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f' is free, finding out if anyone is waiting for it.
>Thread-61::DEBUG::2014-07-07 12:02:11,947::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.11a5671c-86ee-47e5-88a1-d66a76a4817f', Clearing records.
>Thread-61::DEBUG::2014-07-07 12:02:11,948::task::990::TaskManager.Task::(_decref) Task=`01611c96-ca71-4f3a-b9ff-0db824a00a8a`::ref 0 aborting False
>Thread-62::DEBUG::2014-07-07 12:02:11,997::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-62::DEBUG::2014-07-07 12:02:11,998::task::595::TaskManager.Task::(_updateState) Task=`2f697ae6-9c4c-4fa7-9cdb-1bba23d39b9a`::moving from state init -> state preparing
>Thread-62::INFO::2014-07-07 12:02:11,998::logUtils::44::dispatcher::(wrapper) Run and protect: startMonitoringDomain(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', hostID=1, options=None)
>Thread-62::DEBUG::2014-07-07 12:02:11,998::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`6322c700-59f6-4866-ba33-292de72de554`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3685' at 'startMonitoringDomain'
>Thread-62::DEBUG::2014-07-07 12:02:11,999::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-62::DEBUG::2014-07-07 12:02:11,999::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-62::DEBUG::2014-07-07 12:02:11,999::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`6322c700-59f6-4866-ba33-292de72de554`::Granted request
>Thread-62::INFO::2014-07-07 12:02:11,999::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-63::DEBUG::2014-07-07 12:02:12,000::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-62::DEBUG::2014-07-07 12:02:12,000::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-62::DEBUG::2014-07-07 12:02:12,001::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-62::DEBUG::2014-07-07 12:02:12,003::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-62::DEBUG::2014-07-07 12:02:12,003::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-62::INFO::2014-07-07 12:02:12,004::logUtils::47::dispatcher::(wrapper) Run and protect: startMonitoringDomain, Return response: None
>Thread-62::DEBUG::2014-07-07 12:02:12,005::task::1185::TaskManager.Task::(prepare) Task=`2f697ae6-9c4c-4fa7-9cdb-1bba23d39b9a`::finished: None
>Thread-62::DEBUG::2014-07-07 12:02:12,006::task::595::TaskManager.Task::(_updateState) Task=`2f697ae6-9c4c-4fa7-9cdb-1bba23d39b9a`::moving from state preparing -> state finished
>Thread-62::DEBUG::2014-07-07 12:02:12,007::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-62::DEBUG::2014-07-07 12:02:12,008::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-62::DEBUG::2014-07-07 12:02:12,010::task::990::TaskManager.Task::(_decref) Task=`2f697ae6-9c4c-4fa7-9cdb-1bba23d39b9a`::ref 0 aborting False
>Thread-63::DEBUG::2014-07-07 12:02:12,015::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-63::DEBUG::2014-07-07 12:02:12,021::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000380325 s, 1.3 MB/s\n'; <rc> = 0
>Thread-63::DEBUG::2014-07-07 12:02:12,025::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 changed its status to Valid
>Thread-64::DEBUG::2014-07-07 12:02:12,025::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-63::INFO::2014-07-07 12:02:12,025::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>Thread-64::DEBUG::2014-07-07 12:02:12,026::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-63::DEBUG::2014-07-07 12:02:12,027::clusterlock::202::SANLock::(acquireHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 successfully acquired (id: 1)
>Thread-64::DEBUG::2014-07-07 12:02:12,027::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-64::DEBUG::2014-07-07 12:02:12,029::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-66::INFO::2014-07-07 12:02:12,031::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-67::DEBUG::2014-07-07 12:02:17,067::task::595::TaskManager.Task::(_updateState) Task=`3fa9f185-b431-4050-8521-ab48d81069d2`::moving from state init -> state preparing
>Thread-67::INFO::2014-07-07 12:02:17,068::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-67::INFO::2014-07-07 12:02:17,068::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000380325', 'lastCheck': '5.0', 'valid': True}}
>Thread-67::DEBUG::2014-07-07 12:02:17,068::task::1185::TaskManager.Task::(prepare) Task=`3fa9f185-b431-4050-8521-ab48d81069d2`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000380325', 'lastCheck': '5.0', 'valid': True}}
>Thread-67::DEBUG::2014-07-07 12:02:17,068::task::595::TaskManager.Task::(_updateState) Task=`3fa9f185-b431-4050-8521-ab48d81069d2`::moving from state preparing -> state finished
>Thread-67::DEBUG::2014-07-07 12:02:17,068::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-67::DEBUG::2014-07-07 12:02:17,069::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-67::DEBUG::2014-07-07 12:02:17,069::task::990::TaskManager.Task::(_decref) Task=`3fa9f185-b431-4050-8521-ab48d81069d2`::ref 0 aborting False
>Thread-67::ERROR::2014-07-07 12:02:17,070::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-63::DEBUG::2014-07-07 12:02:22,032::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-63::DEBUG::2014-07-07 12:02:22,038::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.00046324 s, 1.1 MB/s\n'; <rc> = 0
>Thread-68::DEBUG::2014-07-07 12:02:22,132::task::595::TaskManager.Task::(_updateState) Task=`ed34abc8-d3c5-4ab5-abfe-b293af101e48`::moving from state init -> state preparing
>Thread-68::INFO::2014-07-07 12:02:22,132::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-68::INFO::2014-07-07 12:02:22,132::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.00046324', 'lastCheck': '0.1', 'valid': True}}
>Thread-68::DEBUG::2014-07-07 12:02:22,133::task::1185::TaskManager.Task::(prepare) Task=`ed34abc8-d3c5-4ab5-abfe-b293af101e48`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.00046324', 'lastCheck': '0.1', 'valid': True}}
>Thread-68::DEBUG::2014-07-07 12:02:22,133::task::595::TaskManager.Task::(_updateState) Task=`ed34abc8-d3c5-4ab5-abfe-b293af101e48`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-07-07 12:02:22,133::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-68::DEBUG::2014-07-07 12:02:22,133::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-07-07 12:02:22,133::task::990::TaskManager.Task::(_decref) Task=`ed34abc8-d3c5-4ab5-abfe-b293af101e48`::ref 0 aborting False
>Thread-68::ERROR::2014-07-07 12:02:22,134::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-69::DEBUG::2014-07-07 12:02:27,196::task::595::TaskManager.Task::(_updateState) Task=`51415057-e00c-4da8-958d-9ca38999374b`::moving from state init -> state preparing
>Thread-69::INFO::2014-07-07 12:02:27,196::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-69::INFO::2014-07-07 12:02:27,197::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.00046324', 'lastCheck': '5.1', 'valid': True}}
>Thread-69::DEBUG::2014-07-07 12:02:27,197::task::1185::TaskManager.Task::(prepare) Task=`51415057-e00c-4da8-958d-9ca38999374b`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.00046324', 'lastCheck': '5.1', 'valid': True}}
>Thread-69::DEBUG::2014-07-07 12:02:27,197::task::595::TaskManager.Task::(_updateState) Task=`51415057-e00c-4da8-958d-9ca38999374b`::moving from state preparing -> state finished
>Thread-69::DEBUG::2014-07-07 12:02:27,197::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-69::DEBUG::2014-07-07 12:02:27,197::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-69::DEBUG::2014-07-07 12:02:27,197::task::990::TaskManager.Task::(_decref) Task=`51415057-e00c-4da8-958d-9ca38999374b`::ref 0 aborting False
>Thread-69::ERROR::2014-07-07 12:02:27,198::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-63::DEBUG::2014-07-07 12:02:32,073::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-63::DEBUG::2014-07-07 12:02:32,079::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000351019 s, 1.5 MB/s\n'; <rc> = 0
>Thread-70::DEBUG::2014-07-07 12:02:32,260::task::595::TaskManager.Task::(_updateState) Task=`8767f429-9c48-4cd6-a067-09879c3e773f`::moving from state init -> state preparing
>Thread-70::INFO::2014-07-07 12:02:32,260::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-70::INFO::2014-07-07 12:02:32,260::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000351019', 'lastCheck': '0.2', 'valid': True}}
>Thread-70::DEBUG::2014-07-07 12:02:32,261::task::1185::TaskManager.Task::(prepare) Task=`8767f429-9c48-4cd6-a067-09879c3e773f`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000351019', 'lastCheck': '0.2', 'valid': True}}
>Thread-70::DEBUG::2014-07-07 12:02:32,261::task::595::TaskManager.Task::(_updateState) Task=`8767f429-9c48-4cd6-a067-09879c3e773f`::moving from state preparing -> state finished
>Thread-70::DEBUG::2014-07-07 12:02:32,261::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-70::DEBUG::2014-07-07 12:02:32,261::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-70::DEBUG::2014-07-07 12:02:32,261::task::990::TaskManager.Task::(_decref) Task=`8767f429-9c48-4cd6-a067-09879c3e773f`::ref 0 aborting False
>Thread-70::ERROR::2014-07-07 12:02:32,262::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-71::DEBUG::2014-07-07 12:02:37,324::task::595::TaskManager.Task::(_updateState) Task=`25a6de64-a3c9-463f-a06a-c70d670a60d3`::moving from state init -> state preparing
>Thread-71::INFO::2014-07-07 12:02:37,324::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-71::INFO::2014-07-07 12:02:37,325::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000351019', 'lastCheck': '5.2', 'valid': True}}
>Thread-71::DEBUG::2014-07-07 12:02:37,325::task::1185::TaskManager.Task::(prepare) Task=`25a6de64-a3c9-463f-a06a-c70d670a60d3`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000351019', 'lastCheck': '5.2', 'valid': True}}
>Thread-71::DEBUG::2014-07-07 12:02:37,325::task::595::TaskManager.Task::(_updateState) Task=`25a6de64-a3c9-463f-a06a-c70d670a60d3`::moving from state preparing -> state finished
>Thread-71::DEBUG::2014-07-07 12:02:37,325::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-71::DEBUG::2014-07-07 12:02:37,325::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-71::DEBUG::2014-07-07 12:02:37,325::task::990::TaskManager.Task::(_decref) Task=`25a6de64-a3c9-463f-a06a-c70d670a60d3`::ref 0 aborting False
>Thread-71::ERROR::2014-07-07 12:02:37,326::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-63::DEBUG::2014-07-07 12:02:42,085::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-63::DEBUG::2014-07-07 12:02:42,092::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.000364625 s, 1.4 MB/s\n'; <rc> = 0
>Thread-72::DEBUG::2014-07-07 12:02:42,387::task::595::TaskManager.Task::(_updateState) Task=`0d9ba9cf-6691-409d-8616-f4b7c8cc16bf`::moving from state init -> state preparing
>Thread-72::INFO::2014-07-07 12:02:42,387::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-72::INFO::2014-07-07 12:02:42,387::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000364625', 'lastCheck': '0.3', 'valid': True}}
>Thread-72::DEBUG::2014-07-07 12:02:42,387::task::1185::TaskManager.Task::(prepare) Task=`0d9ba9cf-6691-409d-8616-f4b7c8cc16bf`::finished: {'62ad18aa-e99a-4139-b11f-3ecd3e188a68': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000364625', 'lastCheck': '0.3', 'valid': True}}
>Thread-72::DEBUG::2014-07-07 12:02:42,388::task::595::TaskManager.Task::(_updateState) Task=`0d9ba9cf-6691-409d-8616-f4b7c8cc16bf`::moving from state preparing -> state finished
>Thread-72::DEBUG::2014-07-07 12:02:42,388::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-72::DEBUG::2014-07-07 12:02:42,388::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-72::DEBUG::2014-07-07 12:02:42,388::task::990::TaskManager.Task::(_decref) Task=`0d9ba9cf-6691-409d-8616-f4b7c8cc16bf`::ref 0 aborting False
>Thread-72::ERROR::2014-07-07 12:02:42,389::API::1611::vds::(_getHaInfo) failed to retrieve Hosted Engine HA info
>Traceback (most recent call last):
>  File "/usr/share/vdsm/API.py", line 1598, in _getHaInfo
>    host_id = instance.get_local_host_id()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/client/client.py", line 193, in get_local_host_id
>    self._config = config.Config()
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 57, in __init__
>    self._load(Config.static_files)
>  File "/usr/lib/python2.6/site-packages/ovirt_hosted_engine_ha/env/config.py", line 63, in _load
>    with open(fname, 'r') as f:
>IOError: [Errno 2] No such file or directory: '/etc/ovirt-hosted-engine/hosted-engine.conf'
>Thread-73::DEBUG::2014-07-07 12:02:48,022::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmGetStats with ('cfec72b7-672a-4801-8727-9480571b1eef',) {}
>Thread-73::DEBUG::2014-07-07 12:02:48,022::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
>Thread-74::DEBUG::2014-07-07 12:02:48,160::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmCreate with ({'emulatedMachine': 'pc', 'vmId': 'cfec72b7-672a-4801-8727-9480571b1eef', 'devices': [{'index': '2', 'iface': 'ide', 'specParams': {}, 'readonly': 'true', 'deviceId': 'a10dd8ff-9d7a-4e5d-8953-4084602f2363', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'index': '0', 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '00000000-0000-0000-0000-000000000000', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996', 'specParams': {}, 'readonly': 'false', 'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'deviceId': '2a5a1148-bc39-47a0-9e29-f5b489435996', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'exclusive', 'propagateErrors': 'off', 'type': 'disk'}, {'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'nicModel': 'pv', 'macAddr': '01:1A:4C:10:3F:11', 'linkActive': 'true', 'network': 'rhevm', 'bootOrder': '1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '949b573a-716a-4d92-b3dd-51a9d4688119', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'console', 'specParams': {}, 'type': 'console', 'deviceId': '1ed6d08a-d6ce-4022-bc7b-d19a58bd227c', 'alias': 'console0'}], 'smp': '2', 'memSize': '4096', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir', 'vmName': 'HostedEngine', 'display': 'vnc'},) {}
>Thread-74::INFO::2014-07-07 12:02:48,166::API::667::vds::(_getNetworkIp) network None: using 0
>Thread-74::INFO::2014-07-07 12:02:48,167::clientIF::366::vds::(createVm) vmContainerLock acquired by vm cfec72b7-672a-4801-8727-9480571b1eef
>Thread-74::DEBUG::2014-07-07 12:02:48,167::libvirtconnection::145::root::(get) trying to connect libvirt
>Thread-75::DEBUG::2014-07-07 12:02:48,203::vm::2270::vm.Vm::(_startUnderlyingVm) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::Start
>Thread-74::DEBUG::2014-07-07 12:02:48,203::clientIF::379::vds::(createVm) Total desktops after creation of cfec72b7-672a-4801-8727-9480571b1eef is 1
>Thread-74::DEBUG::2014-07-07 12:02:48,203::BindingXMLRPC::1074::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'nicModel': 'rtl8139,pv', 'vmId': 'cfec72b7-672a-4801-8727-9480571b1eef', 'emulatedMachine': 'pc', 'displayIp': '0', 'pid': '0', 'devices': [{'index': '2', 'iface': 'ide', 'specParams': {}, 'readonly': 'true', 'deviceId': 'a10dd8ff-9d7a-4e5d-8953-4084602f2363', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'index': '0', 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '00000000-0000-0000-0000-000000000000', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996', 'specParams': {}, 'readonly': 'false', 'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'deviceId': '2a5a1148-bc39-47a0-9e29-f5b489435996', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'exclusive', 'propagateErrors': 'off', 'type': 'disk'}, {'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'nicModel': 'pv', 'macAddr': '01:1A:4C:10:3F:11', 'linkActive': 'true', 'network': 'rhevm', 'bootOrder': '1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '949b573a-716a-4d92-b3dd-51a9d4688119', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'console', 'specParams': {}, 'type': 'console', 'deviceId': '1ed6d08a-d6ce-4022-bc7b-d19a58bd227c', 'alias': 'console0'}], 'smp': '2', 'vmType': 'kvm', 'displaySecurePort': '-1', 'memSize': '4096', 'displayPort': '-1', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sdisplay,sinputs,scursor,splayback,srecord,ssmartcard,susbredir', 'clientIp': '', 'vmName': 'HostedEngine', 'display': 'vnc'}}
>Thread-75::DEBUG::2014-07-07 12:02:48,203::vm::2274::vm.Vm::(_startUnderlyingVm) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::_ongoingCreations acquired
>Thread-75::INFO::2014-07-07 12:02:48,204::vm::3151::vm.Vm::(_run) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::VM wrapper has started
>Thread-75::DEBUG::2014-07-07 12:02:48,205::task::595::TaskManager.Task::(_updateState) Task=`fc8254b4-4e3a-4818-871b-afed6a6a20ee`::moving from state init -> state preparing
>Thread-75::INFO::2014-07-07 12:02:48,205::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='2a5a1148-bc39-47a0-9e29-f5b489435996', volUUID='b36c97fc-9639-4750-b058-693abedd7217', options=None)
>Thread-75::INFO::2014-07-07 12:02:48,208::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '0', 'apparentsize': '26843545600'}
>Thread-75::DEBUG::2014-07-07 12:02:48,208::task::1185::TaskManager.Task::(prepare) Task=`fc8254b4-4e3a-4818-871b-afed6a6a20ee`::finished: {'truesize': '0', 'apparentsize': '26843545600'}
>Thread-75::DEBUG::2014-07-07 12:02:48,208::task::595::TaskManager.Task::(_updateState) Task=`fc8254b4-4e3a-4818-871b-afed6a6a20ee`::moving from state preparing -> state finished
>Thread-75::DEBUG::2014-07-07 12:02:48,209::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-75::DEBUG::2014-07-07 12:02:48,209::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-75::DEBUG::2014-07-07 12:02:48,209::task::990::TaskManager.Task::(_decref) Task=`fc8254b4-4e3a-4818-871b-afed6a6a20ee`::ref 0 aborting False
>Thread-75::INFO::2014-07-07 12:02:48,209::clientIF::324::vds::(prepareVolumePath) prepared volume path: 
>Thread-75::DEBUG::2014-07-07 12:02:48,209::task::595::TaskManager.Task::(_updateState) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::moving from state init -> state preparing
>Thread-75::INFO::2014-07-07 12:02:48,209::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', spUUID='00000000-0000-0000-0000-000000000000', imgUUID='2a5a1148-bc39-47a0-9e29-f5b489435996', leafUUID='b36c97fc-9639-4750-b058-693abedd7217')
>Thread-75::DEBUG::2014-07-07 12:02:48,210::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`c5409013-f279-4fdb-8f05-4af15a8bcc2f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3248' at 'prepareImage'
>Thread-75::DEBUG::2014-07-07 12:02:48,210::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' for lock type 'shared'
>Thread-75::DEBUG::2014-07-07 12:02:48,210::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free. Now locking as 'shared' (1 active user)
>Thread-75::DEBUG::2014-07-07 12:02:48,210::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68`ReqID=`c5409013-f279-4fdb-8f05-4af15a8bcc2f`::Granted request
>Thread-75::DEBUG::2014-07-07 12:02:48,211::task::827::TaskManager.Task::(resourceAcquired) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::_resourcesAcquired: Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68 (shared)
>Thread-75::DEBUG::2014-07-07 12:02:48,211::task::990::TaskManager.Task::(_decref) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::ref 1 aborting False
>Thread-75::DEBUG::2014-07-07 12:02:48,217::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for b36c97fc-9639-4750-b058-693abedd7217
>Thread-75::INFO::2014-07-07 12:02:48,218::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'leasePath': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217.lease', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996'}, 'path': '/var/run/vdsm/storage/62ad18aa-e99a-4139-b11f-3ecd3e188a68/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'imgVolumesInfo': [{'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'leasePath': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217.lease', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996'}]}
>Thread-75::DEBUG::2014-07-07 12:02:48,218::task::1185::TaskManager.Task::(prepare) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::finished: {'info': {'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'leasePath': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217.lease', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996'}, 'path': '/var/run/vdsm/storage/62ad18aa-e99a-4139-b11f-3ecd3e188a68/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'imgVolumesInfo': [{'domainID': '62ad18aa-e99a-4139-b11f-3ecd3e188a68', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217', 'volumeID': 'b36c97fc-9639-4750-b058-693abedd7217', 'leasePath': '/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217.lease', 'imageID': '2a5a1148-bc39-47a0-9e29-f5b489435996'}]}
>Thread-75::DEBUG::2014-07-07 12:02:48,218::task::595::TaskManager.Task::(_updateState) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::moving from state preparing -> state finished
>Thread-75::DEBUG::2014-07-07 12:02:48,218::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68': < ResourceRef 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', isValid: 'True' obj: 'None'>}
>Thread-75::DEBUG::2014-07-07 12:02:48,218::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-75::DEBUG::2014-07-07 12:02:48,218::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68'
>Thread-75::DEBUG::2014-07-07 12:02:48,218::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' (0 active users)
>Thread-75::DEBUG::2014-07-07 12:02:48,218::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68' is free, finding out if anyone is waiting for it.
>Thread-75::DEBUG::2014-07-07 12:02:48,219::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.62ad18aa-e99a-4139-b11f-3ecd3e188a68', Clearing records.
>Thread-75::DEBUG::2014-07-07 12:02:48,219::task::990::TaskManager.Task::(_decref) Task=`7d8f9a21-5884-424c-93ec-72183ca13ebc`::ref 0 aborting False
>Thread-75::INFO::2014-07-07 12:02:48,219::clientIF::324::vds::(prepareVolumePath) prepared volume path: /var/run/vdsm/storage/62ad18aa-e99a-4139-b11f-3ecd3e188a68/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217
>Thread-75::DEBUG::2014-07-07 12:02:48,229::utils::642::root::(execCmd) '/usr/libexec/vdsm/hooks/before_vm_start/50_hostedengine' (cwd None)
>Thread-75::DEBUG::2014-07-07 12:02:48,279::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-75::INFO::2014-07-07 12:02:48,280::hooks::100::root::(_runHooksDir) 
>Thread-75::DEBUG::2014-07-07 12:02:48,281::vm::3190::vm.Vm::(_run) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::<?xml version="1.0" encoding="utf-8"?><domain type="kvm">
>	<name>HostedEngine</name>
>	<uuid>cfec72b7-672a-4801-8727-9480571b1eef</uuid>
>	<memory>4194304</memory>
>	<currentMemory>4194304</currentMemory>
>	<vcpu current="2">2</vcpu>
>	<memtune>
>		<min_guarantee>0</min_guarantee>
>	</memtune>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/cfec72b7-672a-4801-8727-9480571b1eef.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/cfec72b7-672a-4801-8727-9480571b1eef.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<graphics autoport="yes" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" type="vnc"/>
>		<console type="pty">
>			<target port="0" type="virtio"/>
>		</console>
>		<memballoon model="none"/>
>		<controller model="virtio-scsi" type="scsi"/>
>		<interface type="bridge">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>
>			<mac address="01:1A:4C:10:3F:11"/>
>			<model type="virtio"/>
>			<source bridge="rhevm"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>			<boot order="1"/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address bus="1" controller="0" target="0" type="drive" unit="0"/>
>			<source file="" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
>			<source file="/var/run/vdsm/storage/62ad18aa-e99a-4139-b11f-3ecd3e188a68/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>2a5a1148-bc39-47a0-9e29-f5b489435996</serial>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>		<lease>
>			<key>b36c97fc-9639-4750-b058-693abedd7217</key>
>			<lockspace>62ad18aa-e99a-4139-b11f-3ecd3e188a68</lockspace>
>			<target offset="0" path="/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/images/2a5a1148-bc39-47a0-9e29-f5b489435996/b36c97fc-9639-4750-b058-693abedd7217.lease"/>
>		</lease>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="pc">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">Red Hat</entry>
>			<entry name="product">RHEV Hypervisor</entry>
>			<entry name="version">6-5.el6.centos.11.1</entry>
>			<entry name="serial">30303734-3536-5A43-3133-343330305746_a4:5d:36:11:e4:80</entry>
>			<entry name="uuid">cfec72b7-672a-4801-8727-9480571b1eef</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Conroe</model>
>	</cpu>
><on_poweroff>destroy</on_poweroff><on_reboot>destroy</on_reboot><on_crash>destroy</on_crash></domain>
>Thread-75::DEBUG::2014-07-07 12:02:48,287::libvirtconnection::124::root::(wrapper) Unknown libvirterror: ecode: 27 edom: 20 level: 2 message: XML error: expected unicast mac address, found multicast '01:1A:4C:10:3F:11'
>Thread-75::DEBUG::2014-07-07 12:02:48,287::vm::2291::vm.Vm::(_startUnderlyingVm) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::_ongoingCreations released
>Thread-75::ERROR::2014-07-07 12:02:48,287::vm::2317::vm.Vm::(_startUnderlyingVm) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 2277, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/vm.py", line 3224, in _run
>    self._connection.createXML(domxml, flags),
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 92, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2665, in createXML
>    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
>libvirtError: XML error: expected unicast mac address, found multicast '01:1A:4C:10:3F:11'
>Thread-75::DEBUG::2014-07-07 12:02:48,294::vm::2759::vm.Vm::(setDownStatus) vmId=`cfec72b7-672a-4801-8727-9480571b1eef`::Changed state to Down: XML error: expected unicast mac address, found multicast '01:1A:4C:10:3F:11'
>Thread-77::DEBUG::2014-07-07 12:02:48,353::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-77::ERROR::2014-07-07 12:02:48,354::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-78::DEBUG::2014-07-07 12:02:49,494::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-78::ERROR::2014-07-07 12:02:49,495::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-79::DEBUG::2014-07-07 12:02:50,634::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-79::ERROR::2014-07-07 12:02:50,635::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-80::DEBUG::2014-07-07 12:02:51,775::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-80::ERROR::2014-07-07 12:02:51,775::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-63::DEBUG::2014-07-07 12:02:52,100::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_190_nfs04/62ad18aa-e99a-4139-b11f-3ecd3e188a68/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-63::DEBUG::2014-07-07 12:02:52,106::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n513 bytes (513 B) copied, 0.00032579 s, 1.6 MB/s\n'; <rc> = 0
>Thread-81::DEBUG::2014-07-07 12:02:52,914::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-81::ERROR::2014-07-07 12:02:52,915::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-82::DEBUG::2014-07-07 12:02:54,055::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-82::ERROR::2014-07-07 12:02:54,056::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-83::DEBUG::2014-07-07 12:02:55,198::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-83::ERROR::2014-07-07 12:02:55,199::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-84::DEBUG::2014-07-07 12:02:56,343::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-84::ERROR::2014-07-07 12:02:56,343::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-85::DEBUG::2014-07-07 12:02:57,484::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-85::ERROR::2014-07-07 12:02:57,485::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-86::DEBUG::2014-07-07 12:02:58,625::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('cfec72b7-672a-4801-8727-9480571b1eef', '5735IZOR', '10800', 'disconnect', {}) {}
>Thread-86::ERROR::2014-07-07 12:02:58,626::BindingXMLRPC::1086::vds::(wrapper) unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 1070, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/BindingXMLRPC.py", line 314, in vmSetTicket
>    return vm.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/API.py", line 610, in setTicket
>    return v.setTicket(password, ttl, existingConnAction, params)
>  File "/usr/share/vdsm/vm.py", line 4532, in setTicket
>    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
>AttributeError: 'NoneType' object has no attribute 'XMLDesc'
>Thread-87::DEBUG::2014-07-07 12:02:59,694::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-87::DEBUG::2014-07-07 12:02:59,695::task::595::TaskManager.Task::(_updateState) Task=`8b51ac33-be60-4a70-8238-793cd10fd4a5`::moving from state init -> state preparing
>Thread-87::INFO::2014-07-07 12:02:59,695::logUtils::44::dispatcher::(wrapper) Run and protect: stopMonitoringDomain(sdUUID='62ad18aa-e99a-4139-b11f-3ecd3e188a68', options=None)
>Thread-87::DEBUG::2014-07-07 12:02:59,695::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc4f4c63-9b45-4f13-bebc-314295038991`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3692' at 'stopMonitoringDomain'
>Thread-87::DEBUG::2014-07-07 12:02:59,696::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-87::DEBUG::2014-07-07 12:02:59,696::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-87::DEBUG::2014-07-07 12:02:59,696::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`bc4f4c63-9b45-4f13-bebc-314295038991`::Granted request
>Thread-87::INFO::2014-07-07 12:02:59,697::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-63::DEBUG::2014-07-07 12:02:59,697::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 62ad18aa-e99a-4139-b11f-3ecd3e188a68
>Thread-63::INFO::2014-07-07 12:02:59,697::clusterlock::207::SANLock::(releaseHostId) Releasing host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 (id: 1)
>Thread-63::DEBUG::2014-07-07 12:03:01,698::clusterlock::217::SANLock::(releaseHostId) Host id for domain 62ad18aa-e99a-4139-b11f-3ecd3e188a68 released successfully (id: 1)
>Thread-87::DEBUG::2014-07-07 12:03:01,699::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-87::DEBUG::2014-07-07 12:03:01,699::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-87::DEBUG::2014-07-07 12:03:01,699::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-87::DEBUG::2014-07-07 12:03:01,699::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-87::INFO::2014-07-07 12:03:01,699::logUtils::47::dispatcher::(wrapper) Run and protect: stopMonitoringDomain, Return response: None
>Thread-87::DEBUG::2014-07-07 12:03:01,700::task::1185::TaskManager.Task::(prepare) Task=`8b51ac33-be60-4a70-8238-793cd10fd4a5`::finished: None
>Thread-87::DEBUG::2014-07-07 12:03:01,700::task::595::TaskManager.Task::(_updateState) Task=`8b51ac33-be60-4a70-8238-793cd10fd4a5`::moving from state preparing -> state finished
>Thread-87::DEBUG::2014-07-07 12:03:01,700::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-87::DEBUG::2014-07-07 12:03:01,700::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-87::DEBUG::2014-07-07 12:03:01,700::task::990::TaskManager.Task::(_decref) Task=`8b51ac33-be60-4a70-8238-793cd10fd4a5`::ref 0 aborting False

Actions: View

Attachments on bug 1116785: 916035