[ovirt-devel] [ OST Failure Report ] [ oVirt master ] [ 2017-08-30 ] [add_hosts]

Wed Aug 30 10:40:09 UTC 2017

Test failed: [ 002_bootstrap.add_hosts ]

Link to suspected patches:

We suspect this is due to change to LLDPAD in upstream CentOS repos.
We can't tell the exact point it was introduced because other
ovirt-engine regressions introduced too much noise into the system.

It also seems that the failure is not 100% reproducible sine we have
runs that do not encounter it.

Link to Job:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/2151

(This job checked a specific patch to ovirt-log-collector but failure
seems unrelated, and also happens on vanille 'tested' repo right now).

Link to all logs:
VDSM logs seem to be most relevant here:

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/

Error snippet from log:

- From VDSM logs (note it exists very quickly):

<error>

2017-08-30 05:55:52,208-0400 INFO  (MainThread) [vds] (PID: 4594) I am
the actual vdsm 4.20.2-133.git0ce4485.el7.centos
lago-basic-suite-master-host-0 (3.10.0-514.2.2.el7.x86_64) (vdsmd:148)
2017-08-30 05:55:52,209-0400 INFO  (MainThread) [vds] VDSM will run
with cpu affinity: frozenset([1]) (vdsmd:254)
2017-08-30 05:55:52,253-0400 INFO  (MainThread) [storage.check]
Starting check service (check:92)
2017-08-30 05:55:52,257-0400 INFO  (MainThread) [storage.Dispatcher]
Starting StorageDispatcher... (dispatcher:48)
2017-08-30 05:55:52,257-0400 INFO  (check/loop) [storage.asyncevent]
Starting <EventLoop running=True closed=False at 0x45317520>
(asyncevent:125)
2017-08-30 05:55:52,288-0400 INFO  (MainThread) [vdsm.api] START
registerDomainStateChangeCallback(callbackFunc=<functools.partial
object at 0x2b47b50>) from=internal,
task_id=2cebe9ef-358e-47d7-81a6-8c4b54b9cd6d (api:46)
2017-08-30 05:55:52,288-0400 INFO  (MainThread) [vdsm.api] FINISH
registerDomainStateChangeCallback return=None from=internal,
task_id=2cebe9ef-358e-47d7-81a6-8c4b54b9cd6d (api:52)
2017-08-30 05:55:52,288-0400 INFO  (MainThread) [MOM] Preparing MOM
interface (momIF:53)
2017-08-30 05:55:52,289-0400 INFO  (MainThread) [MOM] Using named unix
socket /var/run/vdsm/mom-vdsm.sock (momIF:62)
2017-08-30 05:55:52,289-0400 INFO  (MainThread) [root] Unregistering
all secrets (secret:91)
2017-08-30 05:55:52,307-0400 INFO  (MainThread) [vds] Setting
channels' timeout to 30 seconds. (vmchannels:221)
2017-08-30 05:55:52,309-0400 INFO  (vmrecovery) [vds] recovery:
completed in 0s (clientIF:516)
2017-08-30 05:55:52,310-0400 INFO  (MainThread)
[vds.MultiProtocolAcceptor] Listening at :::54321
(protocoldetector:196)
2017-08-30 05:55:52,496-0400 INFO  (http) [vds] Server running (http:58)
2017-08-30 05:55:52,742-0400 INFO  (periodic/1) [vdsm.api] START
repoStats(domains=()) from=internal,
task_id=85768015-8ecb-48e3-9307-f671bfc33c65 (api:46)
2017-08-30 05:55:52,743-0400 INFO  (periodic/1) [vdsm.api] FINISH
repoStats return={} from=internal,
task_id=85768015-8ecb-48e3-9307-f671bfc33c65 (api:52)
2017-08-30 05:55:52,743-0400 WARN  (periodic/1) [throttled] MOM not
available. (throttledlog:103)
2017-08-30 05:55:52,744-0400 WARN  (periodic/1) [throttled] MOM not
available, KSM stats will be missing. (throttledlog:103)
2017-08-30 05:55:55,043-0400 INFO  (MainThread) [vds] Received signal
15, shutting down (vdsmd:67)
2017-08-30 05:55:55,045-0400 INFO  (MainThread)
[jsonrpc.JsonRpcServer] Stopping JsonRPC Server (__init__:759)
2017-08-30 05:55:55,049-0400 INFO  (MainThread) [vds] Stopping http
server (http:79)
2017-08-30 05:55:55,049-0400 INFO  (http) [vds] Server stopped (http:69)
2017-08-30 05:55:55,050-0400 INFO  (MainThread) [root] Unregistering
all secrets (secret:91)
2017-08-30 05:55:55,052-0400 INFO  (MainThread) [vdsm.api] START
prepareForShutdown(options=None) from=internal,
task_id=ffde5caa-fa44-49ab-bdd1-df81519680a3 (api:46)
2017-08-30 05:55:55,089-0400 INFO  (MainThread) [storage.Monitor]
Shutting down domain monitors (monitor:222)
2017-08-30 05:55:55,090-0400 INFO  (MainThread) [storage.check]
Stopping check service (check:105)
2017-08-30 05:55:55,090-0400 INFO  (check/loop) [storage.asyncevent]
Stopping <EventLoop running=True closed=False at 0x45317520>
(asyncevent:220)
2017-08-30 05:55:55,090-0400 INFO  (MainThread) [vdsm.api] FINISH
prepareForShutdown return=None from=internal,
task_id=ffde5caa-fa44-49ab-bdd1-df81519680a3 (api:52)
2017-08-30 05:55:55,091-0400 INFO  (MainThread) [vds] Stopping threads
(vdsmd:159)
2017-08-30 05:55:55,091-0400 INFO  (MainThread) [vds] Exiting (vdsmd:170)

</error>

- From SuperVDSM logs:

<error>

MainThread::ERROR::2017-08-30
05:55:59,476::initializer::53::root::(_lldp_init) Failed to enable
LLDP on eth1
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/network/initializer.py",
line 51, in _lldp_init
    Lldp.enable_lldp_on_iface(device)
  File "/usr/lib/python2.7/site-packages/vdsm/network/lldp/lldpad.py",
line 30, in enable_lldp_on_iface
    lldptool.enable_lldp_on_iface(iface, rx_only)
  File "/usr/lib/python2.7/site-packages/vdsm/network/lldpad/lldptool.py",
line 46, in enable_lldp_on_iface
    raise EnableLldpError(rc, out, err, iface)
EnableLldpError: (1,
"timeout\n'M00000001C3040000000c04eth1000badminStatus0002rx' command
timed out.\n", '', 'eth1')
MainThread::DEBUG::2017-08-30
05:55:59,477::cmdutils::133::root::(exec_cmd) /usr/sbin/lldptool
get-lldp -i eth0 adminStatus (cwd None)

</error>

-- 
Barak Korren
RHV DevOps team , RHCE, RHCi
Red Hat EMEA
redhat.com | TRIED. TESTED. TRUSTED. | redhat.com/trusted