From cf166322f175dd22f386f4a871948e9b082a9853 Mon Sep 17 00:00:00 2001 From: Jan Richter Date: Wed, 8 Nov 2023 16:57:38 +0100 Subject: [PATCH 1/3] Improve the timeout fail reason When the test is interrupted because of timeout we use `fail_reason` message as `Runner error occurred:`. IMO such message can mislead the user to problem with runner. Let's update this message to more correct `Test interrupted:` Signed-off-by: Jan Richter --- avocado/core/task/statemachine.py | 2 +- selftests/functional/job_timeout.py | 4 ++-- selftests/functional/plugin/runners/avocado_instrumented.py | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/avocado/core/task/statemachine.py b/avocado/core/task/statemachine.py index 6bafbd97fb..a8c571be9e 100644 --- a/avocado/core/task/statemachine.py +++ b/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, ) diff --git a/selftests/functional/job_timeout.py b/selftests/functional/job_timeout.py index 6e1d4a4703..f5af1722d8 100644 --- a/selftests/functional/job_timeout.py +++ b/selftests/functional/job_timeout.py @@ -105,10 +105,10 @@ def _check_timeout_msg(self, idx): 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", + "Test interrupted: Timeout reached", debug_log, ( - f"Runner error occurred: Timeout reached message not " + f"Test interrupted: Timeout reached message not " f"in the {idx}st test's debug.log:\n{debug_log}" ), ) diff --git a/selftests/functional/plugin/runners/avocado_instrumented.py b/selftests/functional/plugin/runners/avocado_instrumented.py index a7b182d3a3..efcddba787 100644 --- a/selftests/functional/plugin/runners/avocado_instrumented.py +++ b/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, ) From cf0d373429f6dd4250d66e2d0baabbbc3fd700f5 Mon Sep 17 00:00:00 2001 From: Jan Richter Date: Wed, 8 Nov 2023 17:06:45 +0100 Subject: [PATCH 2/3] Move instrumented test monitoring into method It will move the message monitoring loop for avocado-instrumented test into its own method. With this change, we can reuse the monitoring loop. Signed-off-by: Jan Richter --- .../plugins/runners/avocado_instrumented.py | 45 ++++++++++--------- 1 file changed, 24 insertions(+), 21 deletions(-) diff --git a/avocado/plugins/runners/avocado_instrumented.py b/avocado/plugins/runners/avocado_instrumented.py index f3db717ce9..55b80f5d00 100644 --- a/avocado/plugins/runners/avocado_instrumented.py +++ b/avocado/plugins/runners/avocado_instrumented.py @@ -129,6 +129,28 @@ 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 self.runnable = runnable @@ -142,28 +164,9 @@ 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 Exception as e: yield messages.StderrMessage.get(traceback.format_exc()) yield messages.FinishedMessage.get( From a6128a0f4e50c48aec0c8aa139055bdf4e249671 Mon Sep 17 00:00:00 2001 From: Jan Richter Date: Wed, 8 Nov 2023 17:11:58 +0100 Subject: [PATCH 3/3] 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__":