On Tue, Aug 3, 2021 at 7:50 AM <jenkins@jenkins.phx.ovirt.org> wrote:
Project: https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/ Build: https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/2126/ Build Number: 2126 Build Status: Failure Triggered By: Started by timer
------------------------------------- Changes Since Last Success: ------------------------------------- Changes for Build #2126 [Michal Skrivanek] basic: skipping just the VNC console part of test_virtual_machines
----------------- Failed Tests: ----------------- 2 tests failed. FAILED: he-basic-suite-master.test-scenarios.test_012_local_maintenance_sdk.test_local_maintenance
Error Message: ovirtsdk4.Error: Failed to read response: [(<pycurl.Curl object at 0x5555faf11228>, 7, 'Failed to connect to 192.168.200.99 port 443: Connection refused')]
This looks very similar to the issue we have with dns/dig failures that cause the engine VM to go down, and it's similar, but different. dig didn't fail (it now uses TCP), but something else caused the agent to stop the engine VM - a combination of high cpu load and low free memory, after restarting the engine VM as part of test_008. https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/2126/... : ===================================================================================== MainThread::INFO::2021-08-03 06:46:55,068::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state ReinitializeFSM (score: 0) MainThread::INFO::2021-08-03 06:47:04,089::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:04,169::brokerlink::73::ovirt_hosted_engine_ha.lib.brokerlink.BrokerLink::(notify) Success, was notification of state_transition (ReinitializeFSM-GlobalMaintenance) sent? ignored MainThread::INFO::2021-08-03 06:47:05,249::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 3400) MainThread::INFO::2021-08-03 06:47:14,439::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:25,526::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 814 due to cpu load MainThread::INFO::2021-08-03 06:47:25,527::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2586) MainThread::INFO::2021-08-03 06:47:25,537::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:26,029::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2586) MainThread::INFO::2021-08-03 06:47:35,050::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:35,576::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2586) MainThread::INFO::2021-08-03 06:47:45,597::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:46,521::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2586) MainThread::INFO::2021-08-03 06:47:55,577::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:47:56,559::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2586) MainThread::INFO::2021-08-03 06:47:56,559::hosted_engine::525::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Best remote host ost-he-basic-suite-master-host-1 (id: 2, score: 3400) MainThread::INFO::2021-08-03 06:48:05,633::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:48:06,188::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 820 due to cpu load MainThread::INFO::2021-08-03 06:48:06,188::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2580) MainThread::INFO::2021-08-03 06:48:16,256::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:48:16,950::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 831 due to cpu load MainThread::INFO::2021-08-03 06:48:16,951::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2569) MainThread::INFO::2021-08-03 06:48:26,053::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:48:26,999::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 839 due to cpu load MainThread::INFO::2021-08-03 06:48:26,999::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2561) MainThread::INFO::2021-08-03 06:48:36,026::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:48:36,802::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 844 due to cpu load MainThread::INFO::2021-08-03 06:48:36,802::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2556) MainThread::INFO::2021-08-03 06:48:45,827::state_decorators::51::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Global maintenance detected MainThread::INFO::2021-08-03 06:48:46,401::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 849 due to cpu load MainThread::INFO::2021-08-03 06:48:46,401::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state GlobalMaintenance (score: 2551) MainThread::INFO::2021-08-03 06:48:56,588::brokerlink::73::ovirt_hosted_engine_ha.lib.brokerlink.BrokerLink::(notify) Success, was notification of state_transition (GlobalMaintenance-ReinitializeFSM) sent? ignored MainThread::INFO::2021-08-03 06:48:58,685::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state ReinitializeFSM (score: 0) MainThread::INFO::2021-08-03 06:49:05,729::brokerlink::73::ovirt_hosted_engine_ha.lib.brokerlink.BrokerLink::(notify) Success, was notification of state_transition (ReinitializeFSM-EngineStarting) sent? ignored MainThread::INFO::2021-08-03 06:49:06,146::states::176::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(score) Penalizing score by 830 due to cpu load MainThread::INFO::2021-08-03 06:49:06,146::states::72::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_penalize_memory) Penalizing score by 400 due to free memory 1782 being lower than required 3171 MainThread::INFO::2021-08-03 06:49:06,146::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state EngineStarting (score: 2170) MainThread::INFO::2021-08-03 06:49:06,150::state_decorators::95::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(check) Timeout cleared while transitioning <class 'ovirt_hosted_engine_ha.agent.states.EngineStarting'> -> <class 'ovirt_hosted_engine_ha.agent.states.EngineUp'> MainThread::INFO::2021-08-03 06:49:06,172::brokerlink::73::ovirt_hosted_engine_ha.lib.brokerlink.BrokerLink::(notify) Success, was notification of state_transition (EngineStarting-EngineUp) sent? ignored MainThread::INFO::2021-08-03 06:49:06,178::hosted_engine::517::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(_monitoring_loop) Current state EngineUp (score: 2570) MainThread::ERROR::2021-08-03 06:49:16,197::states::398::ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine::(consume) Host ost-he-basic-suite-master-host-1 (id 2) score is significantly better than local score, shutting down VM on this host ===================================================================================== I looked a bit at /var/log/messages of the host, and while there is quite some noise there, can't tell specifically what might have caused the high cpu load. Also looked at logs of previous runs, and there is indeed a similar pattern, where the cpuload on the host causes the agent to penalize the score, but according to the agent log the load goes down faster, up to the point of being quite low when the engine is up, and only then we exit global maintenance, allowing the agent to take actions. I now ran it again, but think that otherwise I'll ignore this for now, unless we see more similar failures. If we do, we might want to check/monitor/log the cpu load on the hosts, and/or change test_008 to wait, after the engine is up, until the cpu load on the host goes down a bit. Before the port to pytest we waited a hard-coded 5 minutes and I changed that then to only wait until the engine VM is not migrating, and this worked more-or-less ok. We might need to refine that, although I'd rather not introduce another arbitrary long delays but wait for some condition. I also noticed that this ran was started at "03:04 AM" (UTC), by timer, whereas all previous timer-based runs started at 01:55 AM, somewhat earlier - perhaps there are some other things that run at that time that cause load. Best regards, -- Didi