[ovirt-devel] Re: test_ha_recovery failed (was: [oVirt Jenkins] ovirt-system-tests_he-basic-suite-master - Build # 1943 - Still Failing!)

On Sun, Mar 7, 2021 at 8:24 PM Yedidyah Bar David <didi(a)redhat.com&gt; wrote: > > On Sun, Mar 7, 2021 at 4:06 PM Yedidyah Bar David <didi(a)redhat.com&gt; wrote: > > > > On Sun, Mar 7, 2021 at 5:12 AM <jenkins(a)jenkins.phx.ovirt.org&gt; wrote: > > > > > > Project: https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/ > > > Build: https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/1943/ > > > > Failed during -basic-suite-master.test-scenarios.test_004_basic_sanity.test_ha_recovery > > due to timeout. Can't tell exactly why. Now rebuilt, to see if it > > happens again. Basic suite did pass this point with (mostly) the same > > code, and there shouldn't be anything HE-specific in this test. FYI. > > It did fail again: > > https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/1944/ > > Again, engine.log [1] has no 'VM_DOWN_ERROR'. Any clue? OK. It seems like an OST issue. With [1], I get: 2021-03-08 13:05:10+0100,088 DEBUG (MainThread) [test_004_basic_sanity] test_ha_recovery: ansible_host=ModuleMapper<config_builder=ConfigBuilder<inventory=/tmp/tmp_fdlcj8y, host_pattern=la go-he-basic-suite-master-host-0.lago.local>> (test_004_basic_sanity:1072) 2021-03-08 13:05:10+0100,650 DEBUG (MainThread) [test_004_basic_sanity] test_ha_recovery: pgrep_res={'cmd': 'dig +short vm0', 'stdout': '192.168.200.147', 'stderr': '', 'rc': 0, 'start': ' 2021-03-08 13:01:59.636833', 'end': '2021-03-08 13:01:59.656727', 'delta': '0:00:00.019894', 'changed': True, 'invocation': {'module_args': {'_raw_params': 'dig +short vm0', '_uses_shell': T rue, 'warn': True, 'stdin_add_newline': True, 'strip_empty_ends': True, 'argv': None, 'chdir': None, 'executable': None, 'creates': None, 'removes': None, 'stdin': None}}, 'stdout_lines': [' 192.168.200.147'], 'stderr_lines': [], '_ansible_no_log': False} (test_004_basic_sanity:1074) 2021-03-08 13:05:10+0100,650 DEBUG (MainThread) [test_004_basic_sanity] test_ha_recovery: pid=192.168.200.147 (test_004_basic_sanity:1076) 2021-03-08 13:05:11+0100,194 DEBUG (MainThread) [test_004_basic_sanity] test_ha_recovery: kill_res={'cmd': 'dig +short vm0', 'stdout': '192.168.200.147', 'stderr': '', 'rc': 0, 'start': '2 021-03-08 13:01:59.636833', 'end': '2021-03-08 13:01:59.656727', 'delta': '0:00:00.019894', 'changed': True, 'invocation': {'module_args': {'_raw_params': 'dig +short vm0', '_uses_shell': Tr ue, 'warn': True, 'stdin_add_newline': True, 'strip_empty_ends': True, 'argv': None, 'chdir': None, 'executable': None, 'creates': None, 'removes': None, 'stdin': None}}, 'stdout_lines': ['1 92.168.200.147'], 'stderr_lines': [], '_ansible_no_log': False} (test_004_basic_sanity:1078)

[1] https://gerrit.ovirt.org/c/ovirt-system-tests/+/113804 > > [1] https://jenkins.ovirt.org/job/ovirt-system-tests_he-basic-suite-master/19... > > > > > Some more details: > > > > The function is: > > > > @order_by(_TEST_LIST) > > def test_ha_recovery(engine_api, get_ansible_host_for_vm): > > engine = engine_api.system_service() > > with engine_utils.wait_for_event(engine, [119, 9602, 506]): > > # VM_DOWN_ERROR event(119) > > # HA_VM_FAILED event event(9602) > > # VDS_INITIATED_RUN_VM event(506) > > ansible_host = get_ansible_host_for_vm(VM2_NAME) > > pid = ansible_host.shell('pgrep -f qemu.*guest=vm2')['stdout'].strip() > > ansible_host.shell('kill -KILL {}'.format(pid)) > > > > vm_service = test_utils.get_vm_service(engine, VM2_NAME) > > assertions.assert_true_within_long( > > lambda: > > vm_service.get().status == types.VmStatus.UP > > ) > > with engine_utils.wait_for_event(engine, 33): # USER_STOP_VM event > > vm_service.stop() > > > > It failed inside the 'with' statement. Can't find any of the expected > > events in engine.log. In last successful I see all three of them. > > > > We do not actively log anything about running the pgrep command, but > > it's logged by ansible on the host, to /var/log/messages. I see it in > > last successful, but not in above failed run, in any of the two hosts. > > So most likely it didn't even get to run pgrep. > > > > IMO we probably want some more information logged in such a case, to > > allow further investigation. > > > > Best regards, > > > > > Build Number: 1943 > > > Build Status: Still Failing > > > Triggered By: Started by timer > > > > > > ------------------------------------- > > > Changes Since Last Success: > > > ------------------------------------- > > > Changes for Build #1939 > > > [hbraha] ost: Check if user custom repos are used on VM > > > > > > > > > Changes for Build #1940 > > > [hbraha] network: add check_repos fixture > > > > > > > > > Changes for Build #1941 > > > [Andrej Cernek] network, pylint: Simplify pylintrc file > > > > > > > > > Changes for Build #1942 > > > [Andrej Cernek] network, pylint: Simplify pylintrc file > > > > > > > > > Changes for Build #1943 > > > [Andrej Cernek] network, pylint: Simplify pylintrc file > > > > > > > > > > > > > > > ----------------- > > > Failed Tests: > > > ----------------- > > > 1 tests failed. > > > FAILED: he-basic-suite-master.test-scenarios.test_004_basic_sanity.test_ha_recovery > > > > > > Error Message: > > > AssertionError: False != True after 600 seconds > > > > > > Stack Trace: > > > engine_api = <ovirtsdk4.Connection object at 0x7f408114c1d0> > > > get_ansible_host_for_vm = <function get_ansible_host_for_vm.<locals>.ansible_host_for at 0x7f4081171950> > > > > > > @order_by(_TEST_LIST) > > > def test_ha_recovery(engine_api, get_ansible_host_for_vm): > > > engine = engine_api.system_service() > > > with engine_utils.wait_for_event(engine, [119, 9602, 506]): > > > # VM_DOWN_ERROR event(119) > > > # HA_VM_FAILED event event(9602) > > > # VDS_INITIATED_RUN_VM event(506) > > > ansible_host = get_ansible_host_for_vm(VM2_NAME) > > > pid = ansible_host.shell('pgrep -f qemu.*guest=vm2')['stdout'].strip() > > > > ansible_host.shell('kill -KILL {}'.format(pid)) > > > > > > ../he-basic-suite-master/test-scenarios/test_004_basic_sanity.py:1070: > > > _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ > > > /usr/lib64/python3.6/contextlib.py:88: in __exit__ > > > next(self.gen) > > > ../ost_utils/ost_utils/engine_utils.py:42: in wait_for_event > > > lambda: > > > ../ost_utils/ost_utils/assertions.py:96: in assert_true_within_long > > > assert_equals_within_long(func, True, allowed_exceptions) > > > ../ost_utils/ost_utils/assertions.py:81: in assert_equals_within_long > > > func, value, LONG_TIMEOUT, allowed_exceptions=allowed_exceptions > > > _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ > > > > > > func = <function wait_for_event.<locals>.<lambda> at 0x7f40810d5bf8> > > > value = True, timeout = 600, allowed_exceptions = [], initial_wait = 0 > > > error_message = 'False != True after 600 seconds' > > > > > > def assert_equals_within( > > > func, value, timeout, allowed_exceptions=None, initial_wait=10, > > > error_message=None > > > ): > > > allowed_exceptions = allowed_exceptions or [] > > > res = '<no-result-obtained>' > > > with _EggTimer(timeout) as timer: > > > while not timer.elapsed(): > > > try: > > > res = func() > > > if res == value: > > > return > > > except Exception as exc: > > > if _instance_of_any(exc, allowed_exceptions): > > > time.sleep(3) > > > continue > > > > > > LOGGER.exception("Unhandled exception in %s", func) > > > raise > > > > > > if initial_wait == 0: > > > time.sleep(3) > > > else: > > > time.sleep(initial_wait) > > > initial_wait = 0 > > > try: > > > if error_message is None: > > > error_message = '%s != %s after %s seconds' % (res, value, timeout) > > > > raise AssertionError(error_message) > > > E AssertionError: False != True after 600 seconds > > > > > > ../ost_utils/ost_utils/assertions.py:59: AssertionError > > > > > > > > -- > > Didi > > > > -- > Didi -- Didi