9:48 a.m.
This is a multi-part message in MIME format.
--------------5185435FD38913B821CED967
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Hi,
We had a failure in upgrade suite for 002_bootstrap.add_hosts. I am not
seeing any error that can suggest on an issue in engine.
I can see in the host messages host that we have stopped writing to the
log for 15 minutes and it may suggest that there is something that is
keeping the host from starting which causes us to fail the test on timeout.
However, i can use some help in determining the cause for this failure
and weather its connected to the bootstrap_add_host test in upgrade.
**
*Link to suspected patches: As I said,**I do not think its related, but
this is the patch that was reported. *
*
https://gerrit.ovirt.org/#/c/83854/
Link to Job:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/*
*
*
*Link to all logs:*
*http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifact/*
*
*
*(Relevant) error snippet from the log: *
*
<error>
**
_*Test error: *_**
**
*
Error Message
False != True after 900 seconds
Stacktrace
Traceback (most recent call last):
File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
testMethod()
File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
self.test(*self.arg)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 129, in
wrapped_test
test()
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 59, in
wrapper
return func(get_test_prefix(), *args, **kwargs)
File
"/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/upgrade-from-release-suite-master/test-scenarios-after-upgrade/002_bootstrap.py",
line 187, in add_hosts
testlib.assert_true_within(_host_is_up_4, timeout=15*60)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 263, in
assert_true_within
assert_equals_within(func, True, timeout, allowed_exceptions)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 237, in
assert_equals_within
'%s != %s after %s seconds' % (res, value, timeout)
AssertionError: False != True after 900 seconds
**
**
**
**_lago log: _*
*
*2017-11-13
15:31:23,212::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None] Unable to connect to port 22 on 192.168.200.3
2017-11-13
15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 4 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 4 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:28,224::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:28,225::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:29,228::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:29,228::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None] Unable to connect to port 22 on 192.168.200.3
2017-11-13
15:31:30,229::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:30,230::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 2 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:30,230::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:31,232::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None] Unable to connect to port 22 on 192.168.200.3
2017-11-13
15:31:31,232::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:31,233::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:32,234::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:32,234::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:32,234::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:33,235::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:33,236::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None] Unable to connect to port 22 on 192.168.200.3
2017-11-13 15:31:33,237::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:34,238::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:34,238::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:34,239::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got 1
tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:34,407::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,639::ssh.py::ssh::58::lago.ssh::DEBUG::Running
bb49adfa on lago-upgrade-from-release-suite-master-host0: true
2017-11-13 15:31:34,665::ssh.py::ssh::81::lago.ssh::DEBUG::Command
bb49adfa on lago-upgrade-from-release-suite-master-host0 returned with 0
2017-11-13
15:31:34,665::ssh.py::wait_for_ssh::153::lago.ssh::DEBUG::Wait succeeded
for ssh to lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:34,665::log_utils.py::__exit__::611::lago.prefix::INFO::ESC[32mSuccessESC[0m
(in 0:00:11)
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:34,667::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still got
100 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:34,805::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,906::ssh.py::ssh::58::lago.ssh::DEBUG::Running
bb724bf2 on lago-upgrade-from-release-suite-master-host0: bash -s < "set -xe
DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')
*
*
*
**_from host: _*
*
ions. Proceeding anyway.
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
Configuration file /usr/lib/systemd/system/ebtables.service is marked
executable. Please remove executable permission bits. Proceeding anyway.
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
Configuration file /usr/lib/systemd/system/wpa_supplicant.service is
marked executable. Please remove executable permission bits. Proceeding
anyway.
Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0 yum[1294]:
Updated: iptables-1.4.21-18.2.el7_4.x86_64
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 3.
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Created slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Started Session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: New session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 4.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Created slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Started Session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: New session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 5.
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Cleanup of Temporary Directories...
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
Started Cleanup of Temporary Directories.
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]: DHCPREQUEST on eth0 to 192.168.200.1 port 67 (xid=0x564629cb)
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]: DHCPACK from 192.168.200.1 (xid=0x564629cb)**
*
*
*</error>*
**
--------------5185435FD38913B821CED967
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit
<html>
<head>
<meta http-equiv="content-type" content="text/html;
charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
<p>Hi, <br>
</p>
<p>We had a failure in upgrade suite for 002_bootstrap.add_hosts. I
am not seeing any error that can suggest on an issue in engine. <br>
</p>
<p>I can see in the host messages host that we have stopped writing
to the log for 15 minutes and it may suggest that there is
something that is keeping the host from starting which causes us
to fail the test on timeout. <br>
</p>
<p>However, i can use some help in determining the cause for this
failure and weather its connected to the bootstrap_add_host test
in upgrade.<br>
</p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57">
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
to suspected patches: As I said,<b> </b>I do not think its related, but this
is the patch that was reported.
</span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">
</span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><a
class="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/#/c/83854/">https://gerrit.ov...
<br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
to Job:</span></p>
<a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
to all logs:</span></p>
<a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">(Relevant)
error snippet from the log: </span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><error></span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">
</span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">
</span></p>
</b><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57">
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><u><font
size="+1"><b>Test error: </b></font></u><b>
</b></span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><b>
</b></span></p>
</b></p>
<h3 style="box-sizing: border-box; color: rgb(51, 51, 51);
font-family: Helvetica, Arial, sans-serif; font-style: normal;
font-variant-ligatures: normal; font-variant-caps: normal;
letter-spacing: normal; orphans: 2; text-align: start;
text-indent: 0px; text-transform: none; white-space: normal;
widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px;
text-decoration-style: initial; text-decoration-color: initial;">Error
Message</h3>
<pre style="box-sizing: border-box; white-space: pre-wrap; word-wrap:
break-word; margin: 0px; color: rgb(51, 51, 51); font-size: 14px; font-style: normal;
font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal;
letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform:
none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style:
initial; text-decoration-color: initial;">False != True after 900
seconds</pre>
<h3 style="box-sizing: border-box; color: rgb(51, 51, 51);
font-family: Helvetica, Arial, sans-serif; font-style: normal;
font-variant-ligatures: normal; font-variant-caps: normal;
letter-spacing: normal; orphans: 2; text-align: start;
text-indent: 0px; text-transform: none; white-space: normal;
widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px;
text-decoration-style: initial; text-decoration-color:
initial;">Stacktrace</h3>
<pre style="box-sizing: border-box; white-space: pre-wrap; word-wrap:
break-word; margin: 0px; color: rgb(51, 51, 51); font-size: 14px; font-style: normal;
font-variant-ligatures: normal; font-variant-caps: normal; font-weight: normal;
letter-spacing: normal; orphans: 2; text-align: start; text-indent: 0px; text-transform:
none; widows: 2; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration-style:
initial; text-decoration-color: initial;">Traceback (most recent call last):
File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
testMethod()
File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
self.test(*self.arg)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 129, in
wrapped_test
test()
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 59, in
wrapper
return func(get_test_prefix(), *args, **kwargs)
File
"/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/upgrade-from-release-suite-master/test-scenarios-after-upgrade/002_bootstrap.py",
line 187, in add_hosts
testlib.assert_true_within(_host_is_up_4, timeout=15*60)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 263, in
assert_true_within
assert_equals_within(func, True, timeout, allowed_exceptions)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 237, in
assert_equals_within
'%s != %s after %s seconds' % (res, value, timeout)
AssertionError: False != True after 900 seconds</pre>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57">
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"></span></p>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><b><u><font
size="+1">lago log:
</font></u></b><br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57">2017-11-13
15:31:23,212::log_utils.py::__enter__::600::lago.prefix::<a
class="moz-txt-link-freetext"
href="INFO::ESC">INFO::ESC</a>[0mESC[0m<br>
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3<br>
2017-11-13
15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2<br>
2017-11-13
15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:27,222::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-engine: Timed out (in 4
s) trying to ssh to
lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:27,222::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-host0: Timed out (in 4 s)
trying to ssh to lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:28,224::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:28,225::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2<br>
2017-11-13
15:31:29,228::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:29,228::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-host0: Timed out (in 1 s)
trying to ssh to lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3<br>
2017-11-13
15:31:30,229::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:30,230::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-engine: Timed out (in 2
s) trying to ssh to
lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:30,230::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2<br>
2017-11-13
15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:31,232::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3<br>
2017-11-13
15:31:31,232::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:31,233::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-host0: Timed out (in 1 s)
trying to ssh to lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:32,234::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:32,234::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-engine: Timed out (in 1
s) trying to ssh to
lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:32,234::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2<br>
2017-11-13
15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:33,235::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:33,236::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error connecting to
lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3<br>
2017-11-13
15:31:33,237::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-host0: Timed out (in 1 s)
trying to ssh to lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:34,238::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:<br>
2017-11-13
15:31:34,238::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::129::lago.ssh::DEBUG::Got">ssh::129::lago.ssh::DEBUG::Got</a>
exception while sshing to
lago-upgrade-from-release-suite-master-engine: Timed out (in 1
s) trying to ssh to
lago-upgrade-from-release-suite-master-engine<br>
2017-11-13
15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:34,239::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:34,407::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:34,639::ssh.py::<a class="moz-txt-link-freetext"
href="ssh::58::lago.ssh::DEBUG::Running">ssh::58::lago.ssh::DEBUG::Running</a>
bb49adfa
on lago-upgrade-from-release-suite-master-host0: true<br>
2017-11-13
15:31:34,665::ssh.py::<a class="moz-txt-link-freetext"
href="ssh::81::lago.ssh::DEBUG::Command">ssh::81::lago.ssh::DEBUG::Command</a>
bb49adfa
on lago-upgrade-from-release-suite-master-host0 returned with 0<br>
2017-11-13
15:31:34,665::ssh.py::wait_for_<a class="moz-txt-link-freetext"
href="ssh::153::lago.ssh::DEBUG::Wait">ssh::153::lago.ssh::DEBUG::Wait</a>
succeeded for ssh to
lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:34,665::log_utils.py::__exit__::611::lago.prefix::<a
class="moz-txt-link-freetext"
href="INFO::ESC">INFO::ESC</a>[32mSuccessESC[0m
(in 0:00:11)<br>
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.prefix::<a
class="moz-txt-link-freetext"
href="INFO::ESC">INFO::ESC</a>[0mESC[0m<br>
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:34,667::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 100 tries for lago-upgrade-from-release-suite-master-host0<br>
2017-11-13
15:31:34,805::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:<br>
2017-11-13
15:31:34,906::ssh.py::<a class="moz-txt-link-freetext"
href="ssh::58::lago.ssh::DEBUG::Running">ssh::58::lago.ssh::DEBUG::Running</a>
bb724bf2
on lago-upgrade-from-release-suite-master-host0: bash -s <
"set -xe<br>
DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')<br>
<br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><b><u><font
size="+1">from host:
</font></u></b><br>
</b></p>
<p><span style="font-weight:normal;">ions. Proceeding
anyway.<br>
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0
systemd: Configuration file
/usr/lib/systemd/system/ebtables.service is marked executable.
Please remove executable permission bits. Proceeding anyway.<br>
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0
systemd: Configuration file
/usr/lib/systemd/system/wpa_supplicant.service is marked
executable. Please remove executable permission bits. Proceeding
anyway.<br>
Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0
yum[1294]: Updated: iptables-1.4.21-18.2.el7_4.x86_64<br>
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 3.<br>
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0
systemd: Removed slice user-0.slice.<br>
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0
systemd: Stopping user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Created slice user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Starting user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Started Session 4 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Starting Session 4 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: New session 4 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 4.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Removed slice user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Stopping user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Created slice user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Starting user-0.slice.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Started Session 5 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd: Starting Session 5 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: New session 5 of user root.<br>
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind: Removed session 5.<br>
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0
systemd: Removed slice user-0.slice.<br>
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0
systemd: Stopping user-0.slice.<br>
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0
systemd: Starting Cleanup of Temporary Directories...<br>
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0
systemd: Started Cleanup of Temporary Directories.<br>
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]: DHCPREQUEST on eth0 to 192.168.200.1 port 67
(xid=0x564629cb)<br>
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]: DHCPACK from 192.168.200.1 (xid=0x564629cb)</span><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-ba60-843c-cfdd-7366571bcb57"><b><br>
</b><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"></error></span></p>
</b><br class="Apple-interchange-newline">
</p>
</body>
</html>
--------------5185435FD38913B821CED967--
3:01 a.m.
On Tue, Nov 14, 2017 at 5:48 PM, Dafna Ron <dron(a)redhat.com> wrote:
Hi,
We had a failure in upgrade suite for 002_bootstrap.add_hosts. I am not
seeing any error that can suggest on an issue in engine.
I can see in the host messages host that we have stopped writing to the log
for 15 minutes and it may suggest that there is something that is keeping
the host from starting which causes us to fail the test on timeout.
However, i can use some help in determining the cause for this failure and
weather its connected to the bootstrap_add_host test in upgrade.
Link to suspected patches: As I said, I do not think its related, but this
is the patch that was reported.
https://gerrit.ovirt.org/#/c/83854/
Link to Job:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/
Link to all logs:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifact/
(Relevant) error snippet from the log:
<error>
Test error:
Error Message
False != True after 900 seconds
Stacktrace
Traceback (most recent call last):
File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
testMethod()
File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
self.test(*self.arg)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 129, in
wrapped_test
test()
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 59, in
wrapper
return func(get_test_prefix(), *args, **kwargs)
File
"/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/upgrade-from-release-suite-master/test-scenarios-after-upgrade/002_bootstrap.py",
line 187, in add_hosts
testlib.assert_true_within(_host_is_up_4, timeout=15*60)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 263, in
assert_true_within
assert_equals_within(func, True, timeout, allowed_exceptions)
File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 237, in
assert_equals_within
'%s != %s after %s seconds' % (res, value, timeout)
AssertionError: False != True after 900 seconds
Hi,
It took me way too long to find the log file that includes the above
stack trace. There is a known bug that pressing '(all files in zip)' does
not get all of them, only some. If we can't fix it, please add something
that will create such a zip/tar/whatever as part of the job, so that we
do not rely on jenkins.
Something causes things to be very slow, no idea what in particular,
but could not find a real problem.
Since we timed out and killed the engine in the middle of host-deploy,
we do not have full logs of it. These are copied to the engine from the
host only after it finishes. Before that, the log is written on the host
in /tmp. We might want to make ost collect that as well, to help debug
similar cases.
What we can see in engine log is that we start installing the host [1]:
2017-11-13 11:00:12,331-05 INFO
[org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
(EE-ManagedThreadFactory-engine-Thread-1) [45082420] Before
Installation host 83090668-908c-4f49-8690-5348ec12f931,
lago-upgrade-from-release-suite-master-host0
2017-11-13 11:00:12,354-05 INFO
[org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-1) [45082420] START,
SetVdsStatusVDSCommand(HostName =
lago-upgrade-from-release-suite-master-host0,
SetVdsStatusVDSCommandParameters:{hostId='83090668-908c-4f49-8690-5348ec12f931',
status='Installing', nonOperationalReason='NONE',
stopSpmFailureLogged='false', maintenanceReason='null'}), log id:
22a831f7
First line from host-deploy is:
2017-11-13 11:00:13,335-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
Initializing.
which is one second later, ok.
...
2017-11-13 11:00:13,459-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
Environment packages setup.
It goes install (immediately) packages that it needs for itself,
in this case it updates the package 'dmidecode', from 2.12-9
to 3.0-5. I guess our image is a bit old.
...
2017-11-13 11:00:19,516-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Verify: 2/2: dmidecode.x86_64 1:2.12-9.el7 - ud.
So it took (the equivalent of 'yum update dmidecode') 6 seconds.
Reasonable.
...
Later on, it starts installing/updating the actual packages it
should install/update. Starts with:
2017-11-13 11:00:24,982-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Status: Downloading Packages.
Then there are many lines about each package download. First is:
2017-11-13 11:00:25,049-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Download/Verify: GeoIP-1.5.0-11.el7.x86_64.
Last is:
2017-11-13 11:00:43,790-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Download/Verify: zlib-1.2.7-17.el7.x86_64.
Later we see it updates 570 packages. So downloading 570 packages
took ~ 20 seconds, good too. Then it installs them. First is:
2017-11-13 11:00:46,114-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 1/570: libgcc-4.8.5-16.el7.x86_64.
And then many similar ones. I only skimmed through them, trying to
find large gaps - didn't write a script - and a large one I find is:
2017-11-13 11:10:04,522-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
updated: 506/570: audit.
2017-11-13 11:13:06,483-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
updated: 507/570: openssl-libs.
In between these two lines, there are a few unrelated ones, from some
other engine thread. So something caused it to need 3 minutes to install
openssl-libs.
A wild guess: Perhaps we have low entropy, and openssl does something
that needs entropy?
Checking engine-setup log there [2], I see that the following command
took almost 1.5 minutes to run:
2017-11-13 10:58:19,459-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.executeRaw:813 execute:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass'), executable='None',
cwd='None',
env={'pass': '**FILTERED**', 'LESSOPEN':
'||/usr/bin/lesspipe.sh %s',
'SSH_CLIENT': '192.168.200.1 52372 22',
'SELINUX_USE_CURRENT_RANGE':
'', 'LOGNAME': 'root', 'USER': 'root',
'OVIRT_ENGINE_JAVA_HOME':
u'/usr/lib/jvm/jre', 'PATH':
'/opt/rh/rh-postgresql95/root/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin',
'HOME': '/root', 'OVIRT_JBOSS_HOME':
'/usr/share/ovirt-engine-wildfly', 'LD_LIBRARY_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64', 'LANG': 'en_US.UTF-8',
'SHELL': '/bin/bash', 'LIBRARY_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64', 'SHLVL': '4',
'POSTGRESQLENV':
'COMMAND/pg_dump=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_dump
COMMAND/psql=str:/opt/rh/rh-postgresql95/root/usr/bin/psql
COMMAND/pg_restore=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_restore
COMMAND/postgresql-setup=str:/opt/rh/rh-postgresql95/root/usr/bin/postgresql-setup
OVESETUP_PROVISIONING/postgresService=str:rh-postgresql95-postgresql
OVESETUP_PROVISIONING/postgresConf=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/postgresql.conf
OVESETUP_PROVISIONING/postgresPgHba=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/pg_hba.conf
OVESETUP_PROVISIONING/postgresPgVersion=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/PG_VERSION',
'MANPATH': '/opt/rh/rh-postgresql95/root/usr/share/man:',
'X_SCLS':
'rh-postgresql95 ', 'XDG_RUNTIME_DIR': '/run/user/0',
'OVIRT_ENGINE_JAVA_HOME_FORCE': '1', 'PYTHONPATH':
'/usr/share/ovirt-engine/setup/bin/..::', 'SELINUX_ROLE_REQUESTED':
'', 'MAIL': '/var/mail/root', 'PKG_CONFIG_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64/pkgconfig', 'XDG_SESSION_ID':
'14', 'sclenv': 'rh-postgresql95', 'XDG_CONFIG_DIRS':
'/etc/opt/rh/rh-postgresql95/xdg:/etc/xdg', 'JAVACONFDIRS':
'/etc/opt/rh/rh-postgresql95/java:/etc/java',
'SELINUX_LEVEL_REQUESTED': '', 'XDG_DATA_DIRS':
'/opt/rh/rh-postgresql95/root/usr/share', 'PWD': '/root',
'CPATH':
'/opt/rh/rh-postgresql95/root/usr/include', 'OTOPI_LOGFILE':
'/var/log/ovirt-engine/setup/ovirt-engine-setup-20171113105548-qrc7zo.log',
'SSH_CONNECTION': '192.168.200.1 52372 192.168.200.3 22',
'OTOPI_EXECDIR': '/root'}
2017-11-13 10:59:43,545-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.executeRaw:863 execute-result:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass'), rc=0
2017-11-13 10:59:43,546-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.execute:921 execute-output:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass') stdout:
eyJhcnRpZmFjdCI6IkVudmVsb3BlUEJFIiwic2FsdCI6ImNjSmhFbHRnUEJxeUlNTUJSaU1OdFRYL3M0RGRJT1hOSWJjV2F1NFZGT0U9Iiwic2VjcmV0IjoiK2ZlTzVyZm9kNGlsVmZLRENaRjdseVVQZHZnWnBTWUF0cnBYUWVpQnJaTT0iLCJ2ZXJzaW9uIjoiMSIsIml0ZXJhdGlvbnMiOiI0MDAwIiwiYWxnb3JpdGhtIjoiUEJLREYyV2l0aEhtYWNTSEExIn0=
2017-11-13 10:59:43,546-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.execute:926 execute-output:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass') stderr:
This is almost always due to not enough entropy.
So please check if everything - from physical machines to
lago/ost/libvirt/etc., makes sure to supply all VMs enough
entropy. We usually do this using virtio-rng.
[1]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
[2]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
lago log:
2017-11-13
15:31:23,212::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3
2017-11-13
15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 4 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 4 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:28,224::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine
2017-11-13 15:31:28,225::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13 15:31:29,228::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:29,228::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3
2017-11-13 15:31:30,229::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13
15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:30,230::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 2 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13 15:31:30,230::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:31,232::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3
2017-11-13 15:31:31,232::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:31,233::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13 15:31:32,234::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:32,234::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:32,234::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
Unable to connect to port 22 on 192.168.200.2
2017-11-13
15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:33,235::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-engine
2017-11-13 15:31:33,236::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13
15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
Unable to connect to port 22 on 192.168.200.3
2017-11-13 15:31:33,237::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-host0:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-host0
2017-11-13 15:31:34,238::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
lago-upgrade-from-release-suite-master-engine:
2017-11-13 15:31:34,238::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
exception while sshing to lago-upgrade-from-release-suite-master-engine:
Timed out (in 1 s) trying to ssh to
lago-upgrade-from-release-suite-master-engine
2017-11-13
15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,239::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 1 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13 15:31:34,407::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,639::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb49adfa
on lago-upgrade-from-release-suite-master-host0: true
2017-11-13 15:31:34,665::ssh.py::ssh::81::lago.ssh::DEBUG::Command bb49adfa
on lago-upgrade-from-release-suite-master-host0 returned with 0
2017-11-13 15:31:34,665::ssh.py::wait_for_ssh::153::lago.ssh::DEBUG::Wait
succeeded for ssh to lago-upgrade-from-release-suite-master-host0
2017-11-13
15:31:34,665::log_utils.py::__exit__::611::lago.prefix::INFO::ESC[32mSuccessESC[0m
(in 0:00:11)
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
2017-11-13
15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,667::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
got 100 tries for lago-upgrade-from-release-suite-master-host0
2017-11-13 15:31:34,805::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
lago-upgrade-from-release-suite-master-host0:
2017-11-13 15:31:34,906::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb724bf2
on lago-upgrade-from-release-suite-master-host0: bash -s < "set -xe
DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')
from host:
ions. Proceeding anyway.
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
Configuration file /usr/lib/systemd/system/ebtables.service is marked
executable. Please remove executable permission bits. Proceeding anyway.
Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
Configuration file /usr/lib/systemd/system/wpa_supplicant.service is marked
executable. Please remove executable permission bits. Proceeding anyway.
Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0 yum[1294]:
Updated: iptables-1.4.21-18.2.el7_4.x86_64
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd-logind:
Removed session 3.
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Created slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Started Session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
New session 4 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
Removed session 4.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Created slice user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting user-0.slice.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Started Session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
New session 5 of user root.
Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
Removed session 5.
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
Removed slice user-0.slice.
Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
Stopping user-0.slice.
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
Starting Cleanup of Temporary Directories...
Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
Started Cleanup of Temporary Directories.
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
DHCPREQUEST on eth0 to 192.168.200.1 port 67 (xid=0x564629cb)
Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
DHCPACK from 192.168.200.1 (xid=0x564629cb)
</error>
--
Didi
5:35 a.m.
Didi,
Thank you for your detailed explanation and for taking the time to debug
this issue.
I opened the following Jira's:
1. for increasing entropy in the hosts:
https://ovirt-jira.atlassian.net/browse/OVIRT-1763
2. I added a comment to the not all logs are downloaded Jira regarded a
workaround which would save the logs on a different location:
https://ovirt-jira.atlassian.net/browse/OVIRT-1583
3. adding /tmp logs to the job logs:
https://ovirt-jira.atlassian.net/browse/OVIRT-1764
Again, thank you for your help Didi.
Dafna
On 11/15/2017 09:01 AM, Yedidyah Bar David wrote:
On Tue, Nov 14, 2017 at 5:48 PM, Dafna Ron <dron(a)redhat.com>
wrote:
> Hi,
>
> We had a failure in upgrade suite for 002_bootstrap.add_hosts. I am not
> seeing any error that can suggest on an issue in engine.
>
> I can see in the host messages host that we have stopped writing to the log
> for 15 minutes and it may suggest that there is something that is keeping
> the host from starting which causes us to fail the test on timeout.
>
> However, i can use some help in determining the cause for this failure and
> weather its connected to the bootstrap_add_host test in upgrade.
>
> Link to suspected patches: As I said, I do not think its related, but this
> is the patch that was reported.
>
> https://gerrit.ovirt.org/#/c/83854/
>
>
> Link to Job:
>
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/
>
>
> Link to all logs:
>
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifact/
>
>
> (Relevant) error snippet from the log:
>
> <error>
>
> Test error:
>
> Error Message
>
> False != True after 900 seconds
>
> Stacktrace
>
> Traceback (most recent call last):
> File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
> testMethod()
> File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in
runTest
> self.test(*self.arg)
> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 129,
in
> wrapped_test
> test()
> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 59,
in
> wrapper
> return func(get_test_prefix(), *args, **kwargs)
> File
>
"/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/upgrade-from-release-suite-master/test-scenarios-after-upgrade/002_bootstrap.py",
> line 187, in add_hosts
> testlib.assert_true_within(_host_is_up_4, timeout=15*60)
> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 263,
in
> assert_true_within
> assert_equals_within(func, True, timeout, allowed_exceptions)
> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 237,
in
> assert_equals_within
> '%s != %s after %s seconds' % (res, value, timeout)
> AssertionError: False != True after 900 seconds
>
Hi,
It took me way too long to find the log file that includes the above
stack trace. There is a known bug that pressing '(all files in zip)' does
not get all of them, only some. If we can't fix it, please add something
that will create such a zip/tar/whatever as part of the job, so that we
do not rely on jenkins.
Something causes things to be very slow, no idea what in particular,
but could not find a real problem.
Since we timed out and killed the engine in the middle of host-deploy,
we do not have full logs of it. These are copied to the engine from the
host only after it finishes. Before that, the log is written on the host
in /tmp. We might want to make ost collect that as well, to help debug
similar cases.
What we can see in engine log is that we start installing the host [1]:
2017-11-13 11:00:12,331-05 INFO
[org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
(EE-ManagedThreadFactory-engine-Thread-1) [45082420] Before
Installation host 83090668-908c-4f49-8690-5348ec12f931,
lago-upgrade-from-release-suite-master-host0
2017-11-13 11:00:12,354-05 INFO
[org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
(EE-ManagedThreadFactory-engine-Thread-1) [45082420] START,
SetVdsStatusVDSCommand(HostName =
lago-upgrade-from-release-suite-master-host0,
SetVdsStatusVDSCommandParameters:{hostId='83090668-908c-4f49-8690-5348ec12f931',
status='Installing', nonOperationalReason='NONE',
stopSpmFailureLogged='false', maintenanceReason='null'}), log id:
22a831f7
First line from host-deploy is:
2017-11-13 11:00:13,335-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
Initializing.
which is one second later, ok.
...
2017-11-13 11:00:13,459-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
Environment packages setup.
It goes install (immediately) packages that it needs for itself,
in this case it updates the package 'dmidecode', from 2.12-9
to 3.0-5. I guess our image is a bit old.
...
2017-11-13 11:00:19,516-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Verify: 2/2: dmidecode.x86_64 1:2.12-9.el7 - ud.
So it took (the equivalent of 'yum update dmidecode') 6 seconds.
Reasonable.
...
Later on, it starts installing/updating the actual packages it
should install/update. Starts with:
2017-11-13 11:00:24,982-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Status: Downloading Packages.
Then there are many lines about each package download. First is:
2017-11-13 11:00:25,049-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Download/Verify: GeoIP-1.5.0-11.el7.x86_64.
Last is:
2017-11-13 11:00:43,790-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
Download/Verify: zlib-1.2.7-17.el7.x86_64.
Later we see it updates 570 packages. So downloading 570 packages
took ~ 20 seconds, good too. Then it installs them. First is:
2017-11-13 11:00:46,114-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 1/570: libgcc-4.8.5-16.el7.x86_64.
And then many similar ones. I only skimmed through them, trying to
find large gaps - didn't write a script - and a large one I find is:
2017-11-13 11:10:04,522-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
updated: 506/570: audit.
2017-11-13 11:13:06,483-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
updated: 507/570: openssl-libs.
In between these two lines, there are a few unrelated ones, from some
other engine thread. So something caused it to need 3 minutes to install
openssl-libs.
A wild guess: Perhaps we have low entropy, and openssl does something
that needs entropy?
Checking engine-setup log there [2], I see that the following command
took almost 1.5 minutes to run:
2017-11-13 10:58:19,459-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.executeRaw:813 execute:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass'), executable='None',
cwd='None',
env={'pass': '**FILTERED**', 'LESSOPEN':
'||/usr/bin/lesspipe.sh %s',
'SSH_CLIENT': '192.168.200.1 52372 22',
'SELINUX_USE_CURRENT_RANGE':
'', 'LOGNAME': 'root', 'USER': 'root',
'OVIRT_ENGINE_JAVA_HOME':
u'/usr/lib/jvm/jre', 'PATH':
'/opt/rh/rh-postgresql95/root/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin',
'HOME': '/root', 'OVIRT_JBOSS_HOME':
'/usr/share/ovirt-engine-wildfly', 'LD_LIBRARY_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64', 'LANG': 'en_US.UTF-8',
'SHELL': '/bin/bash', 'LIBRARY_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64', 'SHLVL': '4',
'POSTGRESQLENV':
'COMMAND/pg_dump=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_dump
COMMAND/psql=str:/opt/rh/rh-postgresql95/root/usr/bin/psql
COMMAND/pg_restore=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_restore
COMMAND/postgresql-setup=str:/opt/rh/rh-postgresql95/root/usr/bin/postgresql-setup
OVESETUP_PROVISIONING/postgresService=str:rh-postgresql95-postgresql
OVESETUP_PROVISIONING/postgresConf=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/postgresql.conf
OVESETUP_PROVISIONING/postgresPgHba=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/pg_hba.conf
OVESETUP_PROVISIONING/postgresPgVersion=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/PG_VERSION',
'MANPATH': '/opt/rh/rh-postgresql95/root/usr/share/man:',
'X_SCLS':
'rh-postgresql95 ', 'XDG_RUNTIME_DIR': '/run/user/0',
'OVIRT_ENGINE_JAVA_HOME_FORCE': '1', 'PYTHONPATH':
'/usr/share/ovirt-engine/setup/bin/..::', 'SELINUX_ROLE_REQUESTED':
'', 'MAIL': '/var/mail/root', 'PKG_CONFIG_PATH':
'/opt/rh/rh-postgresql95/root/usr/lib64/pkgconfig', 'XDG_SESSION_ID':
'14', 'sclenv': 'rh-postgresql95', 'XDG_CONFIG_DIRS':
'/etc/opt/rh/rh-postgresql95/xdg:/etc/xdg', 'JAVACONFDIRS':
'/etc/opt/rh/rh-postgresql95/java:/etc/java',
'SELINUX_LEVEL_REQUESTED': '', 'XDG_DATA_DIRS':
'/opt/rh/rh-postgresql95/root/usr/share', 'PWD': '/root',
'CPATH':
'/opt/rh/rh-postgresql95/root/usr/include', 'OTOPI_LOGFILE':
'/var/log/ovirt-engine/setup/ovirt-engine-setup-20171113105548-qrc7zo.log',
'SSH_CONNECTION': '192.168.200.1 52372 192.168.200.3 22',
'OTOPI_EXECDIR': '/root'}
2017-11-13 10:59:43,545-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.executeRaw:863 execute-result:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass'), rc=0
2017-11-13 10:59:43,546-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.execute:921 execute-output:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass') stdout:
eyJhcnRpZmFjdCI6IkVudmVsb3BlUEJFIiwic2FsdCI6ImNjSmhFbHRnUEJxeUlNTUJSaU1OdFRYL3M0RGRJT1hOSWJjV2F1NFZGT0U9Iiwic2VjcmV0IjoiK2ZlTzVyZm9kNGlsVmZLRENaRjdseVVQZHZnWnBTWUF0cnBYUWVpQnJaTT0iLCJ2ZXJzaW9uIjoiMSIsIml0ZXJhdGlvbnMiOiI0MDAwIiwiYWxnb3JpdGhtIjoiUEJLREYyV2l0aEhtYWNTSEExIn0=
2017-11-13 10:59:43,546-0500 DEBUG
otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
plugin.execute:926 execute-output:
('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
'pbe-encode', '--password=env:pass') stderr:
This is almost always due to not enough entropy.
So please check if everything - from physical machines to
lago/ost/libvirt/etc., makes sure to supply all VMs enough
entropy. We usually do this using virtio-rng.
[1]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
[2]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
> lago log:
>
> 2017-11-13
> 15:31:23,212::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
> 2017-11-13
> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13
> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-engine
> 2017-11-13
> 15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
> Unable to connect to port 22 on 192.168.200.3
> 2017-11-13
> 15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
> Unable to connect to port 22 on 192.168.200.2
> 2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-engine:
> Timed out (in 4 s) trying to ssh to
> lago-upgrade-from-release-suite-master-engine
> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-host0:
> Timed out (in 4 s) trying to ssh to
> lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13
> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:28,224::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-engine
> 2017-11-13 15:31:28,225::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
> Unable to connect to port 22 on 192.168.200.2
> 2017-11-13 15:31:29,228::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:29,228::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-host0:
> Timed out (in 1 s) trying to ssh to
> lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
> Unable to connect to port 22 on 192.168.200.3
> 2017-11-13 15:31:30,229::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13
> 15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:30,230::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-engine:
> Timed out (in 2 s) trying to ssh to
> lago-upgrade-from-release-suite-master-engine
> 2017-11-13 15:31:30,230::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
> Unable to connect to port 22 on 192.168.200.2
> 2017-11-13
> 15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:31,232::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-engine
> 2017-11-13
> 15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
> Unable to connect to port 22 on 192.168.200.3
> 2017-11-13 15:31:31,232::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:31,233::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-host0:
> Timed out (in 1 s) trying to ssh to
> lago-upgrade-from-release-suite-master-host0
> 2017-11-13 15:31:32,234::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:32,234::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-engine:
> Timed out (in 1 s) trying to ssh to
> lago-upgrade-from-release-suite-master-engine
> 2017-11-13
> 15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:32,234::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
> Unable to connect to port 22 on 192.168.200.2
> 2017-11-13
> 15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:33,235::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-engine
> 2017-11-13 15:31:33,236::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13
> 15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
> Unable to connect to port 22 on 192.168.200.3
> 2017-11-13 15:31:33,237::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-host0:
> Timed out (in 1 s) trying to ssh to
> lago-upgrade-from-release-suite-master-host0
> 2017-11-13 15:31:34,238::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
> lago-upgrade-from-release-suite-master-engine:
> 2017-11-13 15:31:34,238::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
> exception while sshing to lago-upgrade-from-release-suite-master-engine:
> Timed out (in 1 s) trying to ssh to
> lago-upgrade-from-release-suite-master-engine
> 2017-11-13
> 15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:34,239::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 1 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13 15:31:34,407::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:34,639::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb49adfa
> on lago-upgrade-from-release-suite-master-host0: true
> 2017-11-13 15:31:34,665::ssh.py::ssh::81::lago.ssh::DEBUG::Command bb49adfa
> on lago-upgrade-from-release-suite-master-host0 returned with 0
> 2017-11-13 15:31:34,665::ssh.py::wait_for_ssh::153::lago.ssh::DEBUG::Wait
> succeeded for ssh to lago-upgrade-from-release-suite-master-host0
> 2017-11-13
> 15:31:34,665::log_utils.py::__exit__::611::lago.prefix::INFO::ESC[32mSuccessESC[0m
> (in 0:00:11)
> 2017-11-13
> 15:31:34,666::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
> 2017-11-13
> 15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:34,667::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
> got 100 tries for lago-upgrade-from-release-suite-master-host0
> 2017-11-13 15:31:34,805::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
> lago-upgrade-from-release-suite-master-host0:
> 2017-11-13 15:31:34,906::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb724bf2
> on lago-upgrade-from-release-suite-master-host0: bash -s < "set -xe
> DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')
>
>
> from host:
>
> ions. Proceeding anyway.
> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
> Configuration file /usr/lib/systemd/system/ebtables.service is marked
> executable. Please remove executable permission bits. Proceeding anyway.
> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
> Configuration file /usr/lib/systemd/system/wpa_supplicant.service is marked
> executable. Please remove executable permission bits. Proceeding anyway.
> Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0 yum[1294]:
> Updated: iptables-1.4.21-18.2.el7_4.x86_64
> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd-logind:
> Removed session 3.
> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
> Removed slice user-0.slice.
> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
> Stopping user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Created slice user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Starting user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Started Session 4 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Starting Session 4 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
> New session 4 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
> Removed session 4.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Removed slice user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Stopping user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Created slice user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Starting user-0.slice.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Started Session 5 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
> Starting Session 5 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
> New session 5 of user root.
> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
> Removed session 5.
> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
> Removed slice user-0.slice.
> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
> Stopping user-0.slice.
> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
> Starting Cleanup of Temporary Directories...
> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
> Started Cleanup of Temporary Directories.
> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
> DHCPREQUEST on eth0 to 192.168.200.1 port 67 (xid=0x564629cb)
> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
> DHCPACK from 192.168.200.1 (xid=0x564629cb)
>
> </error>
>
>
8 a.m.
On Wed, Nov 15, 2017 at 1:35 PM, Dafna Ron <dron(a)redhat.com> wrote:
Didi,
Thank you for your detailed explanation and for taking the time to debug
this issue.
I opened the following Jira's:
1. for increasing entropy in the hosts:
https://ovirt-jira.atlassian.net/browse/OVIRT-1763
I do not think anymore this is the main reason for slowness, although
it might still be useful to verify/improve.
yuvalt pointed out in a private discussion that openssl lib does nothing
related to random numbers in its pre/post install scripts.
It does call ldconfig, as do several other packages, which can take
quite a lot of time. Some took less. 3 minutes is definitely not
reasonable.
Also see this, from engine log:
2017-11-13 11:07:17,026-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 398/570: 1:NetworkManager-team-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:30,573-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
obsoleting: 399/570: 1:NetworkManager-ppp-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:45,137-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 400/570: 1:NetworkManager-tui-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:57,842-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 401/570: audit-2.7.6-3.el7.x86_64.
That's ~ 15 seconds per package, and the first 3 have no scripts at all.
I'd say there is some serious storage issue there - bad disk, loaded
storage network/hardware, something like this.
2. I added a comment to the not all logs are downloaded Jira regarded a
workaround which would save the logs on a different location:
https://ovirt-jira.atlassian.net/browse/OVIRT-1583
3. adding /tmp logs to the job logs:
https://ovirt-jira.atlassian.net/browse/OVIRT-1764
Again, thank you for your help Didi.
Dafna
On 11/15/2017 09:01 AM, Yedidyah Bar David wrote:
> On Tue, Nov 14, 2017 at 5:48 PM, Dafna Ron <dron(a)redhat.com> wrote:
>> Hi,
>>
>> We had a failure in upgrade suite for 002_bootstrap.add_hosts. I am not
>> seeing any error that can suggest on an issue in engine.
>>
>> I can see in the host messages host that we have stopped writing to the log
>> for 15 minutes and it may suggest that there is something that is keeping
>> the host from starting which causes us to fail the test on timeout.
>>
>> However, i can use some help in determining the cause for this failure and
>> weather its connected to the bootstrap_add_host test in upgrade.
>>
>> Link to suspected patches: As I said, I do not think its related, but this
>> is the patch that was reported.
>>
>> https://gerrit.ovirt.org/#/c/83854/
>>
>>
>> Link to Job:
>>
>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/
>>
>>
>> Link to all logs:
>>
>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifact/
>>
>>
>> (Relevant) error snippet from the log:
>>
>> <error>
>>
>> Test error:
>>
>> Error Message
>>
>> False != True after 900 seconds
>>
>> Stacktrace
>>
>> Traceback (most recent call last):
>> File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
>> testMethod()
>> File "/usr/lib/python2.7/site-packages/nose/case.py", line 197, in
runTest
>> self.test(*self.arg)
>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
129, in
>> wrapped_test
>> test()
>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
59, in
>> wrapper
>> return func(get_test_prefix(), *args, **kwargs)
>> File
>>
"/home/jenkins/workspace/ovirt-master_change-queue-tester/ovirt-system-tests/upgrade-from-release-suite-master/test-scenarios-after-upgrade/002_bootstrap.py",
>> line 187, in add_hosts
>> testlib.assert_true_within(_host_is_up_4, timeout=15*60)
>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
263, in
>> assert_true_within
>> assert_equals_within(func, True, timeout, allowed_exceptions)
>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line
237, in
>> assert_equals_within
>> '%s != %s after %s seconds' % (res, value, timeout)
>> AssertionError: False != True after 900 seconds
>>
> Hi,
>
> It took me way too long to find the log file that includes the above
> stack trace. There is a known bug that pressing '(all files in zip)' does
> not get all of them, only some. If we can't fix it, please add something
> that will create such a zip/tar/whatever as part of the job, so that we
> do not rely on jenkins.
>
> Something causes things to be very slow, no idea what in particular,
> but could not find a real problem.
>
> Since we timed out and killed the engine in the middle of host-deploy,
> we do not have full logs of it. These are copied to the engine from the
> host only after it finishes. Before that, the log is written on the host
> in /tmp. We might want to make ost collect that as well, to help debug
> similar cases.
>
> What we can see in engine log is that we start installing the host [1]:
>
> 2017-11-13 11:00:12,331-05 INFO
> [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
> (EE-ManagedThreadFactory-engine-Thread-1) [45082420] Before
> Installation host 83090668-908c-4f49-8690-5348ec12f931,
> lago-upgrade-from-release-suite-master-host0
> 2017-11-13 11:00:12,354-05 INFO
> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
> (EE-ManagedThreadFactory-engine-Thread-1) [45082420] START,
> SetVdsStatusVDSCommand(HostName =
> lago-upgrade-from-release-suite-master-host0,
>
SetVdsStatusVDSCommandParameters:{hostId='83090668-908c-4f49-8690-5348ec12f931',
> status='Installing', nonOperationalReason='NONE',
> stopSpmFailureLogged='false', maintenanceReason='null'}), log id:
> 22a831f7
>
> First line from host-deploy is:
>
> 2017-11-13 11:00:13,335-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
> Initializing.
>
> which is one second later, ok.
>
> ...
>
> 2017-11-13 11:00:13,459-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
> Environment packages setup.
>
> It goes install (immediately) packages that it needs for itself,
> in this case it updates the package 'dmidecode', from 2.12-9
> to 3.0-5. I guess our image is a bit old.
>
> ...
>
> 2017-11-13 11:00:19,516-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> Verify: 2/2: dmidecode.x86_64 1:2.12-9.el7 - ud.
>
> So it took (the equivalent of 'yum update dmidecode') 6 seconds.
> Reasonable.
>
> ...
>
> Later on, it starts installing/updating the actual packages it
> should install/update. Starts with:
>
> 2017-11-13 11:00:24,982-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> Status: Downloading Packages.
>
> Then there are many lines about each package download. First is:
>
> 2017-11-13 11:00:25,049-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> Download/Verify: GeoIP-1.5.0-11.el7.x86_64.
>
> Last is:
>
> 2017-11-13 11:00:43,790-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> Download/Verify: zlib-1.2.7-17.el7.x86_64.
>
> Later we see it updates 570 packages. So downloading 570 packages
> took ~ 20 seconds, good too. Then it installs them. First is:
>
> 2017-11-13 11:00:46,114-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> update: 1/570: libgcc-4.8.5-16.el7.x86_64.
>
> And then many similar ones. I only skimmed through them, trying to
> find large gaps - didn't write a script - and a large one I find is:
>
> 2017-11-13 11:10:04,522-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> updated: 506/570: audit.
>
> 2017-11-13 11:13:06,483-05 INFO
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
> updated: 507/570: openssl-libs.
>
> In between these two lines, there are a few unrelated ones, from some
> other engine thread. So something caused it to need 3 minutes to install
> openssl-libs.
>
> A wild guess: Perhaps we have low entropy, and openssl does something
> that needs entropy?
>
> Checking engine-setup log there [2], I see that the following command
> took almost 1.5 minutes to run:
>
> 2017-11-13 10:58:19,459-0500 DEBUG
> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
> plugin.executeRaw:813 execute:
> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
> 'pbe-encode', '--password=env:pass'), executable='None',
cwd='None',
> env={'pass': '**FILTERED**', 'LESSOPEN':
'||/usr/bin/lesspipe.sh %s',
> 'SSH_CLIENT': '192.168.200.1 52372 22',
'SELINUX_USE_CURRENT_RANGE':
> '', 'LOGNAME': 'root', 'USER': 'root',
'OVIRT_ENGINE_JAVA_HOME':
> u'/usr/lib/jvm/jre', 'PATH':
>
'/opt/rh/rh-postgresql95/root/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin',
> 'HOME': '/root', 'OVIRT_JBOSS_HOME':
> '/usr/share/ovirt-engine-wildfly', 'LD_LIBRARY_PATH':
> '/opt/rh/rh-postgresql95/root/usr/lib64', 'LANG':
'en_US.UTF-8',
> 'SHELL': '/bin/bash', 'LIBRARY_PATH':
> '/opt/rh/rh-postgresql95/root/usr/lib64', 'SHLVL': '4',
> 'POSTGRESQLENV':
> 'COMMAND/pg_dump=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_dump
> COMMAND/psql=str:/opt/rh/rh-postgresql95/root/usr/bin/psql
> COMMAND/pg_restore=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_restore
>
COMMAND/postgresql-setup=str:/opt/rh/rh-postgresql95/root/usr/bin/postgresql-setup
> OVESETUP_PROVISIONING/postgresService=str:rh-postgresql95-postgresql
>
OVESETUP_PROVISIONING/postgresConf=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/postgresql.conf
>
OVESETUP_PROVISIONING/postgresPgHba=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/pg_hba.conf
>
OVESETUP_PROVISIONING/postgresPgVersion=str:/var/opt/rh/rh-postgresql95/lib/pgsql/data/PG_VERSION',
> 'MANPATH': '/opt/rh/rh-postgresql95/root/usr/share/man:',
'X_SCLS':
> 'rh-postgresql95 ', 'XDG_RUNTIME_DIR': '/run/user/0',
> 'OVIRT_ENGINE_JAVA_HOME_FORCE': '1', 'PYTHONPATH':
> '/usr/share/ovirt-engine/setup/bin/..::', 'SELINUX_ROLE_REQUESTED':
> '', 'MAIL': '/var/mail/root', 'PKG_CONFIG_PATH':
> '/opt/rh/rh-postgresql95/root/usr/lib64/pkgconfig',
'XDG_SESSION_ID':
> '14', 'sclenv': 'rh-postgresql95',
'XDG_CONFIG_DIRS':
> '/etc/opt/rh/rh-postgresql95/xdg:/etc/xdg', 'JAVACONFDIRS':
> '/etc/opt/rh/rh-postgresql95/java:/etc/java',
> 'SELINUX_LEVEL_REQUESTED': '', 'XDG_DATA_DIRS':
> '/opt/rh/rh-postgresql95/root/usr/share', 'PWD': '/root',
'CPATH':
> '/opt/rh/rh-postgresql95/root/usr/include', 'OTOPI_LOGFILE':
> '/var/log/ovirt-engine/setup/ovirt-engine-setup-20171113105548-qrc7zo.log',
> 'SSH_CONNECTION': '192.168.200.1 52372 192.168.200.3 22',
> 'OTOPI_EXECDIR': '/root'}
> 2017-11-13 10:59:43,545-0500 DEBUG
> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
> plugin.executeRaw:863 execute-result:
> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
> 'pbe-encode', '--password=env:pass'), rc=0
> 2017-11-13 10:59:43,546-0500 DEBUG
> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
> plugin.execute:921 execute-output:
> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
> 'pbe-encode', '--password=env:pass') stdout:
>
eyJhcnRpZmFjdCI6IkVudmVsb3BlUEJFIiwic2FsdCI6ImNjSmhFbHRnUEJxeUlNTUJSaU1OdFRYL3M0RGRJT1hOSWJjV2F1NFZGT0U9Iiwic2VjcmV0IjoiK2ZlTzVyZm9kNGlsVmZLRENaRjdseVVQZHZnWnBTWUF0cnBYUWVpQnJaTT0iLCJ2ZXJzaW9uIjoiMSIsIml0ZXJhdGlvbnMiOiI0MDAwIiwiYWxnb3JpdGhtIjoiUEJLREYyV2l0aEhtYWNTSEExIn0=
>
> 2017-11-13 10:59:43,546-0500 DEBUG
> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
> plugin.execute:926 execute-output:
> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
> 'pbe-encode', '--password=env:pass') stderr:
>
> This is almost always due to not enough entropy.
>
> So please check if everything - from physical machines to
> lago/ost/libvirt/etc., makes sure to supply all VMs enough
> entropy. We usually do this using virtio-rng.
>
> [1]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
> [2]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/artifa...
>
>> lago log:
>>
>> 2017-11-13
>> 15:31:23,212::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
>> 2017-11-13
>> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13
>> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 15:31:23,213::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>> 2017-11-13
>> 15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
>> Unable to connect to port 22 on 192.168.200.3
>> 2017-11-13
>> 15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
>> Unable to connect to port 22 on 192.168.200.2
>> 2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:27,222::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-engine:
>> Timed out (in 4 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-engine
>> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-host0:
>> Timed out (in 4 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13
>> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:28,224::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>> 2017-11-13 15:31:28,225::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>> 15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
>> Unable to connect to port 22 on 192.168.200.2
>> 2017-11-13 15:31:29,228::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:29,228::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-host0:
>> Timed out (in 1 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>> 15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
>> Unable to connect to port 22 on 192.168.200.3
>> 2017-11-13 15:31:30,229::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13
>> 15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:30,230::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-engine:
>> Timed out (in 2 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-engine
>> 2017-11-13 15:31:30,230::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>> 15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
>> Unable to connect to port 22 on 192.168.200.2
>> 2017-11-13
>> 15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:31,232::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>> 2017-11-13
>> 15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
>> Unable to connect to port 22 on 192.168.200.3
>> 2017-11-13 15:31:31,232::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:31,233::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-host0:
>> Timed out (in 1 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 15:31:32,234::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:32,234::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-engine:
>> Timed out (in 1 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-engine
>> 2017-11-13
>> 15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:32,234::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>> 15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno None]
>> Unable to connect to port 22 on 192.168.200.2
>> 2017-11-13
>> 15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:33,235::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>> 2017-11-13 15:31:33,236::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13
>> 15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket error
>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno None]
>> Unable to connect to port 22 on 192.168.200.3
>> 2017-11-13 15:31:33,237::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-host0:
>> Timed out (in 1 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 15:31:34,238::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
>> lago-upgrade-from-release-suite-master-engine:
>> 2017-11-13 15:31:34,238::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG::Got
>> exception while sshing to lago-upgrade-from-release-suite-master-engine:
>> Timed out (in 1 s) trying to ssh to
>> lago-upgrade-from-release-suite-master-engine
>> 2017-11-13
>> 15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:34,239::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 15:31:34,407::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:34,639::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb49adfa
>> on lago-upgrade-from-release-suite-master-host0: true
>> 2017-11-13 15:31:34,665::ssh.py::ssh::81::lago.ssh::DEBUG::Command bb49adfa
>> on lago-upgrade-from-release-suite-master-host0 returned with 0
>> 2017-11-13 15:31:34,665::ssh.py::wait_for_ssh::153::lago.ssh::DEBUG::Wait
>> succeeded for ssh to lago-upgrade-from-release-suite-master-host0
>> 2017-11-13
>>
15:31:34,665::log_utils.py::__exit__::611::lago.prefix::INFO::ESC[32mSuccessESC[0m
>> (in 0:00:11)
>> 2017-11-13
>> 15:31:34,666::log_utils.py::__enter__::600::lago.prefix::INFO::ESC[0mESC[0m
>> 2017-11-13
>> 15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:34,667::ssh.py::get_ssh_client::339::lago.ssh::DEBUG::Still
>> got 100 tries for lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 15:31:34,805::log_utils.py::__exit__::611::lago.ssh::DEBUG::end
>> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
>> lago-upgrade-from-release-suite-master-host0:
>> 2017-11-13 15:31:34,906::ssh.py::ssh::58::lago.ssh::DEBUG::Running bb724bf2
>> on lago-upgrade-from-release-suite-master-host0: bash -s < "set -xe
>> DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')
>>
>>
>> from host:
>>
>> ions. Proceeding anyway.
>> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
>> Configuration file /usr/lib/systemd/system/ebtables.service is marked
>> executable. Please remove executable permission bits. Proceeding anyway.
>> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
>> Configuration file /usr/lib/systemd/system/wpa_supplicant.service is marked
>> executable. Please remove executable permission bits. Proceeding anyway.
>> Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0 yum[1294]:
>> Updated: iptables-1.4.21-18.2.el7_4.x86_64
>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd-logind:
>> Removed session 3.
>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
>> Removed slice user-0.slice.
>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
>> Stopping user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Created slice user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Starting user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Started Session 4 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Starting Session 4 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
>> New session 4 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
>> Removed session 4.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Removed slice user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Stopping user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Created slice user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Starting user-0.slice.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Started Session 5 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>> Starting Session 5 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
>> New session 5 of user root.
>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd-logind:
>> Removed session 5.
>> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
>> Removed slice user-0.slice.
>> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
>> Stopping user-0.slice.
>> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
>> Starting Cleanup of Temporary Directories...
>> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
>> Started Cleanup of Temporary Directories.
>> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
>> DHCPREQUEST on eth0 to 192.168.200.1 port 67 (xid=0x564629cb)
>> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0 dhclient[906]:
>> DHCPACK from 192.168.200.1 (xid=0x564629cb)
>>
>> </error>
>>
>>
>
>
--
Didi
8:48 a.m.
On Wed, Nov 15, 2017 at 4:00 PM, Yedidyah Bar David <didi(a)redhat.com> wrote:
On Wed, Nov 15, 2017 at 1:35 PM, Dafna Ron <dron(a)redhat.com>
wrote:
> Didi,
>
> Thank you for your detailed explanation and for taking the time to debug
> this issue.
>
> I opened the following Jira's:
>
> 1. for increasing entropy in the hosts:
> https://ovirt-jira.atlassian.net/browse/OVIRT-1763
I do not think anymore this is the main reason for slowness, although
it might still be useful to verify/improve.
yuvalt pointed out in a private discussion that openssl lib does nothing
related to random numbers in its pre/post install scripts.
It does call ldconfig, as do several other packages, which can take
quite a lot of time. Some took less. 3 minutes is definitely not
reasonable.
Also see this, from engine log:
2017-11-13 11:07:17,026-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 398/570: 1:NetworkManager-team-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:30,573-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
obsoleting: 399/570: 1:NetworkManager-ppp-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:45,137-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 400/570: 1:NetworkManager-tui-1.8.0-11.el7_4.x86_64.
2017-11-13 11:07:57,842-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
Installing Host lago-upgrade-from-release-suite-master-host0. Yum
update: 401/570: audit-2.7.6-3.el7.x86_64.
That's ~ 15 seconds per package, and the first 3 have no scripts at all.
I'd say there is some serious storage issue there - bad disk, loaded
storage network/hardware, something like this.
That was my guess as well. Sometimes selinux relabeling takes time (I
believe ovirt console does that).
Y.
>
> 2. I added a comment to the not all logs are downloaded Jira regarded a
> workaround which would save the logs on a different location:
> https://ovirt-jira.atlassian.net/browse/OVIRT-1583
>
> 3. adding /tmp logs to the job logs:
> https://ovirt-jira.atlassian.net/browse/OVIRT-1764
>
> Again, thank you for your help Didi.
>
> Dafna
>
>
>
> On 11/15/2017 09:01 AM, Yedidyah Bar David wrote:
>> On Tue, Nov 14, 2017 at 5:48 PM, Dafna Ron <dron(a)redhat.com> wrote:
>>> Hi,
>>>
>>> We had a failure in upgrade suite for 002_bootstrap.add_hosts. I am not
>>> seeing any error that can suggest on an issue in engine.
>>>
>>> I can see in the host messages host that we have stopped writing to
the log
>>> for 15 minutes and it may suggest that there is something that is
keeping
>>> the host from starting which causes us to fail the test on timeout.
>>>
>>> However, i can use some help in determining the cause for this
failure and
>>> weather its connected to the bootstrap_add_host test in upgrade.
>>>
>>> Link to suspected patches: As I said, I do not think its related, but
this
>>> is the patch that was reported.
>>>
>>> https://gerrit.ovirt.org/#/c/83854/
>>>
>>>
>>> Link to Job:
>>>
>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3795/
>>>
>>>
>>> Link to all logs:
>>>
>>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/3795/artifact/
>>>
>>>
>>> (Relevant) error snippet from the log:
>>>
>>> <error>
>>>
>>> Test error:
>>>
>>> Error Message
>>>
>>> False != True after 900 seconds
>>>
>>> Stacktrace
>>>
>>> Traceback (most recent call last):
>>> File "/usr/lib64/python2.7/unittest/case.py", line 369, in run
>>> testMethod()
>>> File "/usr/lib/python2.7/site-packages/nose/case.py", line 197,
in
runTest
>>> self.test(*self.arg)
>>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py",
line
129, in
>>> wrapped_test
>>> test()
>>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py",
line
59, in
>>> wrapper
>>> return func(get_test_prefix(), *args, **kwargs)
>>> File
>>> "/home/jenkins/workspace/ovirt-master_change-queue-
tester/ovirt-system-tests/upgrade-from-release-suite-
master/test-scenarios-after-upgrade/002_bootstrap.py",
>>> line 187, in add_hosts
>>> testlib.assert_true_within(_host_is_up_4, timeout=15*60)
>>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py",
line
263, in
>>> assert_true_within
>>> assert_equals_within(func, True, timeout, allowed_exceptions)
>>> File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py",
line
237, in
>>> assert_equals_within
>>> '%s != %s after %s seconds' % (res, value, timeout)
>>> AssertionError: False != True after 900 seconds
>>>
>> Hi,
>>
>> It took me way too long to find the log file that includes the above
>> stack trace. There is a known bug that pressing '(all files in zip)'
does
>> not get all of them, only some. If we can't fix it, please add something
>> that will create such a zip/tar/whatever as part of the job, so that we
>> do not rely on jenkins.
>>
>> Something causes things to be very slow, no idea what in particular,
>> but could not find a real problem.
>>
>> Since we timed out and killed the engine in the middle of host-deploy,
>> we do not have full logs of it. These are copied to the engine from the
>> host only after it finishes. Before that, the log is written on the host
>> in /tmp. We might want to make ost collect that as well, to help debug
>> similar cases.
>>
>> What we can see in engine log is that we start installing the host [1]:
>>
>> 2017-11-13 11:00:12,331-05 INFO
>> [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand]
>> (EE-ManagedThreadFactory-engine-Thread-1) [45082420] Before
>> Installation host 83090668-908c-4f49-8690-5348ec12f931,
>> lago-upgrade-from-release-suite-master-host0
>> 2017-11-13 11:00:12,354-05 INFO
>> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
>> (EE-ManagedThreadFactory-engine-Thread-1) [45082420] START,
>> SetVdsStatusVDSCommand(HostName =
>> lago-upgrade-from-release-suite-master-host0,
>> SetVdsStatusVDSCommandParameters:{hostId='83090668-908c-
4f49-8690-5348ec12f931',
>> status='Installing', nonOperationalReason='NONE',
>> stopSpmFailureLogged='false', maintenanceReason='null'}), log
id:
>> 22a831f7
>>
>> First line from host-deploy is:
>>
>> 2017-11-13 11:00:13,335-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
>> Initializing.
>>
>> which is one second later, ok.
>>
>> ...
>>
>> 2017-11-13 11:00:13,459-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Stage:
>> Environment packages setup.
>>
>> It goes install (immediately) packages that it needs for itself,
>> in this case it updates the package 'dmidecode', from 2.12-9
>> to 3.0-5. I guess our image is a bit old.
>>
>> ...
>>
>> 2017-11-13 11:00:19,516-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> Verify: 2/2: dmidecode.x86_64 1:2.12-9.el7 - ud.
>>
>> So it took (the equivalent of 'yum update dmidecode') 6 seconds.
>> Reasonable.
>>
>> ...
>>
>> Later on, it starts installing/updating the actual packages it
>> should install/update. Starts with:
>>
>> 2017-11-13 11:00:24,982-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> Status: Downloading Packages.
>>
>> Then there are many lines about each package download. First is:
>>
>> 2017-11-13 11:00:25,049-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> Download/Verify: GeoIP-1.5.0-11.el7.x86_64.
>>
>> Last is:
>>
>> 2017-11-13 11:00:43,790-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> Download/Verify: zlib-1.2.7-17.el7.x86_64.
>>
>> Later we see it updates 570 packages. So downloading 570 packages
>> took ~ 20 seconds, good too. Then it installs them. First is:
>>
>> 2017-11-13 11:00:46,114-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> update: 1/570: libgcc-4.8.5-16.el7.x86_64.
>>
>> And then many similar ones. I only skimmed through them, trying to
>> find large gaps - didn't write a script - and a large one I find is:
>>
>> 2017-11-13 11:10:04,522-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> updated: 506/570: audit.
>>
>> 2017-11-13 11:13:06,483-05 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (VdsDeploy) [45082420] EVENT_ID: VDS_INSTALL_IN_PROGRESS(509),
>> Installing Host lago-upgrade-from-release-suite-master-host0. Yum
>> updated: 507/570: openssl-libs.
>>
>> In between these two lines, there are a few unrelated ones, from some
>> other engine thread. So something caused it to need 3 minutes to install
>> openssl-libs.
>>
>> A wild guess: Perhaps we have low entropy, and openssl does something
>> that needs entropy?
>>
>> Checking engine-setup log there [2], I see that the following command
>> took almost 1.5 minutes to run:
>>
>> 2017-11-13 10:58:19,459-0500 DEBUG
>> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
>> plugin.executeRaw:813 execute:
>> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
>> 'pbe-encode', '--password=env:pass'), executable='None',
cwd='None',
>> env={'pass': '**FILTERED**', 'LESSOPEN':
'||/usr/bin/lesspipe.sh %s',
>> 'SSH_CLIENT': '192.168.200.1 52372 22',
'SELINUX_USE_CURRENT_RANGE':
>> '', 'LOGNAME': 'root', 'USER': 'root',
'OVIRT_ENGINE_JAVA_HOME':
>> u'/usr/lib/jvm/jre', 'PATH':
>> '/opt/rh/rh-postgresql95/root/usr/bin:/usr/local/sbin:/usr/
local/bin:/usr/sbin:/usr/bin',
>> 'HOME': '/root', 'OVIRT_JBOSS_HOME':
>> '/usr/share/ovirt-engine-wildfly', 'LD_LIBRARY_PATH':
>> '/opt/rh/rh-postgresql95/root/usr/lib64', 'LANG':
'en_US.UTF-8',
>> 'SHELL': '/bin/bash', 'LIBRARY_PATH':
>> '/opt/rh/rh-postgresql95/root/usr/lib64', 'SHLVL': '4',
>> 'POSTGRESQLENV':
>> 'COMMAND/pg_dump=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_dump
>> COMMAND/psql=str:/opt/rh/rh-postgresql95/root/usr/bin/psql
>> COMMAND/pg_restore=str:/opt/rh/rh-postgresql95/root/usr/bin/pg_restore
>> COMMAND/postgresql-setup=str:/opt/rh/rh-postgresql95/root/
usr/bin/postgresql-setup
>> OVESETUP_PROVISIONING/postgresService=str:rh-
postgresql95-postgresql
>> OVESETUP_PROVISIONING/postgresConf=str:/var/opt/rh/
rh-postgresql95/lib/pgsql/data/postgresql.conf
>> OVESETUP_PROVISIONING/postgresPgHba=str:/var/opt/rh/
rh-postgresql95/lib/pgsql/data/pg_hba.conf
>> OVESETUP_PROVISIONING/postgresPgVersion=str:/var/
opt/rh/rh-postgresql95/lib/pgsql/data/PG_VERSION',
>> 'MANPATH': '/opt/rh/rh-postgresql95/root/usr/share/man:',
'X_SCLS':
>> 'rh-postgresql95 ', 'XDG_RUNTIME_DIR': '/run/user/0',
>> 'OVIRT_ENGINE_JAVA_HOME_FORCE': '1', 'PYTHONPATH':
>> '/usr/share/ovirt-engine/setup/bin/..::',
'SELINUX_ROLE_REQUESTED':
>> '', 'MAIL': '/var/mail/root',
'PKG_CONFIG_PATH':
>> '/opt/rh/rh-postgresql95/root/usr/lib64/pkgconfig',
'XDG_SESSION_ID':
>> '14', 'sclenv': 'rh-postgresql95',
'XDG_CONFIG_DIRS':
>> '/etc/opt/rh/rh-postgresql95/xdg:/etc/xdg', 'JAVACONFDIRS':
>> '/etc/opt/rh/rh-postgresql95/java:/etc/java',
>> 'SELINUX_LEVEL_REQUESTED': '', 'XDG_DATA_DIRS':
>> '/opt/rh/rh-postgresql95/root/usr/share', 'PWD':
'/root', 'CPATH':
>> '/opt/rh/rh-postgresql95/root/usr/include', 'OTOPI_LOGFILE':
>> '/var/log/ovirt-engine/setup/ovirt-engine-setup-
20171113105548-qrc7zo.log',
>> 'SSH_CONNECTION': '192.168.200.1 52372 192.168.200.3 22',
>> 'OTOPI_EXECDIR': '/root'}
>> 2017-11-13 10:59:43,545-0500 DEBUG
>> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
>> plugin.executeRaw:863 execute-result:
>> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
>> 'pbe-encode', '--password=env:pass'), rc=0
>> 2017-11-13 10:59:43,546-0500 DEBUG
>> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
>> plugin.execute:921 execute-output:
>> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
>> 'pbe-encode', '--password=env:pass') stdout:
>> eyJhcnRpZmFjdCI6IkVudmVsb3BlUEJFIiwic2FsdCI6ImNjSmhFbHRnUEJx
eUlNTUJSaU1OdFRYL3M0RGRJT1hOSWJjV2F1NFZGT0U9Iiwic2VjcmV0Ijoi
K2ZlTzVyZm9kNGlsVmZLRENaRjdseVVQZHZnWnBTWUF0cnBYUWVpQnJaTT0i
LCJ2ZXJzaW9uIjoiMSIsIml0ZXJhdGlvbnMiOiI0MDAwIiwiYWxnb3JpdGht
IjoiUEJLREYyV2l0aEhtYWNTSEExIn0=
>>
>> 2017-11-13 10:59:43,546-0500 DEBUG
>> otopi.plugins.ovirt_engine_setup.ovirt_engine.config.sso
>> plugin.execute:926 execute-output:
>> ('/usr/share/ovirt-engine/bin/ovirt-engine-crypto-tool.sh',
>> 'pbe-encode', '--password=env:pass') stderr:
>>
>> This is almost always due to not enough entropy.
>>
>> So please check if everything - from physical machines to
>> lago/ost/libvirt/etc., makes sure to supply all VMs enough
>> entropy. We usually do this using virtio-rng.
>>
>> [1] http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/3795/artifact/exported-artifacts/upgrade-from-
release-suit-master-el7/test_logs/upgrade-from-release-
suite-master/post-002_bootstrap.py/lago-upgrade-from-release-suite-master-
engine/_var_log/ovirt-engine/engine.log
>> [2] http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/3795/artifact/exported-artifacts/upgrade-from-
release-suit-master-el7/test_logs/upgrade-from-release-
suite-master/post-002_bootstrap.py/lago-upgrade-from-release-suite-master-
engine/_var_log/ovirt-engine/setup/ovirt-engine-setup-
20171113105548-qrc7zo.log
>>
>>> lago log:
>>>
>>> 2017-11-13
>>> 15:31:23,212::log_utils.py::__enter__::600::lago.prefix::
INFO::ESC[0mESC[0m
>>> 2017-11-13
>>> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13
>>> 15:31:23,213::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:23,213::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13 15:31:23,213::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13
>>> 15:31:26,220::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.3
>>> 2017-11-13
>>> 15:31:26,221::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.2
>>> 2017-11-13 15:31:27,222::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:91372413-f7fd-4b72-85b9-9f5216ca7ae9:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:27,222::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:0468ed2f-b174-4d94-bc66-2b6e08087a86:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-engine:
>>> Timed out (in 4 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13 15:31:27,222::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-host0:
>>> Timed out (in 4 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13
>>> 15:31:28,224::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:28,224::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13 15:31:28,225::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:28,226::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.2
>>> 2017-11-13 15:31:29,228::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:afb01a46-6338-407f-b7c9-9d5c6b91404d:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:29,228::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-host0:
>>> Timed out (in 1 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:29,229::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.3
>>> 2017-11-13 15:31:30,229::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:fc88f641-b012-4636-a471-9ccaaf361a53:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13
>>> 15:31:30,230::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:30,230::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-engine:
>>> Timed out (in 2 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13 15:31:30,230::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:30,231::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.2
>>> 2017-11-13
>>> 15:31:31,231::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:31,232::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13
>>> 15:31:31,232::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.3
>>> 2017-11-13 15:31:31,232::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:9df5ddca-bbc4-485a-9f3a-b0b9a5bb5990:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:31,233::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-host0:
>>> Timed out (in 1 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13 15:31:32,234::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:53fe67da-a632-49fe-b697-e8a2c4cb7d23:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:32,234::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-engine:
>>> Timed out (in 1 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13
>>> 15:31:32,234::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:32,234::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:32,235::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-host0: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.2
>>> 2017-11-13
>>> 15:31:33,235::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:33,235::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13 15:31:33,236::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:1969bf5b-4e66-43d7-91c6-a28949e98fe8:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13
>>> 15:31:33,236::ssh.py::get_ssh_client::354::lago.ssh::DEBUG::Socket
error
>>> connecting to lago-upgrade-from-release-suite-master-engine: [Errno
None]
>>> Unable to connect to port 22 on 192.168.200.3
>>> 2017-11-13 15:31:33,237::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-host0:
>>> Timed out (in 1 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13 15:31:34,238::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:5fd0e3c3-d83c-46f9-9c88-bc739aa9c430:Get ssh client for
>>> lago-upgrade-from-release-suite-master-engine:
>>> 2017-11-13 15:31:34,238::ssh.py::wait_for_ssh::129::lago.ssh::DEBUG:
:Got
>>> exception while sshing to lago-upgrade-from-release-
suite-master-engine:
>>> Timed out (in 1 s) trying to ssh to
>>> lago-upgrade-from-release-suite-master-engine
>>> 2017-11-13
>>> 15:31:34,238::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:34,239::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 1 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13 15:31:34,407::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:22550d6e-c397-43dc-9691-c8d9debfe416:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:34,639::ssh.py::ssh::58::lago.ssh::DEBUG::Running
bb49adfa
>>> on lago-upgrade-from-release-suite-master-host0: true
>>> 2017-11-13 15:31:34,665::ssh.py::ssh::81::lago.ssh::DEBUG::Command
bb49adfa
>>> on lago-upgrade-from-release-suite-master-host0 returned with 0
>>> 2017-11-13 15:31:34,665::ssh.py::wait_for_ssh::153::lago.ssh::DEBUG:
:Wait
>>> succeeded for ssh to lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13
>>> 15:31:34,665::log_utils.py::__exit__::611::lago.prefix::
INFO::ESC[32mSuccessESC[0m
>>> (in 0:00:11)
>>> 2017-11-13
>>> 15:31:34,666::log_utils.py::__enter__::600::lago.prefix::
INFO::ESC[0mESC[0m
>>> 2017-11-13
>>> 15:31:34,666::log_utils.py::__enter__::600::lago.ssh::DEBUG::start
>>> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:34,667::ssh.py::get_ssh_
client::339::lago.ssh::DEBUG::Still
>>> got 100 tries for lago-upgrade-from-release-suite-master-host0
>>> 2017-11-13 15:31:34,805::log_utils.py::__
exit__::611::lago.ssh::DEBUG::end
>>> task:4e2a7421-28f7-4679-955f-7261fe377939:Get ssh client for
>>> lago-upgrade-from-release-suite-master-host0:
>>> 2017-11-13 15:31:34,906::ssh.py::ssh::58::lago.ssh::DEBUG::Running
bb724bf2
>>> on lago-upgrade-from-release-suite-master-host0: bash -s < "set -xe
>>> DIST=$(uname -r | sed -r 's/^.*\.([^\.]+)\.[^\.]+$/\1/')
>>>
>>>
>>> from host:
>>>
>>> ions. Proceeding anyway.
>>> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Configuration file /usr/lib/systemd/system/ebtables.service is marked
>>> executable. Please remove executable permission bits. Proceeding
anyway.
>>> Nov 13 10:31:34 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Configuration file /usr/lib/systemd/system/wpa_supplicant.service is
marked
>>> executable. Please remove executable permission bits. Proceeding
anyway.
>>> Nov 13 10:31:55 lago-upgrade-from-release-suite-master-host0
yum[1294]:
>>> Updated: iptables-1.4.21-18.2.el7_4.x86_64
>>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0
systemd-logind:
>>> Removed session 3.
>>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Removed slice user-0.slice.
>>> Nov 13 10:31:56 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Stopping user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Created slice user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Starting user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Started Session 4 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Starting Session 4 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind:
>>> New session 4 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind:
>>> Removed session 4.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Removed slice user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Stopping user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Created slice user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Starting user-0.slice.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Started Session 5 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Starting Session 5 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind:
>>> New session 5 of user root.
>>> Nov 13 10:44:00 lago-upgrade-from-release-suite-master-host0
systemd-logind:
>>> Removed session 5.
>>> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Removed slice user-0.slice.
>>> Nov 13 10:44:01 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Stopping user-0.slice.
>>> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Starting Cleanup of Temporary Directories...
>>> Nov 13 10:46:27 lago-upgrade-from-release-suite-master-host0 systemd:
>>> Started Cleanup of Temporary Directories.
>>> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]:
>>> DHCPREQUEST on eth0 to 192.168.200.1 port 67 (xid=0x564629cb)
>>> Nov 13 10:54:36 lago-upgrade-from-release-suite-master-host0
dhclient[906]:
>>> DHCPACK from 192.168.200.1 (xid=0x564629cb)
>>>
>>> </error>
>>>
>>>
>>
>>
>
--
Didi
2352
days inactive
2353
days old
4 comments
3 participants
participants (3)
-
Dafna Ron -
Yaniv Kaul -
Yedidyah Bar David