[oVirt Jenkins] ovirt-system-tests_he-basic-ansible-suite-4.2 - Build # 578 - Failure!

Project: http://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-ansible-suite-4.2/ Build: http://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-ansible-suite-4.... Build Number: 578 Build Status: Failure Triggered By: Started by timer ------------------------------------- Changes Since Last Success: ------------------------------------- Changes for Build #578 [Milan Zamazal] Update test-vm.ovf file ----------------- Failed Tests: ----------------- 1 tests failed. FAILED: 008_restart_he_vm.restart_he_vm Error Message: could not parse JSON: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": -------------------- >> begin captured logging << -------------------- lago.ssh: DEBUG: start task:6469ff97-fd82-4fba-8353-9b736936a12c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:6469ff97-fd82-4fba-8353-9b736936a12c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2561 (Tue Sep 18 12:10:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=EngineUp\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "5bb7aefb", "local_conf_timestamp": 2561, "host-ts": 2561}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2560 (Tue Sep 18 12:10:10 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=EngineDown\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "d172629f", "local_conf_timestamp": 2561, "host-ts": 2560}, "global_maintenance": true} root: INFO: * Shutting down HE VM on host: lago-he-basic-ansible-suite-4-2-host-0 lago.ssh: DEBUG: start task:a1e2f644-5484-4092-976b-f93b9bff8d63:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a1e2f644-5484-4092-976b-f93b9bff8d63:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 55273866 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-shutdown lago.ssh: DEBUG: Command 55273866 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 root: INFO: * Command succeeded root: INFO: * Waiting for VM to be down... lago.ssh: DEBUG: start task:19bbae64-260d-4591-8719-ec52c46081a3:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:19bbae64-260d-4591-8719-ec52c46081a3:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2561 (Tue Sep 18 12:10:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=EngineUp\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "5bb7aefb", "local_conf_timestamp": 2561, "host-ts": 2561}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2560 (Tue Sep 18 12:10:10 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=EngineDown\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "d172629f", "local_conf_timestamp": 2561, "host-ts": 2560}, "global_maintenance": true} lago.ssh: DEBUG: start task:41902ed5-eb63-4017-8b3a-b612b34f6bcc:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:41902ed5-eb63-4017-8b3a-b612b34f6bcc:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2571 (Tue Sep 18 12:10:20 2018)\nhost-id=1\nscore=3000\nvm_conf_refresh_time=2571 (Tue Sep 18 12:10:20 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "fcf99ac3", "local_conf_timestamp": 2571, "host-ts": 2571}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2570 (Tue Sep 18 12:10:19 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2570 (Tue Sep 18 12:10:19 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=EngineDown\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "60fe16df", "local_conf_timestamp": 2570, "host-ts": 2570}, "global_maintenance": true} lago.ssh: DEBUG: start task:f9baa42f-d1b9-44e8-9d0a-42f41a495362:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:f9baa42f-d1b9-44e8-9d0a-42f41a495362:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2581 (Tue Sep 18 12:10:30 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2581 (Tue Sep 18 12:10:31 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "down_unexpected", "detail": "Down"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e5962d00", "local_conf_timestamp": 2581, "host-ts": 2581}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2580 (Tue Sep 18 12:10:29 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2580 (Tue Sep 18 12:10:29 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "de32fbcb", "local_conf_timestamp": 2580, "host-ts": 2580}, "global_maintenance": true} root: INFO: * VM is down. root: INFO: * Stopping services... lago.ssh: DEBUG: start task:cb8c09f1-87dd-405d-8904-907a1989cb31:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:cb8c09f1-87dd-405d-8904-907a1989cb31:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 5f714e2e on lago-he-basic-ansible-suite-4-2-host-0: systemctl stop vdsmd ovirt-ha-broker ovirt-ha-agent lago.ssh: DEBUG: Command 5f714e2e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 root: INFO: * Starting services... lago.ssh: DEBUG: start task:7ccaa6ca-f2ea-4e2a-98c6-0c543fd3cb72:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:7ccaa6ca-f2ea-4e2a-98c6-0c543fd3cb72:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 66c72220 on lago-he-basic-ansible-suite-4-2-host-0: systemctl start vdsmd ovirt-ha-broker ovirt-ha-agent lago.ssh: DEBUG: Command 66c72220 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 root: INFO: * Waiting for agent to be ready... lago.ssh: DEBUG: start task:170c54e8-f608-4663-adb8-07875043648b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:170c54e8-f608-4663-adb8-07875043648b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:181570eb-206a-4ec7-91ea-b0b5169fedfd:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:181570eb-206a-4ec7-91ea-b0b5169fedfd:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:326af4dd-1f16-4935-9874-0d80259c7697:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:326af4dd-1f16-4935-9874-0d80259c7697:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 71b4333a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 71b4333a on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 71b4333a on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:4290047c-da3a-49e5-a7b2-a9d60c8383cb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:4290047c-da3a-49e5-a7b2-a9d60c8383cb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:e1724b51-9e94-4e12-be43-374a22a56e5c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:e1724b51-9e94-4e12-be43-374a22a56e5c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:3f9b1f59-ee4f-49a6-ad21-c77d3c403aba:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:3f9b1f59-ee4f-49a6-ad21-c77d3c403aba:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:0a356812-9169-42e4-bb61-f41c500bab0b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:0a356812-9169-42e4-bb61-f41c500bab0b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:4440aaf7-97cd-4106-9d80-4f3d6265ba1d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:4440aaf7-97cd-4106-9d80-4f3d6265ba1d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:4a3838f9-2b52-4189-8915-0c39dc71ccb1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:4a3838f9-2b52-4189-8915-0c39dc71ccb1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0 output: The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable. lago.ssh: DEBUG: start task:78ae6cc0-4511-4e8f-89c1-d015830bab8c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:78ae6cc0-4511-4e8f-89c1-d015830bab8c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0 output: !! Cluster is in GLOBAL MAINTENANCE mode !! --== Host 1 status ==-- conf_on_shared_storage : True Status up-to-date : True Hostname : lago-he-basic-ansible-suite-4-2-host-0 Host ID : 1 Engine status : {"reason": "bad vm status", "health": "bad", "vm": "down", "detail": "Down"} Score : 0 stopped : False Local maintenance : False crc32 : 486f8a4a local_conf_timestamp : 2641 Host timestamp : 2641 Extra metadata (valid at timestamp): metadata_parse_version=1 metadata_feature_version=1 timestamp=2641 (Tue Sep 18 12:11:30 2018) host-id=1 score=0 vm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018) conf_on_shared_storage=True maintenance=False state=ReinitializeFSM stopped=False --== Host 2 status ==-- conf_on_shared_storage : True Status up-to-date : False Hostname : lago-he-basic-ansible-suite-4-2-host-1 Host ID : 2 Engine status : unknown stale-data Score : 3400 stopped : False Local maintenance : False crc32 : fa3768d0 local_conf_timestamp : 2631 Host timestamp : 2631 Extra metadata (valid at timestamp): metadata_parse_version=1 metadata_feature_version=1 timestamp=2631 (Tue Sep 18 12:11:21 2018) host-id=2 score=3400 vm_conf_refresh_time=2631 (Tue Sep 18 12:11:21 2018) conf_on_shared_storage=True maintenance=False state=GlobalMaintenance stopped=False !! Cluster is in GLOBAL MAINTENANCE mode !! root: INFO: * Agent is ready. root: INFO: * Starting VM... lago.ssh: DEBUG: start task:a93330e3-27f0-4aa9-8491-3716ebc19284:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a93330e3-27f0-4aa9-8491-3716ebc19284:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 8179b344 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-start lago.ssh: DEBUG: Command 8179b344 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 8179b344 on lago-he-basic-ansible-suite-4-2-host-0 output: VM exists and is down, cleaning up and restarting root: INFO: * Command succeeded root: INFO: * Waiting for VM to be UP... lago.ssh: DEBUG: start task:142d6f14-a10b-4195-93eb-b0e1b92926d8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:142d6f14-a10b-4195-93eb-b0e1b92926d8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 83234016 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 83234016 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 83234016 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\nhost-id=1\nscore=0\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=ReinitializeFSM\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "down", "detail": "Down"}, "score": 0, "stopped": false, "maintenance": false, "crc32": "486f8a4a", "local_conf_timestamp": 2641, "host-ts": 2641}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2631 (Tue Sep 18 12:11:21 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2631 (Tue Sep 18 12:11:21 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "fa3768d0", "local_conf_timestamp": 2631, "host-ts": 2631}, "global_maintenance": true} lago.ssh: DEBUG: start task:5c32f6b0-8dec-42c6-9ec4-1b96850c35b4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:5c32f6b0-8dec-42c6-9ec4-1b96850c35b4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "159650eb", "local_conf_timestamp": 2651, "host-ts": 2651}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "c614bc31", "local_conf_timestamp": 2641, "host-ts": 2641}, "global_maintenance": true} root: INFO: * VM is UP. root: INFO: * Waiting for engine to start... lago.ssh: DEBUG: start task:f05d40f1-75a1-43bf-b63a-a6209f4a0878:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:f05d40f1-75a1-43bf-b63a-a6209f4a0878:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "159650eb", "local_conf_timestamp": 2651, "host-ts": 2651}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "c614bc31", "local_conf_timestamp": 2641, "host-ts": 2641}, "global_maintenance": true} lago.ssh: DEBUG: start task:8af4d2ba-7614-4b29-8c96-7957e80f3911:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:8af4d2ba-7614-4b29-8c96-7957e80f3911:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "a658da6c", "local_conf_timestamp": 2661, "host-ts": 2661}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "009ff8e7", "local_conf_timestamp": 2651, "host-ts": 2651}, "global_maintenance": true} lago.ssh: DEBUG: start task:ef2e841b-741f-48ab-ab4e-12b9e761930d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:ef2e841b-741f-48ab-ab4e-12b9e761930d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "a658da6c", "local_conf_timestamp": 2661, "host-ts": 2661}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true} lago.ssh: DEBUG: start task:76207a3b-da9a-4920-a92b-137966b18627:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:76207a3b-da9a-4920-a92b-137966b18627:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e73b0f94", "local_conf_timestamp": 2672, "host-ts": 2671}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true} lago.ssh: DEBUG: start task:9399a6ca-99fa-47fe-99b2-90964b83d06d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:9399a6ca-99fa-47fe-99b2-90964b83d06d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 97c62998 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 97c62998 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 97c62998 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e73b0f94", "local_conf_timestamp": 2672, "host-ts": 2671}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true} lago.ssh: DEBUG: start task:0c6ad5e5-1a85-4270-9c6d-b9dfe9237306:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:0c6ad5e5-1a85-4270-9c6d-b9dfe9237306:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "cff126b0", "local_conf_timestamp": 2672, "host-ts": 2671}, "global_maintenance": true} lago.ssh: DEBUG: start task:e00ae9c4-1936-456d-9965-c5ae52b9bd88:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:e00ae9c4-1936-456d-9965-c5ae52b9bd88:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0 output: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": ovirtlago.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x7f091b01f050> Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 234, in assert_equals_within res = func() File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 187, in <lambda> for k, v in _get_he_status(host).items() File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 128, in _get_he_status raise RuntimeError('could not parse JSON: %s' % ret.out) RuntimeError: could not parse JSON: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\nconf_on_shared_storage=True\nmaintenance=False\nstate=GlobalMaintenance\nstopped=False\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": --------------------- >> end captured logging << --------------------- Stack Trace: 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 142, in wrapped_test test() File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 60, in wrapper return func(get_test_prefix(), *args, **kwargs) File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 53, in restart_he_vm _wait_for_engine_health(host) File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 185, in _wait_for_engine_health testlib.assert_true_within_long(lambda: any( File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 286, in assert_true_within_long assert_equals_within_long(func, True, allowed_exceptions) File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 273, in assert_equals_within_long func, value, LONG_TIMEOUT, allowed_exceptions=allowed_exceptions File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 234, in assert_equals_within res = func() File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 187, in <lambda> for k, v in _get_he_status(host).items() File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 128, in _get_he_status raise RuntimeError('could not parse JSON: %s' % ret.out) 'could not parse JSON: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": \n-------------------- >> begin captured logging << --------------------\nlago.ssh: DEBUG: start task:6469ff97-fd82-4fba-8353-9b736936a12c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:6469ff97-fd82-4fba-8353-9b736936a12c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 54a3b8d8 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2561 (Tue Sep 18 12:10:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=EngineUp\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "5bb7aefb", "local_conf_timestamp": 2561, "host-ts": 2561}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2560 (Tue Sep 18 12:10:10 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=EngineDown\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "d172629f", "local_conf_timestamp": 2561, "host-ts": 2560}, "global_maintenance": true}\n\nroot: INFO: * Shutting down HE VM on host: lago-he-basic-ansible-suite-4-2-host-0\nlago.ssh: DEBUG: start task:a1e2f644-5484-4092-976b-f93b9bff8d63:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a1e2f644-5484-4092-976b-f93b9bff8d63:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 55273866 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-shutdown\nlago.ssh: DEBUG: Command 55273866 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nroot: INFO: * Command succeeded\nroot: INFO: * Waiting for VM to be down...\nlago.ssh: DEBUG: start task:19bbae64-260d-4591-8719-ec52c46081a3:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:19bbae64-260d-4591-8719-ec52c46081a3:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 55d4e434 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2561 (Tue Sep 18 12:10:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=EngineUp\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "5bb7aefb", "local_conf_timestamp": 2561, "host-ts": 2561}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2560 (Tue Sep 18 12:10:10 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2561 (Tue Sep 18 12:10:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=EngineDown\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "d172629f", "local_conf_timestamp": 2561, "host-ts": 2560}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:41902ed5-eb63-4017-8b3a-b612b34f6bcc:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:41902ed5-eb63-4017-8b3a-b612b34f6bcc:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 5c8a15ec on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2571 (Tue Sep 18 12:10:20 2018)\\nhost-id=1\\nscore=3000\\nvm_conf_refresh_time=2571 (Tue Sep 18 12:10:20 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "fcf99ac3", "local_conf_timestamp": 2571, "host-ts": 2571}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2570 (Tue Sep 18 12:10:19 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2570 (Tue Sep 18 12:10:19 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=EngineDown\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "60fe16df", "local_conf_timestamp": 2570, "host-ts": 2570}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:f9baa42f-d1b9-44e8-9d0a-42f41a495362:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:f9baa42f-d1b9-44e8-9d0a-42f41a495362:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 5eddf14c on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2581 (Tue Sep 18 12:10:30 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2581 (Tue Sep 18 12:10:31 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "down_unexpected", "detail": "Down"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e5962d00", "local_conf_timestamp": 2581, "host-ts": 2581}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2580 (Tue Sep 18 12:10:29 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2580 (Tue Sep 18 12:10:29 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "de32fbcb", "local_conf_timestamp": 2580, "host-ts": 2580}, "global_maintenance": true}\n\nroot: INFO: * VM is down.\nroot: INFO: * Stopping services...\nlago.ssh: DEBUG: start task:cb8c09f1-87dd-405d-8904-907a1989cb31:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:cb8c09f1-87dd-405d-8904-907a1989cb31:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 5f714e2e on lago-he-basic-ansible-suite-4-2-host-0: systemctl stop vdsmd ovirt-ha-broker ovirt-ha-agent\nlago.ssh: DEBUG: Command 5f714e2e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nroot: INFO: * Starting services...\nlago.ssh: DEBUG: start task:7ccaa6ca-f2ea-4e2a-98c6-0c543fd3cb72:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:7ccaa6ca-f2ea-4e2a-98c6-0c543fd3cb72:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 66c72220 on lago-he-basic-ansible-suite-4-2-host-0: systemctl start vdsmd ovirt-ha-broker ovirt-ha-agent\nlago.ssh: DEBUG: Command 66c72220 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nroot: INFO: * Waiting for agent to be ready...\nlago.ssh: DEBUG: start task:170c54e8-f608-4663-adb8-07875043648b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:170c54e8-f608-4663-adb8-07875043648b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 6938ed86 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:181570eb-206a-4ec7-91ea-b0b5169fedfd:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:181570eb-206a-4ec7-91ea-b0b5169fedfd:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 6f91b55a on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:326af4dd-1f16-4935-9874-0d80259c7697:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:326af4dd-1f16-4935-9874-0d80259c7697:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 71b4333a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 71b4333a on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 71b4333a on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:4290047c-da3a-49e5-a7b2-a9d60c8383cb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:4290047c-da3a-49e5-a7b2-a9d60c8383cb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 73da3b46 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:e1724b51-9e94-4e12-be43-374a22a56e5c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:e1724b51-9e94-4e12-be43-374a22a56e5c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 76029bf2 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:3f9b1f59-ee4f-49a6-ad21-c77d3c403aba:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:3f9b1f59-ee4f-49a6-ad21-c77d3c403aba:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 783cb2ae on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:0a356812-9169-42e4-bb61-f41c500bab0b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:0a356812-9169-42e4-bb61-f41c500bab0b:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 7a64f6c2 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:4440aaf7-97cd-4106-9d80-4f3d6265ba1d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:4440aaf7-97cd-4106-9d80-4f3d6265ba1d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 7c8cedf6 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:4a3838f9-2b52-4189-8915-0c39dc71ccb1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:4a3838f9-2b52-4189-8915-0c39dc71ccb1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 7eb64906 on lago-he-basic-ansible-suite-4-2-host-0 output:\n The hosted engine configuration has not been retrieved from shared storage. Please ensure that ovirt-ha-agent is running and the storage server is reachable.\n\nlago.ssh: DEBUG: start task:78ae6cc0-4511-4e8f-89c1-d015830bab8c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:78ae6cc0-4511-4e8f-89c1-d015830bab8c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 80ec9144 on lago-he-basic-ansible-suite-4-2-host-0 output:\n \n\n!! Cluster is in GLOBAL MAINTENANCE mode !!\n\n\n\n--== Host 1 status ==--\n\nconf_on_shared_storage : True\nStatus up-to-date : True\nHostname : lago-he-basic-ansible-suite-4-2-host-0\nHost ID : 1\nEngine status : {"reason": "bad vm status", "health": "bad", "vm": "down", "detail": "Down"}\nScore : 0\nstopped : False\nLocal maintenance : False\ncrc32 : 486f8a4a\nlocal_conf_timestamp : 2641\nHost timestamp : 2641\nExtra metadata (valid at timestamp):\n\tmetadata_parse_version=1\n\tmetadata_feature_version=1\n\ttimestamp=2641 (Tue Sep 18 12:11:30 2018)\n\thost-id=1\n\tscore=0\n\tvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\n\tconf_on_shared_storage=True\n\tmaintenance=False\n\tstate=ReinitializeFSM\n\tstopped=False\n\n\n--== Host 2 status ==--\n\nconf_on_shared_storage : True\nStatus up-to-date : False\nHostname : lago-he-basic-ansible-suite-4-2-host-1\nHost ID : 2\nEngine status : unknown stale-data\nScore : 3400\nstopped : False\nLocal maintenance : False\ncrc32 : fa3768d0\nlocal_conf_timestamp : 2631\nHost timestamp : 2631\nExtra metadata (valid at timestamp):\n\tmetadata_parse_version=1\n\tmetadata_feature_version=1\n\ttimestamp=2631 (Tue Sep 18 12:11:21 2018)\n\thost-id=2\n\tscore=3400\n\tvm_conf_refresh_time=2631 (Tue Sep 18 12:11:21 2018)\n\tconf_on_shared_storage=True\n\tmaintenance=False\n\tstate=GlobalMaintenance\n\tstopped=False\n\n\n!! Cluster is in GLOBAL MAINTENANCE mode !!\n\n\nroot: INFO: * Agent is ready.\nroot: INFO: * Starting VM...\nlago.ssh: DEBUG: start task:a93330e3-27f0-4aa9-8491-3716ebc19284:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a93330e3-27f0-4aa9-8491-3716ebc19284:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 8179b344 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-start\nlago.ssh: DEBUG: Command 8179b344 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 8179b344 on lago-he-basic-ansible-suite-4-2-host-0 output:\n VM exists and is down, cleaning up and restarting\n\nroot: INFO: * Command succeeded\nroot: INFO: * Waiting for VM to be UP...\nlago.ssh: DEBUG: start task:142d6f14-a10b-4195-93eb-b0e1b92926d8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:142d6f14-a10b-4195-93eb-b0e1b92926d8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 83234016 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 83234016 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 83234016 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\\nhost-id=1\\nscore=0\\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=ReinitializeFSM\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "down", "detail": "Down"}, "score": 0, "stopped": false, "maintenance": false, "crc32": "486f8a4a", "local_conf_timestamp": 2641, "host-ts": 2641}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2631 (Tue Sep 18 12:11:21 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2631 (Tue Sep 18 12:11:21 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "fa3768d0", "local_conf_timestamp": 2631, "host-ts": 2631}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:5c32f6b0-8dec-42c6-9ec4-1b96850c35b4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:5c32f6b0-8dec-42c6-9ec4-1b96850c35b4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 89b990e2 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "159650eb", "local_conf_timestamp": 2651, "host-ts": 2651}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "c614bc31", "local_conf_timestamp": 2641, "host-ts": 2641}, "global_maintenance": true}\n\nroot: INFO: * VM is UP.\nroot: INFO: * Waiting for engine to start...\nlago.ssh: DEBUG: start task:f05d40f1-75a1-43bf-b63a-a6209f4a0878:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:f05d40f1-75a1-43bf-b63a-a6209f4a0878:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 8a3fc81a on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "159650eb", "local_conf_timestamp": 2651, "host-ts": 2651}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2641 (Tue Sep 18 12:11:30 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2641 (Tue Sep 18 12:11:30 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "c614bc31", "local_conf_timestamp": 2641, "host-ts": 2641}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:8af4d2ba-7614-4b29-8c96-7957e80f3911:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:8af4d2ba-7614-4b29-8c96-7957e80f3911:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 90d5a046 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "a658da6c", "local_conf_timestamp": 2661, "host-ts": 2661}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2651 (Tue Sep 18 12:11:40 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2651 (Tue Sep 18 12:11:40 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "009ff8e7", "local_conf_timestamp": 2651, "host-ts": 2651}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:ef2e841b-741f-48ab-ab4e-12b9e761930d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:ef2e841b-741f-48ab-ab4e-12b9e761930d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 931b2fb0 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "a658da6c", "local_conf_timestamp": 2661, "host-ts": 2661}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:76207a3b-da9a-4920-a92b-137966b18627:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:76207a3b-da9a-4920-a92b-137966b18627:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 956f9c56 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e73b0f94", "local_conf_timestamp": 2672, "host-ts": 2671}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:9399a6ca-99fa-47fe-99b2-90964b83d06d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:9399a6ca-99fa-47fe-99b2-90964b83d06d:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 97c62998 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 97c62998 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 97c62998 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "bad vm status", "health": "bad", "vm": "up", "detail": "Powering up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "e73b0f94", "local_conf_timestamp": 2672, "host-ts": 2671}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2661 (Tue Sep 18 12:11:50 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2661 (Tue Sep 18 12:11:51 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "907333dc", "local_conf_timestamp": 2661, "host-ts": 2661}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:0c6ad5e5-1a85-4270-9c6d-b9dfe9237306:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:0c6ad5e5-1a85-4270-9c6d-b9dfe9237306:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 9a47efd0 on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": 2, "engine-status": {"reason": "vm not running on this host", "health": "bad", "vm": "down_unexpected", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "cff126b0", "local_conf_timestamp": 2672, "host-ts": 2671}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:e00ae9c4-1936-456d-9965-c5ae52b9bd88:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:e00ae9c4-1936-456d-9965-c5ae52b9bd88:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 9c9892bc on lago-he-basic-ansible-suite-4-2-host-0 output:\n {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": \novirtlago.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x7f091b01f050>\nTraceback (most recent call last):\n File "/usr/lib/python2.7/site-packages/ovirtlago/testlib.py", line 234, in assert_equals_within\n res = func()\n File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 187, in <lambda>\n for k, v in _get_he_status(host).items()\n File "/home/jenkins/workspace/ovirt-system-tests_he-basic-ansible-suite-4.2/ovirt-system-tests/he-basic-ansible-suite-4.2/test-scenarios/008_restart_he_vm.py", line 128, in _get_he_status\n raise RuntimeError(\'could not parse JSON: %s\' % ret.out)\nRuntimeError: could not parse JSON: {"1": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2681 (Tue Sep 18 12:12:10 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2681 (Tue Sep 18 12:12:10 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-0", "host-id": 1, "engine-status": {"reason": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Up"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "ca5cd2cc", "local_conf_timestamp": 2681, "host-ts": 2681}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2671 (Tue Sep 18 12:12:01 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2672 (Tue Sep 18 12:12:01 2018)\\nconf_on_shared_storage=True\\nmaintenance=False\\nstate=GlobalMaintenance\\nstopped=False\\n", "hostname": "lago-he-basic-ansible-suite-4-2-host-1", "host-id": \n--------------------- >> end captured logging << ---------------------'