Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 916035 Details for
Bug 1116785
multicast mac address should be filtered by hosted-engine-setup
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
vdsm log
vdsm.log (text/plain), 217.44 KB, created by
Jiri Moskovcak
on 2014-07-07 10:50:08 UTC
(
hide
)
Description:
vdsm log
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1116785
: 916035