avocado-instrumented tearDown during timeout

It introduces SIGTERM handling in avocado-instrumented tests to run a
tearDown method when the test has been interrupted. It uses
functionality from Test class, which already handles interruptions. It
only adds a monitoring loop to send all messages created by tearDown to
avocado core.

Reference: avocado-framework#5707 avocado-framework#5407
Signed-off-by: Jan Richter <[email protected]>

avocado/core/exceptions.py

@@ -165,3 +165,13 @@ class TestCancel(TestBaseException):
     """
 
     status = "CANCEL"
+
+
+class TestInterrupt(TestBaseException):
+    """
+    Indicates that a test was interrupted.
+
+    Should be thrown when the test method is interrupted by user or timeout.
+    """
+
+    status = "INTERRUPTED"

avocado/plugins/runners/avocado_instrumented.py

@@ -1,10 +1,12 @@
 import multiprocessing
 import os
+import signal
 import sys
 import tempfile
 import time
 import traceback
 
+from avocado.core.exceptions import TestInterrupt
 from avocado.core.nrunner.app import BaseRunnerApp
 from avocado.core.nrunner.runner import (
     RUNNER_RUN_CHECK_INTERVAL,
@@ -42,6 +44,11 @@ class and method names should be separated by a ":".  One
         "job.run.store_logging_stream",
     ]
 
+    @staticmethod
+    def signal_handler(signum, frame):  # pylint: disable=W0613
+        if signum == signal.SIGTERM.value:
+            raise TestInterrupt("Test interrupted: Timeout reached")
+
     @staticmethod
     def _create_params(runnable):
         """Create params for the test"""
@@ -69,6 +76,7 @@ def _run_avocado(runnable, queue):
             #
             # To be defined: if the resolution uri should be composed like
             # this, or broken down and stored into other data fields
+            signal.signal(signal.SIGTERM, AvocadoInstrumentedTestRunner.signal_handler)
             module_path, klass_method = runnable.uri.split(":", 1)
 
             klass, method = klass_method.split(".", 1)
@@ -153,6 +161,7 @@ def _monitor(proc, time_started, queue):
 
     def run(self, runnable):
         # pylint: disable=W0201
+        signal.signal(signal.SIGTERM, AvocadoInstrumentedTestRunner.signal_handler)
         self.runnable = runnable
         yield messages.StartedMessage.get()
         try:
@@ -167,6 +176,10 @@ def run(self, runnable):
             for message in self._monitor(process, time_started, queue):
                 yield message
 
+        except TestInterrupt:
+            process.terminate()
+            for message in self._monitor(process, time_started, queue):
+                yield message
         except Exception as e:
             yield messages.StderrMessage.get(traceback.format_exc())
             yield messages.FinishedMessage.get(

selftests/functional/job_timeout.py

@@ -1,5 +1,6 @@
 import glob
 import os
+import tempfile
 import unittest
 import xml.dom.minidom
 
@@ -26,6 +27,22 @@ def test01pass(self):
         pass
     def test02pass(self):
         pass
+
+    def tearDown(self):
+        self.log.info("tearDown")
+"""
+
+PYTHON_LONG_CONTENT = """#!/usr/bin/env python
+import time
+from avocado import Test
+
+class Dummy(Test):
+    def test00sleep(self):
+        time.sleep(10)
+
+    def tearDown(self):
+        time.sleep(5)
+        self.log.info("tearDown")
 """
 
 
@@ -48,6 +65,10 @@ def setUp(self):
             "sleep_test.py", PYTHON_CONTENT, "avocado_timeout_functional"
         )
         self.py.save()
+        self.long_py = script.TemporaryScript(
+            "sleep_long.py", PYTHON_LONG_CONTENT, "avocado_timeout_functional"
+        )
+        self.long_py.save()
 
     def run_and_check(self, cmd_line, e_rc, e_ntests, terminated_tests):
         os.chdir(BASEDIR)
@@ -100,18 +121,22 @@ def run_and_check(self, cmd_line, e_rc, e_ntests, terminated_tests):
                 f"Test {terminated_test} was not in {output}.",
             )
 
-    def _check_timeout_msg(self, idx):
+    def _check_timeout_msg(self, idx, message, negation=False):
         res_dir = os.path.join(self.tmpdir.name, "latest", "test-results")
         debug_log_paths = glob.glob(os.path.join(res_dir, f"{idx}-*", "debug.log"))
         debug_log = genio.read_file(debug_log_paths[0])
-        self.assertIn(
-            "Test interrupted: Timeout reached",
-            debug_log,
-            (
-                f"Test interrupted: Timeout reached message not "
-                f"in the {idx}st test's debug.log:\n{debug_log}"
-            ),
-        )
+        if not negation:
+            self.assertIn(
+                message,
+                debug_log,
+                f"{message} message not in the {idx}st test's debug.log:\n{debug_log}",
+            )
+        else:
+            self.assertNotIn(
+                message,
+                debug_log,
+                f"{message} message is in the {idx}st test's debug.log:\n{debug_log}",
+            )
 
     def test_sleep_short_timeout(self):
         cmd_line = (
@@ -132,7 +157,7 @@ def test_sleep_longer_timeout_interrupted(self):
         self.run_and_check(
             cmd_line, exit_codes.AVOCADO_JOB_INTERRUPTED, 2, [self.script_long.path]
         )
-        self._check_timeout_msg(1)
+        self._check_timeout_msg(1, "Test interrupted: Timeout reached")
 
     def test_sleep_longer_timeout_all_ok(self):
         cmd_line = (
@@ -155,7 +180,7 @@ def test_sleep_short_timeout_with_test_methods(self):
             3,
             [f"{self.py.path}:Dummy.test00sleep"],
         )
-        self._check_timeout_msg(1)
+        self._check_timeout_msg(1, "Test interrupted: Timeout reached")
 
     def test_invalid_values(self):
         cmd_line = (
@@ -205,11 +230,62 @@ def test_valid_values(self):
         result = process.run(cmd_line, ignore_status=True)
         self.assertEqual(result.exit_status, exit_codes.AVOCADO_ALL_OK)
 
+    def test_timout_with_tear_down(self):
+        cmd_line = (
+            f"{AVOCADO} run --job-results-dir {self.tmpdir.name} "
+            f"--disable-sysinfo "
+            f"--job-timeout=5 {self.py.path}"
+        )
+        self.run_and_check(
+            cmd_line,
+            exit_codes.AVOCADO_JOB_INTERRUPTED,
+            3,
+            [f"{self.py.path}:Dummy.test00sleep"],
+        )
+        self._check_timeout_msg(1, "tearDown")
+
+    def test_timeout_with_long_tear_down(self):
+        config = "[runner.task.interval]\nfrom_soft_to_hard_termination=10\n"
+        fd, config_file = tempfile.mkstemp(dir=self.tmpdir.name)
+        os.write(fd, config.encode())
+        os.close(fd)
+        cmd_line = (
+            f"{AVOCADO} --config {config_file} run --job-results-dir {self.tmpdir.name} "
+            f"--disable-sysinfo "
+            f"--job-timeout=5 {self.long_py.path}"
+        )
+        self.run_and_check(
+            cmd_line,
+            exit_codes.AVOCADO_JOB_INTERRUPTED,
+            1,
+            [f"{self.long_py.path}:Dummy.test00sleep"],
+        )
+        self._check_timeout_msg(1, "tearDown")
+
+    def test_timeout_with_long_tear_down_interupted(self):
+        config = "[runner.task.interval]\nfrom_soft_to_hard_termination=3\n"
+        fd, config_file = tempfile.mkstemp(dir=self.tmpdir.name)
+        os.write(fd, config.encode())
+        os.close(fd)
+        cmd_line = (
+            f"{AVOCADO} --config {config_file} run --job-results-dir {self.tmpdir.name} "
+            f"--disable-sysinfo "
+            f"--job-timeout=5 {self.long_py.path}"
+        )
+        self.run_and_check(
+            cmd_line,
+            exit_codes.AVOCADO_JOB_INTERRUPTED,
+            1,
+            [f"{self.long_py.path}:Dummy.test00sleep"],
+        )
+        self._check_timeout_msg(1, "tearDown", True)
+
     def tearDown(self):
         super().tearDown()
         self.script_short.remove()
         self.script_long.remove()
         self.py.remove()
+        self.long_py.remove()
 
 
 if __name__ == "__main__":