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 <jarichte@redhat.com>

Author: richtja

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):
         """

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())

selftests/check.py

@@ -29,7 +29,7 @@
     "nrunner-requirement": 28,
     "unit": 682,
     "jobs": 11,
-    "functional-parallel": 317,
+    "functional-parallel": 318,
     "functional-serial": 7,
     "optional-plugins": 0,
     "optional-plugins-golang": 2,

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(),
+                )