[ovirt-devel] OST CI: Time issue?

Hi all, I looked at failure of [1]. It timed out while waiting for the engine to be up, after restarting the engine VM. lago.log [2] has: 2020-01-20 04:16:06,026::008_restart_he_vm.py::_start_he_vm::173::root::INFO::Starting VM... ... 2020-01-20 04:16:09,823::008_restart_he_vm.py::_start_he_vm::178::root::INFO::Waiting for VM to be UP... ... 2020-01-20 04:16:25,113::008_restart_he_vm.py::_start_he_vm::186::root::INFO::VM is UP. 2020-01-20 04:16:25,113::008_restart_he_vm.py::_wait_for_engine_health::190::root::INFO::Waiting for engine to start... ... Then there is a loop of running 'hosted-engine --vm-status --json' and parsing the status, specifically checking the health. The health status does not change until the timeout (after 10 minutes), but after 'vm', there is 'detail', which does change. First one is 'Powering up': 2020-01-20 04:16:25,113::ssh.py::ssh::89::lago.ssh::DEBUG::Command 9ef791c0 on lago-he-basic-role-remote-suite-4-3-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=5199 (Sun Jan 19 23:16:24 2020)\nhost-id=1\nscore=2400\nvm_conf_refresh_time=5199 (Sun Jan 19 23:16:24 2020)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-role-remote-suite-4-3-host-0.lago.local", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 2400, "stopped": false, "maintenance": false, "crc32": "e7f42f2a", "local_conf_timestamp": 5199, "host-ts": 5199}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=5190 (Sun Jan 19 23:16:15 2020)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=5190 (Sun Jan 19 23:16:15 2020)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-role-remote-suite-4-3-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "c3657e8b", "local_conf_timestamp": 5190, "host-ts": 5190}, "global_maintenance": true} ... Then a few similar ones, last one is from '2020-01-20 04:17:22,980', and then it changes to 'Up': 2020-01-20 04:17:27,517::ssh.py::ssh::89::lago.ssh::DEBUG::Command c426f53a on lago-he-basic-role-remote-suite-4-3-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=5259 (Sun Jan 19 23:17:24 2020)\nhost-id=1\nscore=2928\nvm_conf_refresh_time=5259 (Sun Jan 19 23:17:24 2020)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-role-remote-suite-4-3-host-0.lago.local", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 2928, "stopped": false, "maintenance": false, "crc32": "08d4bfe1", "local_conf_timestamp": 5259, "host-ts": 5259}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=5250 (Sun Jan 19 23:17:16 2020)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=5251 (Sun Jan 19 23:17:16 2020)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-role-remote-suite-4-3-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ab277249", "local_conf_timestamp": 5251, "host-ts": 5250}, "global_maintenance": true} /var/log/messages of the engine vm [3] has: Jan 19 23:17:57 lago-he-basic-role-remote-suite-4-3-engine kernel: Initializing cgroup subsys cpuset Meaning, the first line after the reboot has a timestamp that's almost 2 minutes after starting the VM. That's a long time. That's half a minute after detail changed to 'Up', above (no idea where we take this 'detail' from, though). Then, first line that is not from the kernel: Jan 19 23:17:58 lago-he-basic-role-remote-suite-4-3-engine systemd[1]: systemd 219 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN) then it starts lots of services, and then: Jan 19 23:20:31 lago-he-basic-role-remote-suite-4-3-engine systemd: Started oVirt Engine websockets proxy. Jan 19 23:20:33 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: Selected source 45.33.103.94 Jan 19 23:20:37 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: System clock wrong by 3.919225 seconds, adjustment started Jan 19 23:20:37 lago-he-basic-role-remote-suite-4-3-engine systemd: Time has been changed Jan 19 23:20:37 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: System clock was stepped by 3.919225 seconds Jan 19 23:20:38 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: Selected source 129.250.35.250 Jan 19 23:20:43 lago-he-basic-role-remote-suite-4-3-engine cloud-init: Cloud-init v. 18.5 running 'modules:config' at Mon, 20 Jan 2020 04:20:39 +0000. Up 182.82 seconds. and later: Jan 19 23:21:32 lago-he-basic-role-remote-suite-4-3-engine systemd: Started Update UTMP about System Runlevel Changes. Jan 19 23:21:32 lago-he-basic-role-remote-suite-4-3-engine systemd: Startup finished in 22.344s (kernel) + 32.237s (initrd) + 3min 815ms (userspace) = 3min 55.397s. Jan 19 23:21:43 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: Selected source 206.55.191.142 Jan 19 23:23:52 lago-he-basic-role-remote-suite-4-3-engine chronyd[872]: Selected source 129.250.35.250 Jan 19 23:26:32 lago-he-basic-role-remote-suite-4-3-engine systemd: Created slice User Slice of root. engine.log's [4] first line after the reboot is: 2020-01-19 23:26:18,251-05 INFO [org.ovirt.engine.core.uutils.config.ShellLikeConfd] (ServerService Thread Pool -- 103) [] Loaded file '/usr/share/ovirt-engine/services/ovirt-engine/ovirt-engine.conf'. which is a mere 40 seconds before the timeout, and server.log's [5] first line is: 2020-01-19 23:23:13,392-05 INFO [org.jboss.as.server.deployment] (MSC service thread 1-2) WFLYSRV0027: Starting deployment of "apidoc.war" (runtime-name: "apidoc.war") which is a 3 minutes before that. I do not know much about what the engine does during its startup, and how the logs should look, and how long it should take between startup and a working health page. If this all looks normal, then perhaps we should simply give it more than 10 minutes. Otherwise, there is either heavy load on the infra, or perhaps some NTP problems. Anyone has a clue? Anyway, now pushed a patch [6] to allow up to 20 minutes, at least to reduce the noise. Thanks and best regards, [1] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-role-remote-sui... [2] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-role-remote-sui... [3] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-role-remote-sui... [4] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-role-remote-sui... [5] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-role-remote-sui... [6] https://gerrit.ovirt.org/106411 -- Didi