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