From 1555489a1d4e958f31a8d85f6243d1a18f396e56 Mon Sep 17 00:00:00 2001 From: Jan Richter Date: Thu, 31 Oct 2024 12:54:22 +0100 Subject: [PATCH] Avocado instrumented timeout handling in thread This commit changes the way how avocado instrumented runner handles test timeouts. For timeout handling, we used to use signals and raising TestInterrupt error. Such solution has an issue that we can't control where in the code the Error will be raised, and it can be handled before it reaches the runner layer. More info about this issue in #6046. This change removes the signal handling and uses threading instead. Now each test method will be run in a separated thread and this thread will be terminated if timeout is reached. This solution selves the raising error issue and keeps the current test lifecycle untouched. Reference: #6046 Signed-off-by: Jan Richter --- avocado/core/test.py | 30 ++++++++--- .../plugins/runners/avocado_instrumented.py | 26 +++------- selftests/check.py | 2 +- .../plugin/runners/avocado_instrumented.py | 51 ++++++++++++++++++- 4 files changed, 80 insertions(+), 29 deletions(-) diff --git a/avocado/core/test.py b/avocado/core/test.py index 763cf705bb..fedac7d772 100644 --- a/avocado/core/test.py +++ b/avocado/core/test.py @@ -22,6 +22,8 @@ import functools import inspect import logging +import multiprocessing +import multiprocessing.pool import os import shutil import sys @@ -654,14 +656,26 @@ def _setup_environment_variables(self): def _catch_test_status(self, method): """Wrapper around test methods for catching and logging failures.""" - try: + + def set_new_event_loop_for_method(method): + asyncio.set_event_loop(asyncio.new_event_loop()) method() - if self.__log_warn_used and self.__status not in STATUSES_NOT_OK: - raise exceptions.TestWarn( - "Test passed but there were warnings " - "during execution. Check the log for " - "details." - ) + + try: + pool = multiprocessing.pool.ThreadPool(1) + res = pool.apply_async(set_new_event_loop_for_method, [method]) + pool.close() + try: + res.get(self.timeout) + if self.__log_warn_used and self.__status not in STATUSES_NOT_OK: + raise exceptions.TestWarn( + "Test passed but there were warnings " + "during execution. Check the log for " + "details." + ) + except multiprocessing.TimeoutError: + raise exceptions.TestInterrupt("Test interrupted: Timeout reached") + except exceptions.TestBaseException as detail: self.__status = detail.status self.__fail_class = detail.__class__.__name__ @@ -686,6 +700,8 @@ def _catch_test_status(self, method): ) for e_line in tb_info: self.log.error(e_line) + finally: + pool.terminate() def run_avocado(self): """ diff --git a/avocado/plugins/runners/avocado_instrumented.py b/avocado/plugins/runners/avocado_instrumented.py index a08ecceaa2..5aa779bd7e 100644 --- a/avocado/plugins/runners/avocado_instrumented.py +++ b/avocado/plugins/runners/avocado_instrumented.py @@ -8,11 +8,7 @@ from avocado.core.exceptions import TestInterrupt from avocado.core.nrunner.app import BaseRunnerApp -from avocado.core.nrunner.runner import ( - RUNNER_RUN_CHECK_INTERVAL, - RUNNER_RUN_STATUS_INTERVAL, - BaseRunner, -) +from avocado.core.nrunner.runner import RUNNER_RUN_CHECK_INTERVAL, BaseRunner from avocado.core.test import TestID from avocado.core.tree import TreeNodeEnvOnly from avocado.core.utils import loader, messages @@ -138,23 +134,14 @@ def _run_avocado(runnable, queue): ) @staticmethod - def _monitor(proc, time_started, queue): - timeout = float("inf") - next_status_time = None + def _monitor(queue): while True: time.sleep(RUNNER_RUN_CHECK_INTERVAL) - now = time.monotonic() if queue.empty(): - if next_status_time is None or now > next_status_time: - next_status_time = now + RUNNER_RUN_STATUS_INTERVAL - yield messages.RunningMessage.get() - if (now - time_started) > timeout: - proc.terminate() + yield messages.RunningMessage.get() else: message = queue.get() - if message.get("type") == "early_state": - timeout = float(message.get("timeout") or float("inf")) - else: + if message.get("type") != "early_state": yield message if message.get("status") == "finished": break @@ -172,13 +159,12 @@ def run(self, runnable): process.start() - time_started = time.monotonic() - for message in self._monitor(process, time_started, queue): + for message in self._monitor(queue): yield message except TestInterrupt: process.terminate() - for message in self._monitor(process, time_started, queue): + for message in self._monitor(queue): yield message except Exception as e: yield messages.StderrMessage.get(traceback.format_exc()) diff --git a/selftests/check.py b/selftests/check.py index d24009bd49..da86be24ce 100755 --- a/selftests/check.py +++ b/selftests/check.py @@ -29,7 +29,7 @@ "nrunner-requirement": 28, "unit": 678, "jobs": 11, - "functional-parallel": 313, + "functional-parallel": 314, "functional-serial": 7, "optional-plugins": 0, "optional-plugins-golang": 2, diff --git a/selftests/functional/plugin/runners/avocado_instrumented.py b/selftests/functional/plugin/runners/avocado_instrumented.py index efcddba787..ed8e9c1390 100644 --- a/selftests/functional/plugin/runners/avocado_instrumented.py +++ b/selftests/functional/plugin/runners/avocado_instrumented.py @@ -1,8 +1,30 @@ +import json +import os + from avocado import Test from avocado.core.exit_codes import AVOCADO_JOB_INTERRUPTED -from avocado.utils import process +from avocado.utils import process, script from selftests.utils import AVOCADO, TestCaseTmpDir +TIMEOU_TEST_WITH_EXCEPTION = """ +import time + +from avocado import Test + +class TimeoutTest(Test): + + timeout = 3 + + def test(self): + try: + time.sleep(5) + except Exception: + pass + + def tearDown(self): + self.log.info("TearDown") +""" + class AvocadoInstrumentedRunnerTest(TestCaseTmpDir, Test): def test_timeout(self): @@ -16,3 +38,30 @@ def test_timeout(self): "examples/tests/timeouttest.py:TimeoutTest.test: INTERRUPTED: Test interrupted: Timeout reached", result.stdout_text, ) + + def test_timeout_with_exception(self): + with script.TemporaryScript( + "test_timeout.py", + TIMEOU_TEST_WITH_EXCEPTION, + "avocado_timeout_test", + ) as tst: + res = process.run( + ( + f"{AVOCADO} run --disable-sysinfo " + f"--job-results-dir {self.tmpdir.name} {tst} " + f"--json -" + ), + ignore_status=True, + ) + results = json.loads(res.stdout_text) + self.assertIn( + "Test interrupted: Timeout reached", + results["tests"][0]["fail_reason"], + ) + debug_log_path = results["tests"][0]["logfile"] + self.assertTrue(os.path.exists(debug_log_path)) + with open(debug_log_path, encoding="utf-8") as file: + self.assertIn( + "INFO | TearDown", + file.read(), + )