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.2/6... Build Number: 630 Build Status: Failure Triggered By: Started by timer ------------------------------------- Changes Since Last Success: ------------------------------------- Changes for Build #630 [Gal Ben Haim] Remove stale url to the internal repo ----------------- 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=2614 (Fri Oct 5 20:09:16 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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 -------------------- >> begin captured logging << -------------------- lago.ssh: DEBUG: start task:6d60779b-e79e-47e9-998c-39cfc96cd6e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:6d60779b-e79e-47e9-998c-39cfc96cd6e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running ddf43558 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command ddf43558 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command ddf43558 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=2528 (Fri Oct 5 20:07:50 2018)\nhost-id=1\nscore=3000\nvm_conf_refresh_time=2528 (Fri Oct 5 20:07:50 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": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "0ae6d9ce", "local_conf_timestamp": 2528, "host-ts": 2528}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2525 (Fri Oct 5 20:07:48 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2525 (Fri Oct 5 20:07:48 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "94893d0b", "local_conf_timestamp": 2525, "host-ts": 2525}, "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:7b60163a-89bd-45bf-892b-6646944ca73c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:7b60163a-89bd-45bf-892b-6646944ca73c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running de6f6eee on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-shutdown lago.ssh: DEBUG: Command de6f6eee 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:79648c0a-2c58-4b9f-9378-35b1d2928ff2:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:79648c0a-2c58-4b9f-9378-35b1d2928ff2:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running dfced7d4 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command dfced7d4 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command dfced7d4 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=2528 (Fri Oct 5 20:07:50 2018)\nhost-id=1\nscore=3000\nvm_conf_refresh_time=2528 (Fri Oct 5 20:07:50 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": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "0ae6d9ce", "local_conf_timestamp": 2528, "host-ts": 2528}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2525 (Fri Oct 5 20:07:48 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2525 (Fri Oct 5 20:07:48 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "94893d0b", "local_conf_timestamp": 2525, "host-ts": 2525}, "global_maintenance": true} lago.ssh: DEBUG: start task:a41bee7a-3df1-42b7-8f4e-8fc96f15783e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a41bee7a-3df1-42b7-8f4e-8fc96f15783e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running e645a99e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command e645a99e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command e645a99e 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=2538 (Fri Oct 5 20:08:00 2018)\nhost-id=1\nscore=3000\nvm_conf_refresh_time=2538 (Fri Oct 5 20:08: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": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "4d8f1a0d", "local_conf_timestamp": 2538, "host-ts": 2538}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2535 (Fri Oct 5 20:07:58 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2535 (Fri Oct 5 20:07:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "62e7f5d6", "local_conf_timestamp": 2535, "host-ts": 2535}, "global_maintenance": true} lago.ssh: DEBUG: start task:f94c5d2f-8f54-460d-a98d-e33e771daa29:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:f94c5d2f-8f54-460d-a98d-e33e771daa29:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running e894511e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command e894511e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command e894511e 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=2538 (Fri Oct 5 20:08:00 2018)\nhost-id=1\nscore=3000\nvm_conf_refresh_time=2538 (Fri Oct 5 20:08: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": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "4d8f1a0d", "local_conf_timestamp": 2538, "host-ts": 2538}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2535 (Fri Oct 5 20:07:58 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2535 (Fri Oct 5 20:07:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "62e7f5d6", "local_conf_timestamp": 2535, "host-ts": 2535}, "global_maintenance": true} lago.ssh: DEBUG: start task:fe6c5374-0d07-415c-86d2-d062e00b3dd8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:fe6c5374-0d07-415c-86d2-d062e00b3dd8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running eae90770 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command eae90770 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command eae90770 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=2548 (Fri Oct 5 20:08:11 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2548 (Fri Oct 5 20:08:11 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": "7e8da80c", "local_conf_timestamp": 2548, "host-ts": 2548}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2545 (Fri Oct 5 20:08:07 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2545 (Fri Oct 5 20:08:08 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "cc7c8506", "local_conf_timestamp": 2545, "host-ts": 2545}, "global_maintenance": true} root: INFO: * VM is down. root: INFO: * Stopping services... lago.ssh: DEBUG: start task:8bee4b95-9d41-4a07-8b01-22a28b0b68e1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:8bee4b95-9d41-4a07-8b01-22a28b0b68e1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running eb5d2844 on lago-he-basic-ansible-suite-4-2-host-0: systemctl stop vdsmd ovirt-ha-broker ovirt-ha-agent lago.ssh: DEBUG: Command eb5d2844 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 root: INFO: * Starting services... lago.ssh: DEBUG: start task:b7d48c4f-78d1-4522-b25f-631ceeba11ed:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:b7d48c4f-78d1-4522-b25f-631ceeba11ed:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running f30b9404 on lago-he-basic-ansible-suite-4-2-host-0: systemctl start vdsmd ovirt-ha-broker ovirt-ha-agent lago.ssh: DEBUG: Command f30b9404 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:a906a664-8725-4391-986a-075cbeceb847:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a906a664-8725-4391-986a-075cbeceb847:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running f5a174b8 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command f5a174b8 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command f5a174b8 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:6d97ee02-a35e-45dc-b9f6-d08eebcfdb73:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:6d97ee02-a35e-45dc-b9f6-d08eebcfdb73:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running fbfa66c6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command fbfa66c6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command fbfa66c6 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:81a47930-f5a7-4d9a-bf95-c516a4d20119:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:81a47930-f5a7-4d9a-bf95-c516a4d20119:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running fe1c7976 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command fe1c7976 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command fe1c7976 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:a09e616e-557f-46cf-96da-4c1d08e6c20c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a09e616e-557f-46cf-96da-4c1d08e6c20c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 005dceec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 005dceec on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 005dceec 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:680788ce-4a96-456e-939e-4187ba02ecf9:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:680788ce-4a96-456e-939e-4187ba02ecf9:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 0289b564 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 0289b564 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 0289b564 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:d677c081-7afd-49ed-83bc-9e42703f5926:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:d677c081-7afd-49ed-83bc-9e42703f5926:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 04b2c16e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 04b2c16e on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 04b2c16e 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:3ec69661-9088-4107-a61a-78d064f23194:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:3ec69661-9088-4107-a61a-78d064f23194:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 06dafbb4 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 06dafbb4 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 06dafbb4 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:a7313617-2000-4cba-b1f3-2b0430d3d031:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:a7313617-2000-4cba-b1f3-2b0430d3d031:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 0909032c on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 0909032c on lago-he-basic-ansible-suite-4-2-host-0 returned with 1 lago.ssh: DEBUG: Command 0909032c 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:b749c52f-0363-47af-8b07-12d48fbc0f89:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:b749c52f-0363-47af-8b07-12d48fbc0f89:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 0b3262ec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status lago.ssh: DEBUG: Command 0b3262ec on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 0b3262ec 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 : 6d4d94fa local_conf_timestamp : 2604 Host timestamp : 2604 Extra metadata (valid at timestamp): metadata_parse_version=1 metadata_feature_version=1 timestamp=2604 (Fri Oct 5 20:09:06 2018) host-id=1 score=0 vm_conf_refresh_time=2604 (Fri Oct 5 20:09:06 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 : 8bf93dc1 local_conf_timestamp : 2595 Host timestamp : 2595 Extra metadata (valid at timestamp): metadata_parse_version=1 metadata_feature_version=1 timestamp=2595 (Fri Oct 5 20:08:58 2018) host-id=2 score=3400 vm_conf_refresh_time=2595 (Fri Oct 5 20:08:58 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:ca0f6687-e4a5-4a45-a33b-851a4b0a27fb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:ca0f6687-e4a5-4a45-a33b-851a4b0a27fb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 0bbc3922 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-start lago.ssh: DEBUG: Command 0bbc3922 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 0bbc3922 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:13617503-7603-4b90-bb3e-7c88ee81e50e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:13617503-7603-4b90-bb3e-7c88ee81e50e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 0cf57dbc on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 0cf57dbc on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 0cf57dbc 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=2604 (Fri Oct 5 20:09:06 2018)\nhost-id=1\nscore=0\nvm_conf_refresh_time=2604 (Fri Oct 5 20:09:06 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": "6d4d94fa", "local_conf_timestamp": 2604, "host-ts": 2604}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2595 (Fri Oct 5 20:08:58 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2595 (Fri Oct 5 20:08:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "8bf93dc1", "local_conf_timestamp": 2595, "host-ts": 2595}, "global_maintenance": true} lago.ssh: DEBUG: start task:28442f55-f66b-4ae8-8be6-dc95642b20e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:28442f55-f66b-4ae8-8be6-dc95642b20e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 137469e6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 137469e6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 137469e6 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=2614 (Fri Oct 5 20:09:16 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "71e9ed52", "local_conf_timestamp": 2605, "host-ts": 2605}, "global_maintenance": true} root: INFO: * VM is UP. root: INFO: * Waiting for engine to start... lago.ssh: DEBUG: start task:7c749b65-99a0-4890-b105-d81df4cd8b2e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: end task:7c749b65-99a0-4890-b105-d81df4cd8b2e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0: lago.ssh: DEBUG: Running 13faa7d6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json lago.ssh: DEBUG: Command 13faa7d6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0 lago.ssh: DEBUG: Command 13faa7d6 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=2614 (Fri Oct 5 20:09:16 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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 ovirtlago.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x7feaff4389b0> 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=2614 (Fri Oct 5 20:09:16 2018)\nhost-id=1\nscore=3400\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\nmetadata_feature_version=1\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\nhost-id=2\nscore=3400\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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 --------------------- >> 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=2614 (Fri Oct 5 20:09:16 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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\n-------------------- >> begin captured logging << --------------------\nlago.ssh: DEBUG: start task:6d60779b-e79e-47e9-998c-39cfc96cd6e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:6d60779b-e79e-47e9-998c-39cfc96cd6e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running ddf43558 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command ddf43558 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command ddf43558 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=2528 (Fri Oct 5 20:07:50 2018)\\nhost-id=1\\nscore=3000\\nvm_conf_refresh_time=2528 (Fri Oct 5 20:07:50 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": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "0ae6d9ce", "local_conf_timestamp": 2528, "host-ts": 2528}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2525 (Fri Oct 5 20:07:48 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2525 (Fri Oct 5 20:07:48 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "94893d0b", "local_conf_timestamp": 2525, "host-ts": 2525}, "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:7b60163a-89bd-45bf-892b-6646944ca73c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:7b60163a-89bd-45bf-892b-6646944ca73c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running de6f6eee on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-shutdown\nlago.ssh: DEBUG: Command de6f6eee 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:79648c0a-2c58-4b9f-9378-35b1d2928ff2:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:79648c0a-2c58-4b9f-9378-35b1d2928ff2:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running dfced7d4 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command dfced7d4 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command dfced7d4 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=2528 (Fri Oct 5 20:07:50 2018)\\nhost-id=1\\nscore=3000\\nvm_conf_refresh_time=2528 (Fri Oct 5 20:07:50 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": {"health": "good", "vm": "up", "detail": "Up"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "0ae6d9ce", "local_conf_timestamp": 2528, "host-ts": 2528}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2525 (Fri Oct 5 20:07:48 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2525 (Fri Oct 5 20:07:48 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "94893d0b", "local_conf_timestamp": 2525, "host-ts": 2525}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:a41bee7a-3df1-42b7-8f4e-8fc96f15783e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a41bee7a-3df1-42b7-8f4e-8fc96f15783e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running e645a99e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command e645a99e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command e645a99e 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=2538 (Fri Oct 5 20:08:00 2018)\\nhost-id=1\\nscore=3000\\nvm_conf_refresh_time=2538 (Fri Oct 5 20:08: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": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "4d8f1a0d", "local_conf_timestamp": 2538, "host-ts": 2538}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2535 (Fri Oct 5 20:07:58 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2535 (Fri Oct 5 20:07:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "62e7f5d6", "local_conf_timestamp": 2535, "host-ts": 2535}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:f94c5d2f-8f54-460d-a98d-e33e771daa29:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:f94c5d2f-8f54-460d-a98d-e33e771daa29:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running e894511e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command e894511e on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command e894511e 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=2538 (Fri Oct 5 20:08:00 2018)\\nhost-id=1\\nscore=3000\\nvm_conf_refresh_time=2538 (Fri Oct 5 20:08: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": "failed liveliness check", "health": "bad", "vm": "up", "detail": "Powering down"}, "score": 3000, "stopped": false, "maintenance": false, "crc32": "4d8f1a0d", "local_conf_timestamp": 2538, "host-ts": 2538}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2535 (Fri Oct 5 20:07:58 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2535 (Fri Oct 5 20:07:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "62e7f5d6", "local_conf_timestamp": 2535, "host-ts": 2535}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:fe6c5374-0d07-415c-86d2-d062e00b3dd8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:fe6c5374-0d07-415c-86d2-d062e00b3dd8:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running eae90770 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command eae90770 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command eae90770 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=2548 (Fri Oct 5 20:08:11 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2548 (Fri Oct 5 20:08:11 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": "7e8da80c", "local_conf_timestamp": 2548, "host-ts": 2548}, "2": {"conf_on_shared_storage": true, "live-data": true, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2545 (Fri Oct 5 20:08:07 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2545 (Fri Oct 5 20:08:08 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "cc7c8506", "local_conf_timestamp": 2545, "host-ts": 2545}, "global_maintenance": true}\n\nroot: INFO: * VM is down.\nroot: INFO: * Stopping services...\nlago.ssh: DEBUG: start task:8bee4b95-9d41-4a07-8b01-22a28b0b68e1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:8bee4b95-9d41-4a07-8b01-22a28b0b68e1:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running eb5d2844 on lago-he-basic-ansible-suite-4-2-host-0: systemctl stop vdsmd ovirt-ha-broker ovirt-ha-agent\nlago.ssh: DEBUG: Command eb5d2844 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nroot: INFO: * Starting services...\nlago.ssh: DEBUG: start task:b7d48c4f-78d1-4522-b25f-631ceeba11ed:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:b7d48c4f-78d1-4522-b25f-631ceeba11ed:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running f30b9404 on lago-he-basic-ansible-suite-4-2-host-0: systemctl start vdsmd ovirt-ha-broker ovirt-ha-agent\nlago.ssh: DEBUG: Command f30b9404 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:a906a664-8725-4391-986a-075cbeceb847:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a906a664-8725-4391-986a-075cbeceb847:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running f5a174b8 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command f5a174b8 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command f5a174b8 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:6d97ee02-a35e-45dc-b9f6-d08eebcfdb73:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:6d97ee02-a35e-45dc-b9f6-d08eebcfdb73:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running fbfa66c6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command fbfa66c6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command fbfa66c6 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:81a47930-f5a7-4d9a-bf95-c516a4d20119:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:81a47930-f5a7-4d9a-bf95-c516a4d20119:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running fe1c7976 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command fe1c7976 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command fe1c7976 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:a09e616e-557f-46cf-96da-4c1d08e6c20c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a09e616e-557f-46cf-96da-4c1d08e6c20c:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 005dceec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 005dceec on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 005dceec 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:680788ce-4a96-456e-939e-4187ba02ecf9:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:680788ce-4a96-456e-939e-4187ba02ecf9:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 0289b564 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 0289b564 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 0289b564 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:d677c081-7afd-49ed-83bc-9e42703f5926:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:d677c081-7afd-49ed-83bc-9e42703f5926:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 04b2c16e on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 04b2c16e on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 04b2c16e 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:3ec69661-9088-4107-a61a-78d064f23194:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:3ec69661-9088-4107-a61a-78d064f23194:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 06dafbb4 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 06dafbb4 on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 06dafbb4 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:a7313617-2000-4cba-b1f3-2b0430d3d031:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:a7313617-2000-4cba-b1f3-2b0430d3d031:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 0909032c on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 0909032c on lago-he-basic-ansible-suite-4-2-host-0 returned with 1\nlago.ssh: DEBUG: Command 0909032c 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:b749c52f-0363-47af-8b07-12d48fbc0f89:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:b749c52f-0363-47af-8b07-12d48fbc0f89:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 0b3262ec on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status\nlago.ssh: DEBUG: Command 0b3262ec on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 0b3262ec 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 : 6d4d94fa\nlocal_conf_timestamp : 2604\nHost timestamp : 2604\nExtra metadata (valid at timestamp):\n\tmetadata_parse_version=1\n\tmetadata_feature_version=1\n\ttimestamp=2604 (Fri Oct 5 20:09:06 2018)\n\thost-id=1\n\tscore=0\n\tvm_conf_refresh_time=2604 (Fri Oct 5 20:09:06 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 : 8bf93dc1\nlocal_conf_timestamp : 2595\nHost timestamp : 2595\nExtra metadata (valid at timestamp):\n\tmetadata_parse_version=1\n\tmetadata_feature_version=1\n\ttimestamp=2595 (Fri Oct 5 20:08:58 2018)\n\thost-id=2\n\tscore=3400\n\tvm_conf_refresh_time=2595 (Fri Oct 5 20:08:58 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:ca0f6687-e4a5-4a45-a33b-851a4b0a27fb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:ca0f6687-e4a5-4a45-a33b-851a4b0a27fb:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 0bbc3922 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-start\nlago.ssh: DEBUG: Command 0bbc3922 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 0bbc3922 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:13617503-7603-4b90-bb3e-7c88ee81e50e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:13617503-7603-4b90-bb3e-7c88ee81e50e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 0cf57dbc on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 0cf57dbc on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 0cf57dbc 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=2604 (Fri Oct 5 20:09:06 2018)\\nhost-id=1\\nscore=0\\nvm_conf_refresh_time=2604 (Fri Oct 5 20:09:06 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": "6d4d94fa", "local_conf_timestamp": 2604, "host-ts": 2604}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2595 (Fri Oct 5 20:08:58 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2595 (Fri Oct 5 20:08:58 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "8bf93dc1", "local_conf_timestamp": 2595, "host-ts": 2595}, "global_maintenance": true}\n\nlago.ssh: DEBUG: start task:28442f55-f66b-4ae8-8be6-dc95642b20e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:28442f55-f66b-4ae8-8be6-dc95642b20e4:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 137469e6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 137469e6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 137469e6 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=2614 (Fri Oct 5 20:09:16 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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", "detail": "unknown"}, "score": 3400, "stopped": false, "maintenance": false, "crc32": "71e9ed52", "local_conf_timestamp": 2605, "host-ts": 2605}, "global_maintenance": true}\n\nroot: INFO: * VM is UP.\nroot: INFO: * Waiting for engine to start...\nlago.ssh: DEBUG: start task:7c749b65-99a0-4890-b105-d81df4cd8b2e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: end task:7c749b65-99a0-4890-b105-d81df4cd8b2e:Get ssh client for lago-he-basic-ansible-suite-4-2-host-0:\nlago.ssh: DEBUG: Running 13faa7d6 on lago-he-basic-ansible-suite-4-2-host-0: hosted-engine --vm-status --json\nlago.ssh: DEBUG: Command 13faa7d6 on lago-he-basic-ansible-suite-4-2-host-0 returned with 0\nlago.ssh: DEBUG: Command 13faa7d6 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=2614 (Fri Oct 5 20:09:16 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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\novirtlago.testlib: ERROR: * Unhandled exception in <function <lambda> at 0x7feaff4389b0>\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=2614 (Fri Oct 5 20:09:16 2018)\\nhost-id=1\\nscore=3400\\nvm_conf_refresh_time=2614 (Fri Oct 5 20:09:17 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": "e0beb128", "local_conf_timestamp": 2614, "host-ts": 2614}, "2": {"conf_on_shared_storage": true, "live-data": false, "extra": "metadata_parse_version=1\\nmetadata_feature_version=1\\ntimestamp=2605 (Fri Oct 5 20:09:08 2018)\\nhost-id=2\\nscore=3400\\nvm_conf_refresh_time=2605 (Fri Oct 5 20:09:08 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\n--------------------- >> end captured logging << ---------------------'