[Users] VDSM ERROR

Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs: ---- MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0 MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt' MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)> ---- ovirtmgmt is up and running: -bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0
<> Nathan Stratton nathan at robotics.net http://www.robotics.net

Is there a way to manually test and debug VDSM?
<> Nathan Stratton nathan at robotics.net http://www.robotics.net
On Thu, 21 Jun 2012, Nathan Stratton wrote:
Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs:
----
MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0 MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt'
MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)>
----
ovirtmgmt is up and running:
-bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0
<> Nathan Stratton nathan at robotics.net http://www.robotics.net
Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users

On Thu, Jun 21, 2012 at 12:15:25PM -0500, Nathan Stratton wrote:
Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs:
----
MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0 MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt'
MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)>
----
ovirtmgmt is up and running:
-bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0
Which version of vdsm is installed on your host? What does `rpm -V vdsm` say?
File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ])
was removed long ago. I suspect that you are experiencing the pains of f17's ifconfig changed output Dan.

Hi Nathan, On 06/21/2012 01:15 PM, Nathan Stratton wrote:
Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs:
----
MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0
4.9-0? Looks like a previous version of vdsm which we had a network error. Can you please try 4.10.0 ?
MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt'
MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)>
----
ovirtmgmt is up and running:
-bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0
<> Nathan Stratton nathan at robotics.net http://www.robotics.net
Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
-- Cheers Douglas

Thanks! That was it, now I think I have some issue with sudo or someting. If I run vdsm as root it connects to the engine and the host comes up, but if it is run normally I get: MainThread::INFO::2012-06-22 15:46:50,424::vdsm::70::vds::(run) I am the actual vdsm 4.10-1 MainThread::DEBUG::2012-06-22 15:46:50,675::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage' MainThread::DEBUG::2012-06-22 15:46:50,675::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0 MainThread::DEBUG::2012-06-22 15:46:50,690::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/kill -9 2106' (cwd None) MainThread::DEBUG::2012-06-22 15:46:50,696::supervdsm::103::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm Permission denied MainThread::DEBUG::2012-06-22 15:46:50,697::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm MainThread::DEBUG::2012-06-22 15:46:50,697::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 5b882e55-ee35-4daa-86ab-be408d99e8b3 3032' (cwd None) MainThread::ERROR::2012-06-22 15:46:50,702::clientIF::210::vds::(_initIRS) Error initializing IRS Traceback (most recent call last): File "/usr/share/vdsm/clientIF.py", line 208, in _initIRS self.irs = Dispatcher(HSM()) File "/usr/share/vdsm/storage/hsm.py", line 296, in __init__ if not multipath.isEnabled(): File "/usr/share/vdsm/storage/multipath.py", line 85, in isEnabled svdsm = supervdsm.getProxy() File "/usr/share/vdsm/supervdsm.py", line 135, in getProxy _g_singletonSupervdsmInstance = SuperVdsmProxy() File "/usr/share/vdsm/supervdsm.py", line 82, in __init__ self._restartSupervdsm() File "/usr/share/vdsm/supervdsm.py", line 123, in _restartSupervdsm self._launchSupervdsm() File "/usr/share/vdsm/supervdsm.py", line 94, in _launchSupervdsm misc.execCmd(superVdsmCmd, sync=False, sudo=True) File "/usr/share/vdsm/storage/misc.py", line 199, in execCmd p = BetterPopen(command, close_fds=True, cwd=cwd, env=env) File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 46, in __init__ stderr=PIPE) File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__ errread, errwrite) File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 60, in _execute_child cwd, env) OSError: Permission denied MainThread::DEBUG::2012-06-22 15:46:50,712::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None) MainThread::DEBUG::2012-06-22 15:46:50,725::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 MainThread::INFO::2012-06-22 15:46:50,726::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds. VM Channels Listener::INFO::2012-06-22 15:46:50,728::vmChannels::127::vds::(run) Starting VM channels listener thread. MainThread::ERROR::2012-06-22 15:46:50,731::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed. MainThread::INFO::2012-06-22 15:55:12,339::vmChannels::135::vds::(stop) VM channels listener was stopped. MainThread::INFO::2012-06-22 15:55:12,339::vdsm::75::vds::(run) VDSM main thread ended. Waiting for 15 other threads... MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <_MainThread(MainThread, started 140294687758144)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <Thread(libvirtEventLoop, started daemon 140294603454208)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-8, started daemon 140293965870848)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-5, started daemon 140294469170944)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-4, started daemon 140294477563648)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-10, started daemon 140293949085440)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-3, started daemon 140294485956352)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <Thread(Thread-11, started daemon 140293940692736)> MainThread::INFO::2012-06-22 15:55:12,340::vdsm::78::vds::(run) <WorkerThread(Thread-9, started daemon 140293957478144)> MainThread::INFO::2012-06-22 15:55:12,341::vmChannels::135::vds::(stop) VM channels listener was stopped. MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <Listener(VM Channels Listener, started daemon 140293428999936)> MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <WorkerThread(Thread-1, started daemon 140294502741760)> MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <KsmMonitorThread(KsmMonitor, started daemon 140293923907328)> MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <WorkerThread(Thread-6, started daemon 140294460778240)> MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <WorkerThread(Thread-7, started daemon 140294452385536)> MainThread::INFO::2012-06-22 15:55:12,341::vdsm::78::vds::(run) <WorkerThread(Thread-2, started daemon 140294494349056)> MainThread::INFO::2012-06-22 15:55:19,304::vdsm::70::vds::(run) I am the actual vdsm 4.10-1 MainThread::DEBUG::2012-06-22 15:55:19,557::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace 'Storage' MainThread::DEBUG::2012-06-22 15:55:19,557::threadPool::45::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0 MainThread::DEBUG::2012-06-22 15:55:19,573::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/kill -9 2106' (cwd None) MainThread::DEBUG::2012-06-22 15:55:19,578::supervdsm::103::SuperVdsmProxy::(_killSupervdsm) Could not kill old Super Vdsm Permission denied MainThread::DEBUG::2012-06-22 15:55:19,579::supervdsm::91::SuperVdsmProxy::(_launchSupervdsm) Launching Super Vdsm MainThread::DEBUG::2012-06-22 15:55:19,580::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /usr/bin/python /usr/share/vdsm/supervdsmServer.py 8fc32c0c-f502-4d3c-9de0-fc1bf2ba53cd 3485' (cwd None) MainThread::ERROR::2012-06-22 15:55:19,584::clientIF::210::vds::(_initIRS) Error initializing IRS Traceback (most recent call last): File "/usr/share/vdsm/clientIF.py", line 208, in _initIRS self.irs = Dispatcher(HSM()) File "/usr/share/vdsm/storage/hsm.py", line 296, in __init__ if not multipath.isEnabled(): File "/usr/share/vdsm/storage/multipath.py", line 85, in isEnabled svdsm = supervdsm.getProxy() File "/usr/share/vdsm/supervdsm.py", line 135, in getProxy _g_singletonSupervdsmInstance = SuperVdsmProxy() File "/usr/share/vdsm/supervdsm.py", line 82, in __init__ self._restartSupervdsm() File "/usr/share/vdsm/supervdsm.py", line 123, in _restartSupervdsm self._launchSupervdsm() File "/usr/share/vdsm/supervdsm.py", line 94, in _launchSupervdsm misc.execCmd(superVdsmCmd, sync=False, sudo=True) File "/usr/share/vdsm/storage/misc.py", line 199, in execCmd p = BetterPopen(command, close_fds=True, cwd=cwd, env=env) File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 46, in __init__ stderr=PIPE) File "/usr/lib64/python2.7/subprocess.py", line 679, in __init__ errread, errwrite) File "/usr/lib/python2.7/site-packages/vdsm/betterPopen/__init__.py", line 60, in _execute_child cwd, env) OSError: Permission denied MainThread::DEBUG::2012-06-22 15:55:19,594::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/pgrep -xf ksmd' (cwd None) MainThread::DEBUG::2012-06-22 15:55:19,606::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0 MainThread::INFO::2012-06-22 15:55:19,607::vmChannels::139::vds::(settimeout) Setting channels' timeout to 30 seconds. VM Channels Listener::INFO::2012-06-22 15:55:19,608::vmChannels::127::vds::(run) Starting VM channels listener thread. MainThread::ERROR::2012-06-22 15:55:19,612::clientIF::151::vds::(_prepareBindings) Unable to load the rest server module. Please make sure it is installed.
<> Nathan Stratton nathan at robotics.net http://www.robotics.net
On Fri, 22 Jun 2012, Douglas Landgraf wrote:
Hi Nathan,
On 06/21/2012 01:15 PM, Nathan Stratton wrote:
Fedora 17 RPMs, hosts complets install and reboots, but never connects back to engine. I just see thousands of the following in the logs:
----
MainThread::INFO::2012-06-21 13:07:26,304::vdsm::71::vds::(run) I am the actual vdsm 4.9-0
4.9-0? Looks like a previous version of vdsm which we had a network error. Can you please try 4.10.0 ?
MainThread::ERROR::2012-06-21 13:07:26,656::vdsm::74::vds::(run) Traceback (most recent call last): File "/usr/share/vdsm/vdsm", line 72, in run serve_clients(log) File "/usr/share/vdsm/vdsm", line 40, in serve_clients cif = clientIF.clientIF(log) File "/usr/share/vdsm/clientIF.py", line 115, in __init__ self._createLibvirtNetworks() File "/usr/share/vdsm/clientIF.py", line 152, in _createLibvirtNetworks nf = netinfo.NetInfo() File "/usr/share/vdsm/netinfo.py", line 268, in __init__ _netinfo = get() File "/usr/share/vdsm/netinfo.py", line 215, in get for bridge in bridges() ]) KeyError: 'ovirtmgmt'
MainThread::INFO::2012-06-21 13:07:26,657::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads... MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <_MainThread(MainThread, started 140487047427904)> MainThread::INFO::2012-06-21 13:07:26,657::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140486974248704)>
----
ovirtmgmt is up and running:
-bash-4.2# brctl show bridge name bridge id STP enabled interfaces ovirtmgmt 8000.a0369f0a15f8 no bond0
<> Nathan Stratton nathan at robotics.net http://www.robotics.net
Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
-- Cheers Douglas

On Fri, Jun 22, 2012 at 02:57:40PM -0500, Nathan Stratton wrote:
Thanks! That was it, now I think I have some issue with sudo or someting. If I run vdsm as root
Please refrain from doing that. It make vdsm create all sort of files owned by root (vdsm.log, /var/run/vdsm/vdsm.pid, probably others) which a future non-root vdsm process would find hard to override. I suspect that this is your problem now. Try running vdsm from the commandline (as vdsm user!) for hints where startup fails.
it connects to the engine and the host comes up, but if it is run normally I get:
MainThread::INFO::2012-06-22 15:46:50,424::vdsm::70::vds::(run) I am the actual vdsm 4.10-1
participants (3)
-
Dan Kenigsberg
-
Douglas Landgraf
-
Nathan Stratton