[Users] host deploy and after reboot not responsive

[Dan Kenigsberg]

On Wed, Jan 16, 2013 at 01:19:47AM +0100, Gianluca Cecchi wrote:
> On Wed, Jan 16, 2013 at 12:08 AM, Dan Kenigsberg wrote:
> 
> > My question regarded a simple node-only reboot. I wonder if vdsm fails
> > to start ALWAYS, or that this is an even more complex glitch.
> >
> 
> Just done another reboot and the same problem. It seems vdsmd doesn't start
> at all
> 
> [root at f18ovn03 ~]# sudo systemctl status vdsmd.service
> vdsmd.service - Virtual Desktop Server Manager
>   Loaded: loaded (/usr/lib/systemd/system/vdsmd.service; enabled)
>   Active: inactive (dead)
>   CGroup: name=systemd:/system/vdsmd.service
> 
> Under /var/log/vdsm I see vdsm.log with timestamp of when I stopped the
> system:
> MainThread::INFO::2013-01-16 00:45:57,716::vdsm::95::vds::(run) VDSM main
> thread ended. Waiting for 16 other threads...
> MainThread::INFO::2013-01-16 00:45:57,716::vdsm::99::vds::(run)
> <Thread(libvirtEventLoop, started daemon 140084926744320)>
> MainThread::INFO::2013-01-16 00:45:57,716::vdsm::99::vds::(run)
> <WorkerThread(Thread-5, started daemon 140084753970944)>
> MainThread::INFO::2013-01-16 00:45:57,716::vdsm::99::vds::(run)
> <HostMonitor(HostMonitor, started daemon 140083713799936)>
> MainThread::INFO::2013-01-16 00:45:57,716::vdsm::99::vds::(run)
> <WorkerThread(Thread-7, started daemon 140084737185536)>
> MainThread::INFO::2013-01-16 00:45:57,717::momIF::65::MOM::(stop) Shutting
> down MOM
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <MomThread(MOM, started 140084200314624)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-4, started daemon 140084762363648)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-10, started daemon 140084233885440)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-9, started daemon 140084242278144)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-1, started daemon 140084787541760)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-3, started daemon 140084770756352)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <WorkerThread(Thread-8, started daemon 140084250670848)>
> MainThread::INFO::2013-01-16 00:45:57,717::vdsm::99::vds::(run)
> <_MainThread(MainThread, started 140085026416448)>
> MainThread::INFO::2013-01-16 00:45:57,718::vdsm::99::vds::(run)
> <GuestManager(GuestManager, started daemon 140083688621824)>
> MainThread::INFO::2013-01-16 00:45:57,718::vdsm::99::vds::(run)
> <PolicyEngine(PolicyEngine, started daemon 140083680229120)>
> MainThread::INFO::2013-01-16 00:45:57,718::vdsm::99::vds::(run)
> <WorkerThread(Thread-2, started daemon 140084779149056)>
> MainThread::INFO::2013-01-16 00:45:57,718::vdsm::99::vds::(run)
> <WorkerThread(Thread-6, started daemon 140084745578240)>
> MainThread::INFO::2013-01-16 00:45:57,718::vmChannels::136::vds::(stop) VM
> channels listener was stopped.
> MainThread::INFO::2013-01-16 00:45:57,718::vdsm::99::vds::(run)
> <Listener(VM Channels Listener, started daemon 140083705407232)>
> 
> If then I manually start it
> root at f18ovn03 vdsm]# systemctl start vdsmd.service
> [root at f18ovn03 vdsm]# echo $?
> 0
> [root at f18ovn03 vdsm]# systemctl status vdsmd.service
> vdsmd.service - Virtual Desktop Server Manager
>   Loaded: loaded (/usr/lib/systemd/system/vdsmd.service; enabled)
>   Active: active (running) since Wed, 2013-01-16 01:09:44 CET; 10s ago
>  Process: 2483 ExecStart=/lib/systemd/systemd-vdsmd start (code=exited,
> status=0/SUCCESS)
> Main PID: 2770 (respawn)
>   CGroup: name=systemd:/system/vdsmd.service
>   ├ 2770 /bin/bash -e /usr/share/vdsm/respawn --minlifetime 10 --daemon
> --masterpid /var/run/vdsm/respawn.p...
>   ├ 2773 /usr/bin/python /usr/share/vdsm/vdsm
>   ├ 2791 /usr/bin/sudo -n /usr/bin/python
> /usr/share/vdsm/supervdsmServer.py 75cc5638-f5c7-4431-bcbe-4a0cd8...
>   └ 2792 /usr/bin/python /usr/share/vdsm/supervdsmServer.py
> 75cc5638-f5c7-4431-bcbe-4a0cd817a0e4 2773 /var/...
> 
> Jan 16 01:09:44 f18ovn03.ceda.polimi.it systemd-vdsmd[2483]: [27B blob data]
> Jan 16 01:09:44 f18ovn03.ceda.polimi.it systemd[1]: Started Virtual Desktop
> Server Manager.
> Jan 16 01:09:45 f18ovn03.ceda.polimi.it python[2773]: DIGEST-MD5 client
> step 2
> Jan 16 01:09:45 f18ovn03.ceda.polimi.it python[2773]: DIGEST-MD5 client
> step 2
> Jan 16 01:09:45 f18ovn03.ceda.polimi.it python[2773]: DIGEST-MD5 client
> step 3
> Jan 16 01:09:45 f18ovn03.ceda.polimi.it vdsm[2773]: vdsm fileUtils WARNING
> Dir /rhev/data-center/mnt already exists
> Jan 16 01:09:48 f18ovn03.ceda.polimi.it vdsm[2773]: vdsm Storage.LVM
> WARNING lvm pvs failed: 5 ['  NQRb0Q-3C0k-3RRo-1LZZ...T01']
> Jan 16 01:09:48 f18ovn03.ceda.polimi.it vdsm[2773]: vdsm Storage.LVM
> WARNING lvm vgs failed: 5 ['  x3XSZx-avUC-0NNI-w5K4...T01']
> Jan 16 01:09:48 f18ovn03.ceda.polimi.it vdsm[2773]: vdsm vds WARNING Unable
> to load the json rpc server module. Please m...lled.
> Jan 16 01:09:51 f18ovn03.ceda.polimi.it vdsm[2773]: vdsm fileUtils WARNING
> Dir /rhev/data-center/hsm-tasks already exists
> 
> Tried also to run anable again
> systemctl enable vdsmd.service
> and reboot but same behaviour.
> In notice that the same is true for ntpd service, configured as enabled but
> not started.
> When I manually start vdsmd, also ntpd starts, as it is in the required
> chain for vdsmd... strange
> Can it depend on delay on network/bridges initialization?

It might be it - but there must be more clues in the logs. I'd like to
see both vdsm.log and /var/log/message of boottime. journalctl may have
stories to tell, too.

If you can manually zap ntpd off of vdsmd.service and reboot, it could
eliminate one usual suspect. Would you?

> 
> when the service has not manually started by me yet, the output of
> systemctl show vdsmd.service
> 
> 
> Id=vdsmd.service
> Names=vdsmd.service
> Requires=multipathd.service libvirtd.service ntpd.service
> systemd-journald.socket basic.target