Avocado instrumented timeout handling in thread

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 _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 @@
                 )
             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 @@
             )
 
     @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 @@
 
             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": 678,
     "jobs": 11,
-    "functional-parallel": 313,
+    "functional-parallel": 314,
     "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(),
+                )