<div dir="ltr"><br><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Aug 30, 2017 at 2:31 PM, Dominik Holler <span dir="ltr"><<a href="mailto:dholler@redhat.com" target="_blank">dholler@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">On Wed, 30 Aug 2017 14:18:49 +0300<br>
Dan Kenigsberg <<a href="mailto:danken@redhat.com">danken@redhat.com</a>> wrote:<br>
<br>
> On Wed, Aug 30, 2017 at 1:40 PM, Barak Korren <<a href="mailto:bkorren@redhat.com">bkorren@redhat.com</a>><br>
> wrote:<br>
> > Test failed: [ 002_bootstrap.add_hosts ]<br>
> ><br>
> > Link to suspected patches:<br>
> ><br>
> > We suspect this is due to change to LLDPAD in upstream CentOS repos.<br>
> > We can't tell the exact point it was introduced because other<br>
> > ovirt-engine regressions introduced too much noise into the system.<br>
> ><br>
> > It also seems that the failure is not 100% reproducible sine we have<br>
> > runs that do not encounter it.<br>
> ><br>
> > Link to Job:<br>
> > <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/2151" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-<wbr>tester/2151</a><br>
> ><br>
> > (This job checked a specific patch to ovirt-log-collector but<br>
> > failure seems unrelated, and also happens on vanille 'tested' repo<br>
> > right now).<br>
> ><br>
> > Link to all logs:<br>
> > VDSM logs seem to be most relevant here:<br>
> ><br>
> > <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/2151/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py/lago-basic-suite-master-host-0/_var_log/vdsm/" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-<wbr>tester/2151/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py/<wbr>lago-basic-suite-master-host-<wbr>0/_var_log/vdsm/</a><br>
> ><br>
> > Error snippet from log:<br>
> ><br>
> > - From VDSM logs (note it exists very quickly):<br>
> ><br>
> > <error><br>
> ><br>
> > 2017-08-30 05:55:52,208-0400 INFO (MainThread) [vds] (PID: 4594) I<br>
> > am the actual vdsm 4.20.2-133.git0ce4485.el7.<wbr>centos<br>
> > lago-basic-suite-master-host-0 (3.10.0-514.2.2.el7.x86_64)<br>
> > (vdsmd:148) 2017-08-30 05:55:52,209-0400 INFO (MainThread) [vds]<br>
> > VDSM will run with cpu affinity: frozenset([1]) (vdsmd:254)<br>
> > 2017-08-30 05:55:52,253-0400 INFO (MainThread) [storage.check]<br>
> > Starting check service (check:92)<br>
> > 2017-08-30 05:55:52,257-0400 INFO (MainThread) [storage.Dispatcher]<br>
> > Starting StorageDispatcher... (dispatcher:48)<br>
> > 2017-08-30 05:55:52,257-0400 INFO (check/loop) [storage.asyncevent]<br>
> > Starting <EventLoop running=True closed=False at 0x45317520><br>
> > (asyncevent:125)<br>
> > 2017-08-30 05:55:52,288-0400 INFO (MainThread) [vdsm.api] START<br>
> > registerDomainStateChangeCallb<wbr>ack(callbackFunc=<functools.<wbr>partial<br>
> > object at 0x2b47b50>) from=internal,<br>
> > task_id=2cebe9ef-358e-47d7-<wbr>81a6-8c4b54b9cd6d (api:46)<br>
> > 2017-08-30 05:55:52,288-0400 INFO (MainThread) [vdsm.api] FINISH<br>
> > registerDomainStateChangeCallb<wbr>ack return=None from=internal,<br>
> > task_id=2cebe9ef-358e-47d7-<wbr>81a6-8c4b54b9cd6d (api:52)<br>
> > 2017-08-30 05:55:52,288-0400 INFO (MainThread) [MOM] Preparing MOM<br>
> > interface (momIF:53)<br>
> > 2017-08-30 05:55:52,289-0400 INFO (MainThread) [MOM] Using named<br>
> > unix socket /var/run/vdsm/mom-vdsm.sock (momIF:62)<br>
> > 2017-08-30 05:55:52,289-0400 INFO (MainThread) [root] Unregistering<br>
> > all secrets (secret:91)<br>
> > 2017-08-30 05:55:52,307-0400 INFO (MainThread) [vds] Setting<br>
> > channels' timeout to 30 seconds. (vmchannels:221)<br>
> > 2017-08-30 05:55:52,309-0400 INFO (vmrecovery) [vds] recovery:<br>
> > completed in 0s (clientIF:516)<br>
> > 2017-08-30 05:55:52,310-0400 INFO (MainThread)<br>
> > [vds.MultiProtocolAcceptor] Listening at :::54321<br>
> > (protocoldetector:196)<br>
> > 2017-08-30 05:55:52,496-0400 INFO (http) [vds] Server running<br>
> > (http:58) 2017-08-30 05:55:52,742-0400 INFO (periodic/1)<br>
> > [vdsm.api] START repoStats(domains=()) from=internal,<br>
> > task_id=85768015-8ecb-48e3-<wbr>9307-f671bfc33c65 (api:46)<br>
> > 2017-08-30 05:55:52,743-0400 INFO (periodic/1) [vdsm.api] FINISH<br>
> > repoStats return={} from=internal,<br>
> > task_id=85768015-8ecb-48e3-<wbr>9307-f671bfc33c65 (api:52)<br>
> > 2017-08-30 05:55:52,743-0400 WARN (periodic/1) [throttled] MOM not<br>
> > available. (throttledlog:103)<br>
> > 2017-08-30 05:55:52,744-0400 WARN (periodic/1) [throttled] MOM not<br>
> > available, KSM stats will be missing. (throttledlog:103)<br>
> > 2017-08-30 05:55:55,043-0400 INFO (MainThread) [vds] Received<br>
> > signal 15, shutting down (vdsmd:67)<br>
> > 2017-08-30 05:55:55,045-0400 INFO (MainThread)<br>
> > [jsonrpc.JsonRpcServer] Stopping JsonRPC Server (__init__:759)<br>
> > 2017-08-30 05:55:55,049-0400 INFO (MainThread) [vds] Stopping http<br>
> > server (http:79)<br>
> > 2017-08-30 05:55:55,049-0400 INFO (http) [vds] Server stopped<br>
> > (http:69) 2017-08-30 05:55:55,050-0400 INFO (MainThread) [root]<br>
> > Unregistering all secrets (secret:91)<br>
> > 2017-08-30 05:55:55,052-0400 INFO (MainThread) [vdsm.api] START<br>
> > prepareForShutdown(options=<wbr>None) from=internal,<br>
> > task_id=ffde5caa-fa44-49ab-<wbr>bdd1-df81519680a3 (api:46)<br>
> > 2017-08-30 05:55:55,089-0400 INFO (MainThread) [storage.Monitor]<br>
> > Shutting down domain monitors (monitor:222)<br>
> > 2017-08-30 05:55:55,090-0400 INFO (MainThread) [storage.check]<br>
> > Stopping check service (check:105)<br>
> > 2017-08-30 05:55:55,090-0400 INFO (check/loop) [storage.asyncevent]<br>
> > Stopping <EventLoop running=True closed=False at 0x45317520><br>
> > (asyncevent:220)<br>
> > 2017-08-30 05:55:55,090-0400 INFO (MainThread) [vdsm.api] FINISH<br>
> > prepareForShutdown return=None from=internal,<br>
> > task_id=ffde5caa-fa44-49ab-<wbr>bdd1-df81519680a3 (api:52)<br>
> > 2017-08-30 05:55:55,091-0400 INFO (MainThread) [vds] Stopping<br>
> > threads (vdsmd:159)<br>
> > 2017-08-30 05:55:55,091-0400 INFO (MainThread) [vds] Exiting<br>
> > (vdsmd:170)<br>
> ><br>
> > </error><br>
> ><br>
> ><br>
> > - From SuperVDSM logs:<br>
> ><br>
> > <error><br>
> ><br>
> > MainThread::ERROR::2017-08-30<br>
> > 05:55:59,476::initializer::53:<wbr>:root::(_lldp_init) Failed to enable<br>
> > LLDP on eth1<br>
> > Traceback (most recent call last):<br>
> > File<br>
> > "/usr/lib/python2.7/site-<wbr>packages/vdsm/network/<wbr>initializer.py",<br>
> > line 51, in _lldp_init Lldp.enable_lldp_on_iface(<wbr>device)<br>
> > File<br>
> > "/usr/lib/python2.7/site-<wbr>packages/vdsm/network/lldp/<wbr>lldpad.py",<br>
> > line 30, in enable_lldp_on_iface<br>
> > lldptool.enable_lldp_on_iface(<wbr>iface, rx_only) File<br>
> > "/usr/lib/python2.7/site-<wbr>packages/vdsm/network/lldpad/<wbr>lldptool.py",<br>
> > line 46, in enable_lldp_on_iface raise EnableLldpError(rc, out,<br>
> > err, iface) EnableLldpError: (1,<br>
> > "timeout\n'<wbr>M00000001C3040000000c04eth1000<wbr>badminStatus0002rx' command<br>
> > timed out.\n", '', 'eth1')<br>
> > MainThread::DEBUG::2017-08-30<br>
> > 05:55:59,477::cmdutils::133::<wbr>root::(exec_cmd) /usr/sbin/lldptool<br>
> > get-lldp -i eth0 adminStatus (cwd None)<br>
> ><br>
> ><br>
> > </error><br>
><br>
> The LLDP errors are due to SELinux, to be fixed in CentOS-7.4.1. They<br>
> do not cause supervdsmd to stop, so they are not the reason for vdsm's<br>
> failure to start. Something ELSE is doing this.<br>
><br>
> in<br>
> <a href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/2151/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-002_bootstrap.py/lago-basic-suite-master-host-0/_var_log/messages/*view*/" rel="noreferrer" target="_blank">http://jenkins.ovirt.org/job/<wbr>ovirt-master_change-queue-<wbr>tester/2151/artifact/exported-<wbr>artifacts/basic-suit-master-<wbr>el7/test_logs/basic-suite-<wbr>master/post-002_bootstrap.py/<wbr>lago-basic-suite-master-host-<wbr>0/_var_log/messages/*view*/</a><br>
> we have<br>
><br>
> Aug 30 05:55:52 lago-basic-suite-master-host-0 journal: vdsm throttled<br>
> WARN MOM not available.<br>
> Aug 30 05:55:52 lago-basic-suite-master-host-0 journal: vdsm throttled<br>
> WARN MOM not available, KSM stats will be missing.<br>
> Aug 30 05:55:53 lago-basic-suite-master-host-0 systemd: Started<br>
> Session 10 of user root.<br>
> Aug 30 05:55:53 lago-basic-suite-master-host-0 systemd-logind: New<br>
> session 10 of user root.<br>
> Aug 30 05:55:53 lago-basic-suite-master-host-0 systemd: Starting<br>
> Session 10 of user root.<br>
> Aug 30 05:55:53 lago-basic-suite-master-host-0 python: ansible-setup<br>
> Invoked with filter=* gather_subset=['all']<br>
> fact_path=/etc/ansible/facts.d gather_timeout=10<br>
> Aug 30 05:55:54 lago-basic-suite-master-host-0 python: ansible-command<br>
> Invoked with warn=True executable=None _uses_shell=False<br>
> _raw_params=bash -c "rpm -qi vdsm | grep -oE<br>
> 'Version\\s+:\\s+[0-9\\.]+' | awk '{print $3}'" removes=None<br>
> creates=None chdir=None<br>
> Aug 30 05:55:54 lago-basic-suite-master-host-0 python: ansible-systemd<br>
> Invoked with no_block=False name=libvirt-guests enabled=True<br>
> daemon_reload=False state=started user=False masked=None<br>
> Aug 30 05:55:54 lago-basic-suite-master-host-0 systemd: Reloading.<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Cannot add<br>
> dependency job for unit lvm2-lvmetad.socket, ignoring: Unit is masked.<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Stopped MOM<br>
> instance configured for VDSM purposes.<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Stopping<br>
> Virtual Desktop Server Manager...<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Starting<br>
> Suspend Active Libvirt Guests...<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Started<br>
> Suspend Active Libvirt Guests.<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 journal: libvirt<br>
> version: 2.0.0, package: 10.el7_3.9 (CentOS BuildSystem<br>
> <<a href="http://bugs.centos.org" rel="noreferrer" target="_blank">http://bugs.centos.org</a>>, <a href="tel:2017-05-25-20" value="+12017052520">2017-05-25-20</a>:52:28, <a href="http://c1bm.rdu2.centos.org" rel="noreferrer" target="_blank">c1bm.rdu2.centos.org</a>)<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 journal: hostname:<br>
> lago-basic-suite-master-host-<wbr>0.lago.local<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 vdsmd_init_common.sh:<br>
> vdsm: Running run_final_hooks<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 journal: End of file<br>
> while reading data: Input/output error<br>
> Aug 30 05:55:55 lago-basic-suite-master-host-0 systemd: Stopped<br>
> Virtual Desktop Server Manager.<br>
><br>
> suggesting that systemd stopped vdsmd since mom did not start on time.<br>
> We have an extremely ugly two-way dependency between the two services.<br>
> Each depends on the other one. I am guessing that systemd's grace<br>
> period for such a cycle has expired, and the couple was taken down.<br>
><br>
> Does anybody have a guess what could cause such slowlness?<br>
<br>
</div></div>Even if the LLDP errors does not have a negative impact of the<br>
functional behavior of supervdsmd, they have a impact timing behavior<br>
of the initialization of supervdsmd.<br>
<br>
I will post a patch today which moves the initialization of LLDP in an<br>
extra thread, to make the initialization of LLDP asynchronly.<br>
<div class="HOEnZb"><div class="h5"><br></div></div></blockquote><div><br></div><div>I'm not sure if this is possible. The LLDP init is processed during the initialization<br></div><div>step of supervdsm service and we depend on it to execute prior to enter the running<br></div><div>stage.<br></div><div>If we will use a thread in this case, the running stage will start but one of the inits<br></div><div>may not end.<br><br></div><div>Perhaps just do some specific checks on init to make it faster. (like check if we<br></div><div>have the selinux issue and break early)<br></div><div><br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">
<br>
______________________________<wbr>_________________<br>
Devel mailing list<br>
<a href="mailto:Devel@ovirt.org">Devel@ovirt.org</a><br>
<a href="http://lists.ovirt.org/mailman/listinfo/devel" rel="noreferrer" target="_blank">http://lists.ovirt.org/<wbr>mailman/listinfo/devel</a><br>
</div></div></blockquote></div><br></div></div>