Merge remote-tracking branch 'richtja/tearDown_fix'

Signed-off-by: Cleber Rosa <[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/core/task/statemachine.py

@@ -205,7 +205,7 @@ async def _send_finished_tasks_message(self, terminate_tasks, reason):
             task_id = str(terminated_task.task.identifier)
             job_id = terminated_task.task.job_id
             log_message = messages.LogMessage.get(
-                f"{time.strftime('%Y-%m-%d %H:%M:%S', time.localtime())} | Runner error occurred: {reason}",
+                f"{time.strftime('%Y-%m-%d %H:%M:%S', time.localtime())} | Test interrupted: {reason}",
                 id=task_id,
                 job_id=job_id,
             )

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)
@@ -129,8 +137,31 @@ def _run_avocado(runnable, queue):
                 )
             )
 
+    @staticmethod
+    def _monitor(proc, time_started, queue):
+        timeout = float("inf")
+        next_status_time = None
+        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()
+            else:
+                message = queue.get()
+                if message.get("type") == "early_state":
+                    timeout = float(message.get("timeout") or float("inf"))
+                else:
+                    yield message
+                if message.get("status") == "finished":
+                    break
+
     def run(self, runnable):
         # pylint: disable=W0201
+        signal.signal(signal.SIGTERM, AvocadoInstrumentedTestRunner.signal_handler)
         self.runnable = runnable
         yield messages.StartedMessage.get()
         try:
@@ -142,28 +173,13 @@ def run(self, runnable):
             process.start()
 
             time_started = time.monotonic()
+            for message in self._monitor(process, time_started, queue):
+                yield message
 
-            timeout = float("inf")
-            next_status_time = None
-            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:
-                        process.terminate()
-                        yield messages.FinishedMessage.get("interrupted", "timeout")
-                        break
-                else:
-                    message = queue.get()
-                    if message.get("type") == "early_state":
-                        timeout = float(message.get("timeout") or float("inf"))
-                    else:
-                        yield message
-                    if message.get("status") == "finished":
-                        break
+        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(
-            "Runner error occurred: Timeout reached",
-            debug_log,
-            (
-                f"Runner error occurred: 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__":

selftests/functional/plugin/runners/avocado_instrumented.py

@@ -13,6 +13,6 @@ def test_timeout(self):
         result = process.run(cmd_line, ignore_status=True)
         self.assertEqual(result.exit_status, AVOCADO_JOB_INTERRUPTED)
         self.assertIn(
-            "examples/tests/timeouttest.py:TimeoutTest.test:  INTERRUPTED: timeout",
+            "examples/tests/timeouttest.py:TimeoutTest.test:  INTERRUPTED: Test interrupted: Timeout reached",
             result.stdout_text,
         )