From a6128a0f4e50c48aec0c8aa139055bdf4e249671 Mon Sep 17 00:00:00 2001 From: Jan Richter Date: Wed, 8 Nov 2023 17:11:58 +0100 Subject: [PATCH] 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: #5707 #5407 Signed-off-by: Jan Richter --- avocado/core/exceptions.py | 10 ++ .../plugins/runners/avocado_instrumented.py | 13 +++ selftests/functional/job_timeout.py | 98 ++++++++++++++++--- 3 files changed, 110 insertions(+), 11 deletions(-) diff --git a/avocado/core/exceptions.py b/avocado/core/exceptions.py index b4730ddd84..16e51256c4 100644 --- a/avocado/core/exceptions.py +++ b/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" diff --git a/avocado/plugins/runners/avocado_instrumented.py b/avocado/plugins/runners/avocado_instrumented.py index 55b80f5d00..d4bec69575 100644 --- a/avocado/plugins/runners/avocado_instrumented.py +++ b/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( diff --git a/selftests/functional/job_timeout.py b/selftests/functional/job_timeout.py index f5af1722d8..fea52c42a4 100644 --- a/selftests/functional/job_timeout.py +++ b/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__":