[ovirt-users] New problem with hosted-engine during "Configuring the management bridge"
Bob Doolittle
bob at doolittle.us.com
Tue May 13 17:11:52 UTC 2014
Maybe this isn't the actual problem after all.
I replaced /sbin/multipath with a script runs the old version, but the
suppresses those errors and returns exit status 0.
But "vdsm-tool service-reload multipathd" is still failing and I don't
know why.
I have attached my vdsm.log file.
Any guidance appreciated. I'll try digging through the python code for
service.py and see if I can catch it when the multipath configuration is
in place to see the exact issue.
-Bob
On 05/13/2014 12:27 PM, Bob Doolittle wrote:
> Hi,
>
> I have started a new installation as specified in the 3.4.1 release
> notes (fresh Fedora 19 install, yum localinstall
> http://resources.ovirt.org/pub/yum-repo/ovirt-release34.rpm).
>
> This is failing in the step "Configuring the management bridge".
>
> Based on the vdsm.log, it appears I am hitting:
> *Bug 988995* <https://bugzilla.redhat.com/show_bug.cgi?id=988995>
> -vdsm multipath.py restarts mutipathd, cutting the branch vdsm sits on
>
> "multipath -F" is returning "invalid keyword: getuid_callout" and it
> appears that this is causing vdsm-tool to abort (although the command
> exit status is 0 and the bug report says that those are only harmless
> warnings).
>
> There is no workaround stated in that bug report.
>
> Help?
>
> -Bob
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20140513/7356bb9f/attachment-0001.html>
-------------- next part --------------
MainThread::INFO::2014-05-13 11:51:28,230::vdsm::119::vds::(run) (PID: 4096) I am the actual vdsm 4.14.8.1-0.fc19 xion2.smartcity.net (3.13.11-100.fc19.x86_64)
MainThread::DEBUG::2014-05-13 11:51:28,231::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2014-05-13 11:51:28,231::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::DEBUG::2014-05-13 11:51:28,500::multipath::151::Storage.Multipath::(isEnabled) multipath Defaulting to False
MainThread::DEBUG::2014-05-13 11:51:28,500::multipath::169::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /usr/bin/cp /tmp/tmp_EEqAA /etc/multipath.conf' (cwd None)
MainThread::DEBUG::2014-05-13 11:51:28,509::multipath::169::Storage.Misc.excCmd::(setupMultipath) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2014-05-13 11:51:28,509::multipath::175::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /sbin/multipath -F' (cwd None)
MainThread::DEBUG::2014-05-13 11:51:28,537::multipath::175::Storage.Misc.excCmd::(setupMultipath) FAILED: <err> = ''; <rc> = 1
MainThread::DEBUG::2014-05-13 11:51:28,537::multipath::178::Storage.Misc.excCmd::(setupMultipath) '/usr/bin/sudo -n /usr/bin/vdsm-tool service-reload multipathd' (cwd None)
MainThread::DEBUG::2014-05-13 11:51:28,844::multipath::178::Storage.Misc.excCmd::(setupMultipath) FAILED: <err> = 'Traceback (most recent call last):\n File "/usr/bin/vdsm-tool", line 145, in <module>\n sys.exit(main())\n File "/usr/bin/vdsm-tool", line 142, in main\n return tool_command[cmd]["command"](*args[1:])\n File "/usr/lib64/python2.7/site-packages/vdsm/tool/service.py", line 399, in service_reload\n return _runAlts(_srvReloadAlts, srvName)\n File "/usr/lib64/python2.7/site-packages/vdsm/tool/service.py", line 351, in _runAlts\n "%s failed" % alt.func_name, out, err)\nvdsm.tool.service.ServiceOperationError: ServiceOperationError: _systemctlReload failed\nJob for multipathd.service failed. See \'systemctl status multipathd.service\' and \'journalctl -xn\' for details.\n\n'; <rc> = 1
MainThread::ERROR::2014-05-13 11:51:28,844::utils::1107::root::(panic) Panic: Error initializing IRS
Traceback (most recent call last):
File "/usr/share/vdsm/vdsm", line 72, in serve_clients
irs = Dispatcher(HSM())
File "/usr/share/vdsm/storage/hsm.py", line 359, in __init__
multipath.setupMultipath()
File "/usr/share/vdsm/storage/multipath.py", line 180, in setupMultipath
raise se.MultipathReloadError()
MultipathReloadError: Multipath service reload error: ()
MainThread::INFO::2014-05-13 11:51:30,078::vdsm::119::vds::(run) (PID: 4251) I am the actual vdsm 4.14.8.1-0.fc19 xion2.smartcity.net (3.13.11-100.fc19.x86_64)
MainThread::DEBUG::2014-05-13 11:51:30,079::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2014-05-13 11:51:30,079::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2014-05-13 11:51:30,080::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2014-05-13 11:51:30,355::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2014-05-13 11:51:30,367::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2014-05-13 11:51:30,367::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2014-05-13 11:51:30,382::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2014-05-13 11:51:30,382::hsm::448::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2014-05-13 11:51:30,385::hsm::480::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2014-05-13 11:51:30,385::hsm::481::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2014-05-13 11:51:30,385::hsm::483::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2014-05-13 11:51:30,386::hsm::526::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2014-05-13 11:51:30,386::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2014-05-13 11:51:30,387::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2014-05-13 11:51:30,387::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 11:51:30,401::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2014-05-13 11:51:30,401::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 11:51:30,401::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2014-05-13 11:51:30,401::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2014-05-13 11:51:30,478::misc::772::SamplingMethod::(__call__) Returning last result
MainThread::DEBUG::2014-05-13 11:51:30,478::task::595::TaskManager.Task::(_updateState) Task=`e761e7aa-f870-4593-b1b0-36e3969ab224`::moving from state init -> state preparing
storageRefresh::DEBUG::2014-05-13 11:51:30,478::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
MainThread::INFO::2014-05-13 11:51:30,478::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x30c0c68>>)
MainThread::INFO::2014-05-13 11:51:30,480::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2014-05-13 11:51:30,481::task::1185::TaskManager.Task::(prepare) Task=`e761e7aa-f870-4593-b1b0-36e3969ab224`::finished: None
MainThread::DEBUG::2014-05-13 11:51:30,481::task::595::TaskManager.Task::(_updateState) Task=`e761e7aa-f870-4593-b1b0-36e3969ab224`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 11:51:30,481::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 11:51:30,481::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 11:51:30,481::task::990::TaskManager.Task::(_decref) Task=`e761e7aa-f870-4593-b1b0-36e3969ab224`::ref 0 aborting False
MainThread::INFO::2014-05-13 11:51:30,486::momIF::47::MOM::(__init__) Starting up MOM
MainThread::INFO::2014-05-13 11:51:30,488::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2014-05-13 11:51:30,490::vmChannels::170::vds::(run) Starting VM channels listener thread.
clientIFinit::DEBUG::2014-05-13 11:51:30,505::libvirtconnection::145::root::(get) trying to connect libvirt
MainThread::WARNING::2014-05-13 11:51:30,505::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
storageRefresh::DEBUG::2014-05-13 11:51:30,535::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2014-05-13 11:51:30,539::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,543::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,546::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,549::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,551::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,554::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,556::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 11:51:30,559::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,573::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-05-13 11:51:30,596::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 11:51:30,598::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,600::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,607::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-05-13 11:51:30,622::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 11:51:30,623::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,626::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-05-13 11:51:30,641::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 11:51:30,642::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,645::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-05-13 11:51:30,669::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 11:51:30,670::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 11:51:30,671::hsm::392::Storage.HSM::(storageRefresh) HSM is ready
Thread-13::DEBUG::2014-05-13 11:51:31,101::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-13::DEBUG::2014-05-13 11:51:31,121::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-15::DEBUG::2014-05-13 11:51:31,199::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-15::DEBUG::2014-05-13 11:51:31,199::task::595::TaskManager.Task::(_updateState) Task=`fddd9d22-c643-4b23-bd30-64ef2c15863a`::moving from state init -> state preparing
Thread-15::INFO::2014-05-13 11:51:31,199::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
Thread-15::INFO::2014-05-13 11:51:31,199::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
Thread-15::DEBUG::2014-05-13 11:51:31,200::task::1185::TaskManager.Task::(prepare) Task=`fddd9d22-c643-4b23-bd30-64ef2c15863a`::finished: {'poollist': []}
Thread-15::DEBUG::2014-05-13 11:51:31,200::task::595::TaskManager.Task::(_updateState) Task=`fddd9d22-c643-4b23-bd30-64ef2c15863a`::moving from state preparing -> state finished
Thread-15::DEBUG::2014-05-13 11:51:31,200::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-15::DEBUG::2014-05-13 11:51:31,200::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-15::DEBUG::2014-05-13 11:51:31,200::task::990::TaskManager.Task::(_decref) Task=`fddd9d22-c643-4b23-bd30-64ef2c15863a`::ref 0 aborting False
Thread-16::DEBUG::2014-05-13 11:53:11,532::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-16::DEBUG::2014-05-13 11:53:11,534::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-18::DEBUG::2014-05-13 11:53:11,605::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-18::DEBUG::2014-05-13 11:53:11,605::task::595::TaskManager.Task::(_updateState) Task=`45beb897-61c1-4627-8f5a-6baa035bc687`::moving from state init -> state preparing
Thread-18::INFO::2014-05-13 11:53:11,606::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
Thread-18::INFO::2014-05-13 11:53:11,606::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
Thread-18::DEBUG::2014-05-13 11:53:11,606::task::1185::TaskManager.Task::(prepare) Task=`45beb897-61c1-4627-8f5a-6baa035bc687`::finished: {'poollist': []}
Thread-18::DEBUG::2014-05-13 11:53:11,606::task::595::TaskManager.Task::(_updateState) Task=`45beb897-61c1-4627-8f5a-6baa035bc687`::moving from state preparing -> state finished
Thread-18::DEBUG::2014-05-13 11:53:11,606::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2014-05-13 11:53:11,606::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18::DEBUG::2014-05-13 11:53:11,606::task::990::TaskManager.Task::(_decref) Task=`45beb897-61c1-4627-8f5a-6baa035bc687`::ref 0 aborting False
Thread-19::DEBUG::2014-05-13 12:09:27,297::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-19::DEBUG::2014-05-13 12:09:27,298::task::595::TaskManager.Task::(_updateState) Task=`81846ffe-6a72-449b-afae-c83ae04a479d`::moving from state init -> state preparing
Thread-19::INFO::2014-05-13 12:09:27,298::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}], options=None)
Thread-19::DEBUG::2014-05-13 12:09:27,303::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 xion2:/export/vm/he1 /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-19::DEBUG::2014-05-13 12:09:27,444::hsm::2318::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/xion2:_export_vm_he1
Thread-19::DEBUG::2014-05-13 12:09:27,445::hsm::2342::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
Thread-19::DEBUG::2014-05-13 12:09:27,445::hsm::2398::Storage.HSM::(connectStorageServer) knownSDs: {}
Thread-19::INFO::2014-05-13 12:09:27,445::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}]}
Thread-19::DEBUG::2014-05-13 12:09:27,446::task::1185::TaskManager.Task::(prepare) Task=`81846ffe-6a72-449b-afae-c83ae04a479d`::finished: {'statuslist': [{'status': 0, 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}]}
Thread-19::DEBUG::2014-05-13 12:09:27,446::task::595::TaskManager.Task::(_updateState) Task=`81846ffe-6a72-449b-afae-c83ae04a479d`::moving from state preparing -> state finished
Thread-19::DEBUG::2014-05-13 12:09:27,446::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2014-05-13 12:09:27,446::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::DEBUG::2014-05-13 12:09:27,446::task::990::TaskManager.Task::(_decref) Task=`81846ffe-6a72-449b-afae-c83ae04a479d`::ref 0 aborting False
Thread-20::DEBUG::2014-05-13 12:09:27,457::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-20::DEBUG::2014-05-13 12:09:27,457::task::595::TaskManager.Task::(_updateState) Task=`fe636408-ff1d-4bc7-a99b-b967e9c23328`::moving from state init -> state preparing
Thread-20::INFO::2014-05-13 12:09:27,457::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000', domainClass=None, storageType=None, remotePath=None, options=None)
Thread-20::DEBUG::2014-05-13 12:09:27,458::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-20::DEBUG::2014-05-13 12:09:27,458::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-20::DEBUG::2014-05-13 12:09:27,458::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-20::DEBUG::2014-05-13 12:09:27,458::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-20::DEBUG::2014-05-13 12:09:27,458::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-20::DEBUG::2014-05-13 12:09:27,458::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-20::DEBUG::2014-05-13 12:09:27,468::misc::772::SamplingMethod::(__call__) Returning last result
Thread-20::DEBUG::2014-05-13 12:09:27,468::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-20::DEBUG::2014-05-13 12:09:27,539::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-20::DEBUG::2014-05-13 12:09:27,539::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,539::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,540::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,540::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,540::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,540::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,540::misc::772::SamplingMethod::(__call__) Returning last result
Thread-20::DEBUG::2014-05-13 12:09:27,540::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-20::DEBUG::2014-05-13 12:09:27,541::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-20::DEBUG::2014-05-13 12:09:27,563::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
Thread-20::DEBUG::2014-05-13 12:09:27,563::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-20::INFO::2014-05-13 12:09:27,645::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': []}
Thread-20::DEBUG::2014-05-13 12:09:27,646::task::1185::TaskManager.Task::(prepare) Task=`fe636408-ff1d-4bc7-a99b-b967e9c23328`::finished: {'domlist': []}
Thread-20::DEBUG::2014-05-13 12:09:27,646::task::595::TaskManager.Task::(_updateState) Task=`fe636408-ff1d-4bc7-a99b-b967e9c23328`::moving from state preparing -> state finished
Thread-20::DEBUG::2014-05-13 12:09:27,646::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-20::DEBUG::2014-05-13 12:09:27,646::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-20::DEBUG::2014-05-13 12:09:27,646::task::990::TaskManager.Task::(_decref) Task=`fe636408-ff1d-4bc7-a99b-b967e9c23328`::ref 0 aborting False
Thread-22::DEBUG::2014-05-13 12:09:27,656::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-22::DEBUG::2014-05-13 12:09:27,656::task::595::TaskManager.Task::(_updateState) Task=`eb88ef76-2184-4b40-b9f0-1fecd3f27fbb`::moving from state init -> state preparing
Thread-22::INFO::2014-05-13 12:09:27,657::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}], options=None)
Thread-22::DEBUG::2014-05-13 12:09:27,657::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-22::DEBUG::2014-05-13 12:09:27,690::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-22::DEBUG::2014-05-13 12:09:27,690::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-22::DEBUG::2014-05-13 12:09:27,690::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-22::DEBUG::2014-05-13 12:09:27,690::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-22::DEBUG::2014-05-13 12:09:27,691::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-22::DEBUG::2014-05-13 12:09:27,691::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-22::DEBUG::2014-05-13 12:09:27,700::misc::772::SamplingMethod::(__call__) Returning last result
Thread-22::DEBUG::2014-05-13 12:09:27,701::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-22::DEBUG::2014-05-13 12:09:27,741::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-22::DEBUG::2014-05-13 12:09:27,741::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,741::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,741::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,742::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,742::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,742::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-22::DEBUG::2014-05-13 12:09:27,742::misc::772::SamplingMethod::(__call__) Returning last result
Thread-22::INFO::2014-05-13 12:09:27,742::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}]}
Thread-22::DEBUG::2014-05-13 12:09:27,742::task::1185::TaskManager.Task::(prepare) Task=`eb88ef76-2184-4b40-b9f0-1fecd3f27fbb`::finished: {'statuslist': [{'status': 0, 'id': 'bb81960b-c378-437d-8b59-192adcb93237'}]}
Thread-22::DEBUG::2014-05-13 12:09:27,742::task::595::TaskManager.Task::(_updateState) Task=`eb88ef76-2184-4b40-b9f0-1fecd3f27fbb`::moving from state preparing -> state finished
Thread-22::DEBUG::2014-05-13 12:09:27,742::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-22::DEBUG::2014-05-13 12:09:27,743::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-22::DEBUG::2014-05-13 12:09:27,743::task::990::TaskManager.Task::(_decref) Task=`eb88ef76-2184-4b40-b9f0-1fecd3f27fbb`::ref 0 aborting False
MainThread::DEBUG::2014-05-13 12:10:34,103::vdsm::55::vds::(sigtermHandler) Received signal 15
MainThread::INFO::2014-05-13 12:10:34,728::vmChannels::183::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2014-05-13 12:10:34,729::momIF::84::MOM::(stop) Shutting down MOM
MainThread::DEBUG::2014-05-13 12:10:34,730::task::595::TaskManager.Task::(_updateState) Task=`035e5707-7427-48ab-af19-c9df2a11c83b`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 12:10:34,730::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2014-05-13 12:10:34,730::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
VM Channels Listener::INFO::2014-05-13 12:10:34,755::vmChannels::178::vds::(run) VM channels listener thread has ended.
MainThread::INFO::2014-05-13 12:10:35,085::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
MainThread::DEBUG::2014-05-13 12:10:35,086::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2014-05-13 12:10:35,086::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2014-05-13 12:10:35,086::task::1185::TaskManager.Task::(prepare) Task=`035e5707-7427-48ab-af19-c9df2a11c83b`::finished: None
MainThread::DEBUG::2014-05-13 12:10:35,086::task::595::TaskManager.Task::(_updateState) Task=`035e5707-7427-48ab-af19-c9df2a11c83b`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 12:10:35,086::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 12:10:35,086::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 12:10:35,086::task::990::TaskManager.Task::(_decref) Task=`035e5707-7427-48ab-af19-c9df2a11c83b`::ref 0 aborting False
MainThread::INFO::2014-05-13 12:10:35,086::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 14 other threads...
MainThread::INFO::2014-05-13 12:10:35,086::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 140067528722176)>
MainThread::INFO::2014-05-13 12:10:35,086::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 140067137910528)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 140067511936768)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140067087554304)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 140067104339712)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 140067112732416)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 140067121125120)>
MainThread::INFO::2014-05-13 12:10:35,087::momIF::84::MOM::(stop) Shutting down MOM
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <MomThread(MOM, started 140066525538048)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-1, started daemon 140067520329472)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <_MainThread(MainThread, started 140067819579200)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 140067129517824)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <GuestManager(GuestManager, started daemon 140066122884864)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 140067486758656)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 140067495151360)>
MainThread::INFO::2014-05-13 12:10:35,087::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 140067503544064)>
MainThread::INFO::2014-05-13 12:10:44,773::vdsm::119::vds::(run) (PID: 5617) I am the actual vdsm 4.14.8.1-0.fc19 xion2.smartcity.net (3.13.11-100.fc19.x86_64)
MainThread::DEBUG::2014-05-13 12:10:44,773::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2014-05-13 12:10:44,773::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2014-05-13 12:10:44,775::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2014-05-13 12:10:45,073::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2014-05-13 12:10:45,077::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2014-05-13 12:10:45,077::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2014-05-13 12:10:45,093::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2014-05-13 12:10:45,093::hsm::448::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2014-05-13 12:10:45,097::hsm::480::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2014-05-13 12:10:45,097::hsm::481::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2014-05-13 12:10:45,097::hsm::483::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2014-05-13 12:10:45,098::hsm::526::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2014-05-13 12:10:45,098::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2014-05-13 12:10:45,099::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2014-05-13 12:10:45,099::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 12:10:45,113::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2014-05-13 12:10:45,113::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 12:10:45,115::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2014-05-13 12:10:45,115::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2014-05-13 12:10:45,124::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 12:10:45,125::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
MainThread::DEBUG::2014-05-13 12:10:45,130::task::595::TaskManager.Task::(_updateState) Task=`0362f634-ba19-48f4-aacb-2228c97b389e`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 12:10:45,130::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1c8ecf8>>)
MainThread::INFO::2014-05-13 12:10:45,130::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2014-05-13 12:10:45,131::task::1185::TaskManager.Task::(prepare) Task=`0362f634-ba19-48f4-aacb-2228c97b389e`::finished: None
MainThread::DEBUG::2014-05-13 12:10:45,131::task::595::TaskManager.Task::(_updateState) Task=`0362f634-ba19-48f4-aacb-2228c97b389e`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 12:10:45,131::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 12:10:45,131::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 12:10:45,131::task::990::TaskManager.Task::(_decref) Task=`0362f634-ba19-48f4-aacb-2228c97b389e`::ref 0 aborting False
MainThread::INFO::2014-05-13 12:10:45,133::momIF::47::MOM::(__init__) Starting up MOM
MainThread::INFO::2014-05-13 12:10:45,136::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2014-05-13 12:10:45,137::vmChannels::170::vds::(run) Starting VM channels listener thread.
clientIFinit::DEBUG::2014-05-13 12:10:45,148::libvirtconnection::145::root::(get) trying to connect libvirt
MainThread::WARNING::2014-05-13 12:10:45,151::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
storageRefresh::DEBUG::2014-05-13 12:10:45,184::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:10:45,188::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,191::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,194::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,198::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,201::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,204::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,207::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 12:10:45,210::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,227::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-05-13 12:10:45,249::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:10:45,250::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,252::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,254::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-05-13 12:10:45,281::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:10:45,282::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,285::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-05-13 12:10:45,300::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:10:45,301::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:10:45,304::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-05-13 12:10:45,319::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:10:45,320::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::WARNING::2014-05-13 12:10:45,321::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
storageRefresh::DEBUG::2014-05-13 12:10:45,321::hsm::392::Storage.HSM::(storageRefresh) HSM is ready
Thread-13::DEBUG::2014-05-13 12:10:45,652::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-13::DEBUG::2014-05-13 12:10:45,673::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-14::DEBUG::2014-05-13 12:10:45,683::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2014-05-13 12:10:45,718::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-14::DEBUG::2014-05-13 12:10:45,728::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2014-05-13 12:10:45,768::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d990cf85cdeb'}], 'FC': []}, 'packages2': {'kernel': {'release': '100.fc19.x86_64', 'buildtime': 1398298257.0, 'version': '3.13.11'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1399473539L, 'version': '4.14.8.1'}, 'qemu-kvm': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz', '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': '4C4C4544-0054-5110-8032-C6C04F445831_1c:3e:84:50:8d:c3', 'lastClientIface': 'lo', 'nics': {'p3p1': {'netmask': '255.255.0.0', 'addr': '172.16.0.58', 'hwaddr': 'b8:ca:3a:79:22:12', 'cfg': {}, 'ipv6addrs': ['fe80::baca:3aff:fe79:2212/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '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,nopl,xtopology,nonstop_tsc,aperfmperf,eagerfpu,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,dtherm,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:d990cf85cdeb', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '1e:72:15:d0:f2:f5', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '24074', 'cpuSpeed': '3842.265', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
Thread-15::DEBUG::2014-05-13 12:57:14,111::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-15::DEBUG::2014-05-13 12:57:14,113::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-17::DEBUG::2014-05-13 12:57:14,186::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-17::DEBUG::2014-05-13 12:57:14,186::task::595::TaskManager.Task::(_updateState) Task=`cbaaca8c-dde4-42f3-a85b-688c6e04cf35`::moving from state init -> state preparing
Thread-17::INFO::2014-05-13 12:57:14,186::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
Thread-17::INFO::2014-05-13 12:57:14,187::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
Thread-17::DEBUG::2014-05-13 12:57:14,187::task::1185::TaskManager.Task::(prepare) Task=`cbaaca8c-dde4-42f3-a85b-688c6e04cf35`::finished: {'poollist': []}
Thread-17::DEBUG::2014-05-13 12:57:14,187::task::595::TaskManager.Task::(_updateState) Task=`cbaaca8c-dde4-42f3-a85b-688c6e04cf35`::moving from state preparing -> state finished
Thread-17::DEBUG::2014-05-13 12:57:14,187::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-17::DEBUG::2014-05-13 12:57:14,187::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-17::DEBUG::2014-05-13 12:57:14,187::task::990::TaskManager.Task::(_decref) Task=`cbaaca8c-dde4-42f3-a85b-688c6e04cf35`::ref 0 aborting False
Thread-18::DEBUG::2014-05-13 12:57:23,616::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-18::DEBUG::2014-05-13 12:57:23,617::task::595::TaskManager.Task::(_updateState) Task=`5a589a01-d3db-44da-8468-12fdacb2ea7c`::moving from state init -> state preparing
Thread-18::INFO::2014-05-13 12:57:23,617::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}], options=None)
Thread-18::DEBUG::2014-05-13 12:57:23,622::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 xion2:/export/vm/he1 /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-18::DEBUG::2014-05-13 12:57:23,758::hsm::2318::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/xion2:_export_vm_he1
Thread-18::DEBUG::2014-05-13 12:57:23,760::hsm::2342::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
Thread-18::DEBUG::2014-05-13 12:57:23,760::hsm::2398::Storage.HSM::(connectStorageServer) knownSDs: {}
Thread-18::INFO::2014-05-13 12:57:23,760::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}]}
Thread-18::DEBUG::2014-05-13 12:57:23,760::task::1185::TaskManager.Task::(prepare) Task=`5a589a01-d3db-44da-8468-12fdacb2ea7c`::finished: {'statuslist': [{'status': 0, 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}]}
Thread-18::DEBUG::2014-05-13 12:57:23,760::task::595::TaskManager.Task::(_updateState) Task=`5a589a01-d3db-44da-8468-12fdacb2ea7c`::moving from state preparing -> state finished
Thread-18::DEBUG::2014-05-13 12:57:23,760::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2014-05-13 12:57:23,760::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18::DEBUG::2014-05-13 12:57:23,760::task::990::TaskManager.Task::(_decref) Task=`5a589a01-d3db-44da-8468-12fdacb2ea7c`::ref 0 aborting False
Thread-19::DEBUG::2014-05-13 12:57:23,771::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-19::DEBUG::2014-05-13 12:57:23,772::task::595::TaskManager.Task::(_updateState) Task=`81c1f6ef-f1c0-4e6b-9a94-0c1fa271069e`::moving from state init -> state preparing
Thread-19::INFO::2014-05-13 12:57:23,772::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000', domainClass=None, storageType=None, remotePath=None, options=None)
Thread-19::DEBUG::2014-05-13 12:57:23,772::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-19::DEBUG::2014-05-13 12:57:23,772::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2014-05-13 12:57:23,772::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-19::DEBUG::2014-05-13 12:57:23,772::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2014-05-13 12:57:23,772::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-19::DEBUG::2014-05-13 12:57:23,773::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-19::DEBUG::2014-05-13 12:57:23,782::misc::772::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2014-05-13 12:57:23,783::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-19::DEBUG::2014-05-13 12:57:23,874::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-19::DEBUG::2014-05-13 12:57:23,874::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,875::misc::772::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2014-05-13 12:57:23,876::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 12:57:23,876::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-19::DEBUG::2014-05-13 12:57:23,898::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
Thread-19::DEBUG::2014-05-13 12:57:23,898::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-19::INFO::2014-05-13 12:57:23,982::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': []}
Thread-19::DEBUG::2014-05-13 12:57:23,983::task::1185::TaskManager.Task::(prepare) Task=`81c1f6ef-f1c0-4e6b-9a94-0c1fa271069e`::finished: {'domlist': []}
Thread-19::DEBUG::2014-05-13 12:57:23,983::task::595::TaskManager.Task::(_updateState) Task=`81c1f6ef-f1c0-4e6b-9a94-0c1fa271069e`::moving from state preparing -> state finished
Thread-19::DEBUG::2014-05-13 12:57:23,983::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2014-05-13 12:57:23,983::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::DEBUG::2014-05-13 12:57:23,983::task::990::TaskManager.Task::(_decref) Task=`81c1f6ef-f1c0-4e6b-9a94-0c1fa271069e`::ref 0 aborting False
Thread-21::DEBUG::2014-05-13 12:57:23,993::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-21::DEBUG::2014-05-13 12:57:23,993::task::595::TaskManager.Task::(_updateState) Task=`f4d33be0-456f-4227-aa8b-2b73b12628dd`::moving from state init -> state preparing
Thread-21::INFO::2014-05-13 12:57:23,993::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}], options=None)
Thread-21::DEBUG::2014-05-13 12:57:23,993::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-21::DEBUG::2014-05-13 12:57:24,019::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-21::DEBUG::2014-05-13 12:57:24,019::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-21::DEBUG::2014-05-13 12:57:24,019::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-21::DEBUG::2014-05-13 12:57:24,019::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-21::DEBUG::2014-05-13 12:57:24,019::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-21::DEBUG::2014-05-13 12:57:24,020::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-21::DEBUG::2014-05-13 12:57:24,029::misc::772::SamplingMethod::(__call__) Returning last result
Thread-21::DEBUG::2014-05-13 12:57:24,029::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-21::DEBUG::2014-05-13 12:57:24,089::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,090::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 12:57:24,091::misc::772::SamplingMethod::(__call__) Returning last result
Thread-21::INFO::2014-05-13 12:57:24,091::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}]}
Thread-21::DEBUG::2014-05-13 12:57:24,091::task::1185::TaskManager.Task::(prepare) Task=`f4d33be0-456f-4227-aa8b-2b73b12628dd`::finished: {'statuslist': [{'status': 0, 'id': 'ce2f9e81-5b6e-4fd8-9109-c55877d36015'}]}
Thread-21::DEBUG::2014-05-13 12:57:24,091::task::595::TaskManager.Task::(_updateState) Task=`f4d33be0-456f-4227-aa8b-2b73b12628dd`::moving from state preparing -> state finished
Thread-21::DEBUG::2014-05-13 12:57:24,091::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-21::DEBUG::2014-05-13 12:57:24,091::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-21::DEBUG::2014-05-13 12:57:24,092::task::990::TaskManager.Task::(_decref) Task=`f4d33be0-456f-4227-aa8b-2b73b12628dd`::ref 0 aborting False
MainThread::DEBUG::2014-05-13 12:58:22,379::vdsm::55::vds::(sigtermHandler) Received signal 15
MainThread::INFO::2014-05-13 12:58:23,055::vmChannels::183::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2014-05-13 12:58:23,056::momIF::84::MOM::(stop) Shutting down MOM
MainThread::DEBUG::2014-05-13 12:58:23,056::task::595::TaskManager.Task::(_updateState) Task=`bd931e9c-dbf1-4a8e-a570-7ac8de1f311a`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 12:58:23,057::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2014-05-13 12:58:23,057::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
VM Channels Listener::INFO::2014-05-13 12:58:23,280::vmChannels::178::vds::(run) VM channels listener thread has ended.
MainThread::INFO::2014-05-13 12:58:23,406::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
MainThread::DEBUG::2014-05-13 12:58:23,406::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2014-05-13 12:58:23,406::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2014-05-13 12:58:23,406::task::1185::TaskManager.Task::(prepare) Task=`bd931e9c-dbf1-4a8e-a570-7ac8de1f311a`::finished: None
MainThread::DEBUG::2014-05-13 12:58:23,407::task::595::TaskManager.Task::(_updateState) Task=`bd931e9c-dbf1-4a8e-a570-7ac8de1f311a`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 12:58:23,407::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 12:58:23,407::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 12:58:23,407::task::990::TaskManager.Task::(_decref) Task=`bd931e9c-dbf1-4a8e-a570-7ac8de1f311a`::ref 0 aborting False
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 14 other threads...
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 140082891319040)>
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140081968969472)>
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <HostMonitor(HostMonitor, started daemon 140081566316288)>
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 140082857748224)>
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 140082874533632)>
MainThread::INFO::2014-05-13 12:58:23,407::momIF::84::MOM::(stop) Shutting down MOM
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <MomThread(MOM, started 140081952184064)>
MainThread::INFO::2014-05-13 12:58:23,407::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 140082497447680)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 140082505840384)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <_MainThread(MainThread, started 140083182176064)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 140082480662272)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-1, started daemon 140082882926336)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 140082489054976)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 140082472269568)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 140082866140928)>
MainThread::INFO::2014-05-13 12:58:23,408::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 140082463876864)>
MainThread::INFO::2014-05-13 12:58:33,746::vdsm::119::vds::(run) (PID: 30592) I am the actual vdsm 4.14.8.1-0.fc19 xion2.smartcity.net (3.13.11-100.fc19.x86_64)
MainThread::DEBUG::2014-05-13 12:58:33,747::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2014-05-13 12:58:33,747::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2014-05-13 12:58:33,748::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2014-05-13 12:58:34,041::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2014-05-13 12:58:34,045::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2014-05-13 12:58:34,045::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2014-05-13 12:58:34,060::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2014-05-13 12:58:34,060::hsm::448::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2014-05-13 12:58:34,064::hsm::480::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2014-05-13 12:58:34,064::hsm::481::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2014-05-13 12:58:34,064::hsm::483::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2014-05-13 12:58:34,065::hsm::526::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2014-05-13 12:58:34,065::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2014-05-13 12:58:34,066::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2014-05-13 12:58:34,066::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 12:58:34,080::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2014-05-13 12:58:34,081::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 12:58:34,082::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2014-05-13 12:58:34,082::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2014-05-13 12:58:34,091::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 12:58:34,091::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
MainThread::DEBUG::2014-05-13 12:58:34,097::task::595::TaskManager.Task::(_updateState) Task=`1f4594c5-e925-46b5-a5d3-93938105bc16`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 12:58:34,097::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1892b48>>)
MainThread::INFO::2014-05-13 12:58:34,097::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2014-05-13 12:58:34,097::task::1185::TaskManager.Task::(prepare) Task=`1f4594c5-e925-46b5-a5d3-93938105bc16`::finished: None
MainThread::DEBUG::2014-05-13 12:58:34,098::task::595::TaskManager.Task::(_updateState) Task=`1f4594c5-e925-46b5-a5d3-93938105bc16`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 12:58:34,098::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 12:58:34,098::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 12:58:34,098::task::990::TaskManager.Task::(_decref) Task=`1f4594c5-e925-46b5-a5d3-93938105bc16`::ref 0 aborting False
MainThread::INFO::2014-05-13 12:58:34,101::momIF::47::MOM::(__init__) Starting up MOM
MainThread::INFO::2014-05-13 12:58:34,103::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2014-05-13 12:58:34,120::vmChannels::170::vds::(run) Starting VM channels listener thread.
clientIFinit::DEBUG::2014-05-13 12:58:34,121::libvirtconnection::145::root::(get) trying to connect libvirt
MainThread::WARNING::2014-05-13 12:58:34,122::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
storageRefresh::DEBUG::2014-05-13 12:58:34,167::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:58:34,170::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,173::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,177::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,182::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,185::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,188::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,191::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 12:58:34,194::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,209::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-05-13 12:58:34,236::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:58:34,238::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,241::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,248::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-05-13 12:58:34,266::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:58:34,267::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,270::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-05-13 12:58:34,284::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:58:34,285::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 12:58:34,288::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-05-13 12:58:34,312::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 12:58:34,313::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::WARNING::2014-05-13 12:58:34,313::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
storageRefresh::DEBUG::2014-05-13 12:58:34,314::hsm::392::Storage.HSM::(storageRefresh) HSM is ready
Thread-13::DEBUG::2014-05-13 12:58:34,622::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-13::DEBUG::2014-05-13 12:58:34,642::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-14::DEBUG::2014-05-13 12:58:34,651::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2014-05-13 12:58:34,687::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-14::DEBUG::2014-05-13 12:58:34,692::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2014-05-13 12:58:34,725::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d990cf85cdeb'}], 'FC': []}, 'packages2': {'kernel': {'release': '100.fc19.x86_64', 'buildtime': 1398298257.0, 'version': '3.13.11'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1399473539L, 'version': '4.14.8.1'}, 'qemu-kvm': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz', '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': '4C4C4544-0054-5110-8032-C6C04F445831_1c:3e:84:50:8d:c3', 'lastClientIface': 'lo', 'nics': {'p3p1': {'netmask': '255.255.0.0', 'addr': '172.16.0.58', 'hwaddr': 'b8:ca:3a:79:22:12', 'cfg': {}, 'ipv6addrs': ['fe80::baca:3aff:fe79:2212/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '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,nopl,xtopology,nonstop_tsc,aperfmperf,eagerfpu,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,dtherm,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:d990cf85cdeb', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '1e:72:15:d0:f2:f5', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '24074', 'cpuSpeed': '3899.906', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
Thread-15::DEBUG::2014-05-13 13:01:03,324::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-15::DEBUG::2014-05-13 13:01:03,326::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-17::DEBUG::2014-05-13 13:01:03,400::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-17::DEBUG::2014-05-13 13:01:03,401::task::595::TaskManager.Task::(_updateState) Task=`d8c9b0f2-4fbf-45c2-a724-cdc7a6c79dae`::moving from state init -> state preparing
Thread-17::INFO::2014-05-13 13:01:03,401::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
Thread-17::INFO::2014-05-13 13:01:03,401::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
Thread-17::DEBUG::2014-05-13 13:01:03,401::task::1185::TaskManager.Task::(prepare) Task=`d8c9b0f2-4fbf-45c2-a724-cdc7a6c79dae`::finished: {'poollist': []}
Thread-17::DEBUG::2014-05-13 13:01:03,401::task::595::TaskManager.Task::(_updateState) Task=`d8c9b0f2-4fbf-45c2-a724-cdc7a6c79dae`::moving from state preparing -> state finished
Thread-17::DEBUG::2014-05-13 13:01:03,401::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-17::DEBUG::2014-05-13 13:01:03,401::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-17::DEBUG::2014-05-13 13:01:03,401::task::990::TaskManager.Task::(_decref) Task=`d8c9b0f2-4fbf-45c2-a724-cdc7a6c79dae`::ref 0 aborting False
Thread-18::DEBUG::2014-05-13 13:01:12,928::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-18::DEBUG::2014-05-13 13:01:12,928::task::595::TaskManager.Task::(_updateState) Task=`4360fbad-9415-492b-985b-15417a20fdf3`::moving from state init -> state preparing
Thread-18::INFO::2014-05-13 13:01:12,929::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '22be046d-fded-4799-995d-b0c913646f50'}], options=None)
Thread-18::DEBUG::2014-05-13 13:01:12,935::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 xion2:/export/vm/he1 /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-18::DEBUG::2014-05-13 13:01:13,076::hsm::2318::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/xion2:_export_vm_he1
Thread-18::DEBUG::2014-05-13 13:01:13,077::hsm::2342::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
Thread-18::DEBUG::2014-05-13 13:01:13,077::hsm::2398::Storage.HSM::(connectStorageServer) knownSDs: {}
Thread-18::INFO::2014-05-13 13:01:13,077::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '22be046d-fded-4799-995d-b0c913646f50'}]}
Thread-18::DEBUG::2014-05-13 13:01:13,078::task::1185::TaskManager.Task::(prepare) Task=`4360fbad-9415-492b-985b-15417a20fdf3`::finished: {'statuslist': [{'status': 0, 'id': '22be046d-fded-4799-995d-b0c913646f50'}]}
Thread-18::DEBUG::2014-05-13 13:01:13,078::task::595::TaskManager.Task::(_updateState) Task=`4360fbad-9415-492b-985b-15417a20fdf3`::moving from state preparing -> state finished
Thread-18::DEBUG::2014-05-13 13:01:13,078::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-18::DEBUG::2014-05-13 13:01:13,078::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-18::DEBUG::2014-05-13 13:01:13,078::task::990::TaskManager.Task::(_decref) Task=`4360fbad-9415-492b-985b-15417a20fdf3`::ref 0 aborting False
Thread-19::DEBUG::2014-05-13 13:01:13,087::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-19::DEBUG::2014-05-13 13:01:13,088::task::595::TaskManager.Task::(_updateState) Task=`c280bde7-4c42-44a7-bc3a-88d1a471b5fd`::moving from state init -> state preparing
Thread-19::INFO::2014-05-13 13:01:13,088::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000', domainClass=None, storageType=None, remotePath=None, options=None)
Thread-19::DEBUG::2014-05-13 13:01:13,088::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-19::DEBUG::2014-05-13 13:01:13,088::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2014-05-13 13:01:13,088::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-19::DEBUG::2014-05-13 13:01:13,088::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-19::DEBUG::2014-05-13 13:01:13,089::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-19::DEBUG::2014-05-13 13:01:13,089::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-19::DEBUG::2014-05-13 13:01:13,099::misc::772::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2014-05-13 13:01:13,100::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-19::DEBUG::2014-05-13 13:01:13,160::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-19::DEBUG::2014-05-13 13:01:13,160::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,160::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,160::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,160::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,161::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,161::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,161::misc::772::SamplingMethod::(__call__) Returning last result
Thread-19::DEBUG::2014-05-13 13:01:13,161::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-19::DEBUG::2014-05-13 13:01:13,162::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-19::DEBUG::2014-05-13 13:01:13,184::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
Thread-19::DEBUG::2014-05-13 13:01:13,184::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-19::INFO::2014-05-13 13:01:13,266::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': []}
Thread-19::DEBUG::2014-05-13 13:01:13,267::task::1185::TaskManager.Task::(prepare) Task=`c280bde7-4c42-44a7-bc3a-88d1a471b5fd`::finished: {'domlist': []}
Thread-19::DEBUG::2014-05-13 13:01:13,267::task::595::TaskManager.Task::(_updateState) Task=`c280bde7-4c42-44a7-bc3a-88d1a471b5fd`::moving from state preparing -> state finished
Thread-19::DEBUG::2014-05-13 13:01:13,267::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-19::DEBUG::2014-05-13 13:01:13,267::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-19::DEBUG::2014-05-13 13:01:13,267::task::990::TaskManager.Task::(_decref) Task=`c280bde7-4c42-44a7-bc3a-88d1a471b5fd`::ref 0 aborting False
Thread-21::DEBUG::2014-05-13 13:01:13,277::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
Thread-21::DEBUG::2014-05-13 13:01:13,277::task::595::TaskManager.Task::(_updateState) Task=`d4ee3c8a-8e65-410d-8941-e9feeacdf2bf`::moving from state init -> state preparing
Thread-21::INFO::2014-05-13 13:01:13,278::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'xion2:/export/vm/he1', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '22be046d-fded-4799-995d-b0c913646f50'}], options=None)
Thread-21::DEBUG::2014-05-13 13:01:13,278::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/umount -f -l /rhev/data-center/mnt/xion2:_export_vm_he1' (cwd None)
Thread-21::DEBUG::2014-05-13 13:01:13,304::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-21::DEBUG::2014-05-13 13:01:13,304::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-21::DEBUG::2014-05-13 13:01:13,304::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-21::DEBUG::2014-05-13 13:01:13,304::misc::764::SamplingMethod::(__call__) Got in to sampling method
Thread-21::DEBUG::2014-05-13 13:01:13,304::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
Thread-21::DEBUG::2014-05-13 13:01:13,304::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-21::DEBUG::2014-05-13 13:01:13,313::misc::772::SamplingMethod::(__call__) Returning last result
Thread-21::DEBUG::2014-05-13 13:01:13,314::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
Thread-21::DEBUG::2014-05-13 13:01:13,366::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-21::DEBUG::2014-05-13 13:01:13,367::misc::772::SamplingMethod::(__call__) Returning last result
Thread-21::INFO::2014-05-13 13:01:13,368::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '22be046d-fded-4799-995d-b0c913646f50'}]}
Thread-21::DEBUG::2014-05-13 13:01:13,368::task::1185::TaskManager.Task::(prepare) Task=`d4ee3c8a-8e65-410d-8941-e9feeacdf2bf`::finished: {'statuslist': [{'status': 0, 'id': '22be046d-fded-4799-995d-b0c913646f50'}]}
Thread-21::DEBUG::2014-05-13 13:01:13,368::task::595::TaskManager.Task::(_updateState) Task=`d4ee3c8a-8e65-410d-8941-e9feeacdf2bf`::moving from state preparing -> state finished
Thread-21::DEBUG::2014-05-13 13:01:13,368::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-21::DEBUG::2014-05-13 13:01:13,368::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-21::DEBUG::2014-05-13 13:01:13,368::task::990::TaskManager.Task::(_decref) Task=`d4ee3c8a-8e65-410d-8941-e9feeacdf2bf`::ref 0 aborting False
MainThread::DEBUG::2014-05-13 13:02:02,883::vdsm::55::vds::(sigtermHandler) Received signal 15
MainThread::INFO::2014-05-13 13:02:03,332::vmChannels::183::vds::(stop) VM channels listener was stopped.
MainThread::INFO::2014-05-13 13:02:03,332::momIF::84::MOM::(stop) Shutting down MOM
MainThread::DEBUG::2014-05-13 13:02:03,333::task::595::TaskManager.Task::(_updateState) Task=`a7369372-c3c8-46f0-8d9c-ffa0709be77f`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 13:02:03,333::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
Thread-11::DEBUG::2014-05-13 13:02:03,333::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
VM Channels Listener::INFO::2014-05-13 13:02:03,350::vmChannels::178::vds::(run) VM channels listener thread has ended.
MainThread::INFO::2014-05-13 13:02:03,672::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
MainThread::DEBUG::2014-05-13 13:02:03,673::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
MainThread::INFO::2014-05-13 13:02:03,673::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
MainThread::DEBUG::2014-05-13 13:02:03,673::task::1185::TaskManager.Task::(prepare) Task=`a7369372-c3c8-46f0-8d9c-ffa0709be77f`::finished: None
MainThread::DEBUG::2014-05-13 13:02:03,673::task::595::TaskManager.Task::(_updateState) Task=`a7369372-c3c8-46f0-8d9c-ffa0709be77f`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 13:02:03,673::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 13:02:03,673::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 13:02:03,673::task::990::TaskManager.Task::(_decref) Task=`a7369372-c3c8-46f0-8d9c-ffa0709be77f`::ref 0 aborting False
MainThread::INFO::2014-05-13 13:02:03,673::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 15 other threads...
MainThread::INFO::2014-05-13 13:02:03,673::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 140426493179648)>
MainThread::INFO::2014-05-13 13:02:03,673::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 140426103224064)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140426052867840)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 140426069653248)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 140426078045952)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 140426094831360)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 140426468001536)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 140426476394240)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-1, started daemon 140426484786944)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <HostMonitor(HostMonitor, started daemon 140425096591104)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <_MainThread(MainThread, started 140426609944384)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 140426459608832)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 140426086438656)>
MainThread::INFO::2014-05-13 13:02:03,674::momIF::84::MOM::(stop) Shutting down MOM
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <MomThread(MOM, started 140425490851584)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 140426451216128)>
MainThread::INFO::2014-05-13 13:02:03,674::vdsm::129::vds::(run) <GuestManager(GuestManager, started daemon 140425088198400)>
MainThread::INFO::2014-05-13 13:02:06,167::vdsm::119::vds::(run) (PID: 31370) I am the actual vdsm 4.14.8.1-0.fc19 xion2.smartcity.net (3.13.11-100.fc19.x86_64)
MainThread::DEBUG::2014-05-13 13:02:06,168::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
MainThread::DEBUG::2014-05-13 13:02:06,168::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
MainThread::WARNING::2014-05-13 13:02:06,169::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
MainThread::DEBUG::2014-05-13 13:02:06,465::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
MainThread::DEBUG::2014-05-13 13:02:06,470::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
MainThread::DEBUG::2014-05-13 13:02:06,470::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
MainThread::DEBUG::2014-05-13 13:02:06,485::hsm::424::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
MainThread::DEBUG::2014-05-13 13:02:06,485::hsm::448::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
MainThread::DEBUG::2014-05-13 13:02:06,489::hsm::480::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
MainThread::DEBUG::2014-05-13 13:02:06,489::hsm::481::Storage.HSM::(__cleanStorageRepository) Mount list: []
MainThread::DEBUG::2014-05-13 13:02:06,489::hsm::483::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
MainThread::DEBUG::2014-05-13 13:02:06,490::hsm::526::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
storageRefresh::DEBUG::2014-05-13 13:02:06,490::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
MainThread::INFO::2014-05-13 13:02:06,491::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
storageRefresh::DEBUG::2014-05-13 13:02:06,496::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 13:02:06,505::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
storageRefresh::DEBUG::2014-05-13 13:02:06,505::misc::764::SamplingMethod::(__call__) Got in to sampling method
storageRefresh::DEBUG::2014-05-13 13:02:06,506::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
storageRefresh::DEBUG::2014-05-13 13:02:06,507::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
storageRefresh::DEBUG::2014-05-13 13:02:06,515::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 13:02:06,515::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
MainThread::DEBUG::2014-05-13 13:02:06,520::task::595::TaskManager.Task::(_updateState) Task=`e83eb012-d5b5-4543-94fe-6d12b823765d`::moving from state init -> state preparing
MainThread::INFO::2014-05-13 13:02:06,520::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x2aeed88>>)
MainThread::INFO::2014-05-13 13:02:06,520::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
MainThread::DEBUG::2014-05-13 13:02:06,521::task::1185::TaskManager.Task::(prepare) Task=`e83eb012-d5b5-4543-94fe-6d12b823765d`::finished: None
MainThread::DEBUG::2014-05-13 13:02:06,521::task::595::TaskManager.Task::(_updateState) Task=`e83eb012-d5b5-4543-94fe-6d12b823765d`::moving from state preparing -> state finished
MainThread::DEBUG::2014-05-13 13:02:06,521::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
MainThread::DEBUG::2014-05-13 13:02:06,521::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
MainThread::DEBUG::2014-05-13 13:02:06,521::task::990::TaskManager.Task::(_decref) Task=`e83eb012-d5b5-4543-94fe-6d12b823765d`::ref 0 aborting False
MainThread::INFO::2014-05-13 13:02:06,523::momIF::47::MOM::(__init__) Starting up MOM
MainThread::INFO::2014-05-13 13:02:06,525::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
VM Channels Listener::INFO::2014-05-13 13:02:06,536::vmChannels::170::vds::(run) Starting VM channels listener thread.
clientIFinit::DEBUG::2014-05-13 13:02:06,536::libvirtconnection::145::root::(get) trying to connect libvirt
MainThread::WARNING::2014-05-13 13:02:06,539::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
storageRefresh::DEBUG::2014-05-13 13:02:06,601::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
storageRefresh::DEBUG::2014-05-13 13:02:06,604::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,606::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,609::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,612::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,615::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,618::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,619::misc::772::SamplingMethod::(__call__) Returning last result
storageRefresh::DEBUG::2014-05-13 13:02:06,620::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,625::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-05-13 13:02:06,645::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 13:02:06,646::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,647::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,649::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-05-13 13:02:06,672::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 13:02:06,673::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,675::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-05-13 13:02:06,691::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 13:02:06,692::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
storageRefresh::DEBUG::2014-05-13 13:02:06,695::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-05-13 13:02:06,711::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ' WARNING: lvmetad is running but disabled. Restart lvmetad before enabling it!\n No volume groups found\n'; <rc> = 0
storageRefresh::DEBUG::2014-05-13 13:02:06,711::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
storageRefresh::WARNING::2014-05-13 13:02:06,712::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
storageRefresh::DEBUG::2014-05-13 13:02:06,713::hsm::392::Storage.HSM::(storageRefresh) HSM is ready
Thread-13::DEBUG::2014-05-13 13:02:07,042::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
Thread-13::DEBUG::2014-05-13 13:02:07,062::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'XPS 8500', 'systemSerialNumber': 'FTQ2DX1', 'systemFamily': 'To be filled by O.E.M.', 'systemVersion': '', 'systemUUID': '4C4C4544-0054-5110-8032-C6C04F445831', 'systemManufacturer': 'Dell Inc.'}}
Thread-14::DEBUG::2014-05-13 13:02:07,071::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getCapabilities with () {}
Thread-14::DEBUG::2014-05-13 13:02:07,107::utils::642::root::(execCmd) '/sbin/ip route show to 0.0.0.0/0 table all' (cwd None)
Thread-14::DEBUG::2014-05-13 13:02:07,110::utils::662::root::(execCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-14::DEBUG::2014-05-13 13:02:07,143::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.1994-05.com.redhat:d990cf85cdeb'}], 'FC': []}, 'packages2': {'kernel': {'release': '100.fc19.x86_64', 'buildtime': 1398298257.0, 'version': '3.13.11'}, 'spice-server': {'release': '3.fc19', 'buildtime': 1383130020L, 'version': '0.12.4'}, 'vdsm': {'release': '0.fc19', 'buildtime': 1399473539L, 'version': '4.14.8.1'}, 'qemu-kvm': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'libvirt': {'release': '1.fc19', 'buildtime': 1387094943L, 'version': '1.1.3.2'}, 'qemu-img': {'release': '15.fc19', 'buildtime': 1387388596L, 'version': '1.4.2'}, 'mom': {'release': '1.fc19', 'buildtime': 1391183561L, 'version': '0.4.0'}}, 'cpuModel': 'Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz', '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': '4C4C4544-0054-5110-8032-C6C04F445831_1c:3e:84:50:8d:c3', 'lastClientIface': 'lo', 'nics': {'p3p1': {'netmask': '255.255.0.0', 'addr': '172.16.0.58', 'hwaddr': 'b8:ca:3a:79:22:12', 'cfg': {}, 'ipv6addrs': ['fe80::baca:3aff:fe79:2212/64'], 'speed': 1000, 'mtu': '1500'}}, 'software_revision': '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,nopl,xtopology,nonstop_tsc,aperfmperf,eagerfpu,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,dtherm,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:d990cf85cdeb', 'netConfigDirty': 'False', 'supportedENGINEs': ['3.0', '3.1', '3.2', '3.3', '3.4'], 'reservedMem': '321', 'bondings': {'bond0': {'netmask': '', 'addr': '', 'slaves': [], 'hwaddr': '1e:72:15:d0:f2:f5', 'cfg': {}, 'ipv6addrs': [], 'mtu': '1500'}}, 'software_version': '4.14', 'memSize': '24074', 'cpuSpeed': '3870.421', 'version_name': 'Snow Man', 'vlans': {}, 'cpuCores': '4', 'kvmEnabled': 'true', 'guestOverhead': '65', 'management_ip': '0.0.0.0', 'cpuThreads': '8', 'emulatedMachines': [u'pc', u'q35', u'isapc', u'pc-0.10', u'pc-0.11', u'pc-0.12', u'pc-0.13', u'pc-0.14', u'pc-0.15', u'pc-1.0', u'pc-1.1', u'pc-1.2', u'pc-1.3', u'none'], 'rngSources': ['random'], 'operatingSystem': {'release': '8', 'version': '19', 'name': 'Fedora'}, 'lastClient': '127.0.0.1'}}
More information about the Users
mailing list