diff --git a/avocado/core/runner.py b/avocado/core/runner.py index fc445abcc127b2c12bf10153a9dd8e6d6ab49079..33570339f5f0ad70ddb9078ffcc98e485796e474 100644 --- a/avocado/core/runner.py +++ b/avocado/core/runner.py @@ -37,6 +37,7 @@ from ..utils import runtime from ..utils import process TEST_LOG = logging.getLogger("avocado.test") +APP_LOG = logging.getLogger("avocado.app") class TestStatus(object): @@ -68,9 +69,8 @@ class TestStatus(object): # Let's catch all exceptions, since errors here mean a # crash in avocado. except Exception as details: - log = logging.getLogger("avocado.app") - log.error("\nError receiving message from test: %s -> %s", - details.__class__, details) + APP_LOG.error("\nError receiving message from test: %s -> %s", + details.__class__, details) stacktrace.log_exc_info(sys.exc_info(), 'avocado.app.tracebacks') return None @@ -222,14 +222,20 @@ class TestRunner(object): """ signal.signal(signal.SIGTSTP, signal.SIG_IGN) logger_list_stdout = [logging.getLogger('avocado.test.stdout'), - logging.getLogger('avocado.test'), + TEST_LOG, logging.getLogger('paramiko')] logger_list_stderr = [logging.getLogger('avocado.test.stderr'), - logging.getLogger('avocado.test'), + TEST_LOG, logging.getLogger('paramiko')] sys.stdout = output.LoggingFile(logger=logger_list_stdout) sys.stderr = output.LoggingFile(logger=logger_list_stderr) + def sigterm_handler(signum, frame): # pylint: disable=W0613 + """ Produce traceback on SIGTERM """ + raise SystemExit("Test interrupted by SIGTERM") + + signal.signal(signal.SIGTERM, sigterm_handler) + instance = loader.load_test(test_factory) if instance.runner_queue is None: instance.runner_queue = queue @@ -238,17 +244,6 @@ class TestRunner(object): early_state['early_status'] = True queue.put(early_state) - def timeout_handler(signum, frame): - e_msg = "Timeout reached waiting for %s to end" % instance - raise exceptions.TestTimeoutInterrupted(e_msg) - - def interrupt_handler(signum, frame): - e_msg = "Test %s interrupted by user" % instance - raise exceptions.TestInterruptedError(e_msg) - - signal.signal(signal.SIGUSR1, timeout_handler) - signal.signal(signal.SIGINT, interrupt_handler) - self.result.start_test(early_state) try: instance.run_avocado() @@ -290,15 +285,13 @@ class TestRunner(object): with sigtstp: msg = "ctrl+z pressed, %%s test (%s)" % proc.pid if self.sigstopped: - logging.getLogger("avocado.app").info("\n" + msg, - "resumming") - logging.getLogger("avocado.test").info(msg, "resumming") + APP_LOG.info("\n" + msg, "resumming") + TEST_LOG.info(msg, "resumming") process.kill_process_tree(proc.pid, signal.SIGCONT, False) self.sigstopped = False else: - logging.getLogger("avocado.app").info("\n" + msg, - "stopping") - logging.getLogger("avocado.test").info(msg, "stopping") + APP_LOG.info("\n" + msg, "stopping") + TEST_LOG.info(msg, "stopping") process.kill_process_tree(proc.pid, signal.SIGSTOP, False) self.sigstopped = True @@ -332,12 +325,14 @@ class TestRunner(object): stage_2_msg_displayed = False first = 0.01 step = 0.1 + abort_reason = None while True: try: if time.time() >= deadline: + abort_reason = "Timeout reached" try: - os.kill(proc.pid, signal.SIGUSR1) + os.kill(proc.pid, signal.SIGTERM) except OSError: pass break @@ -359,6 +354,7 @@ class TestRunner(object): ctrl_c_count += 1 if ctrl_c_count == 1: if not stage_1_msg_displayed: + abort_reason = "Interrupted by ctrl+c" self.job.log.debug("\nInterrupt requested. Waiting %d " "seconds for test to finish " "(ignoring new Ctrl+C until then)", @@ -367,6 +363,7 @@ class TestRunner(object): ignore_time_started = time.time() if (ctrl_c_count > 1) and (time_elapsed > ignore_window): if not stage_2_msg_displayed: + abort_reason = "Interrupted by ctrl+c (multiple-times)" self.job.log.debug("Killing test subprocess %s", proc.pid) stage_2_msg_displayed = True @@ -379,6 +376,20 @@ class TestRunner(object): test_state = test_status.abort(proc, time_started, cycle_timeout, first, step) + # Try to log the timeout reason to test's results and update test_state + if abort_reason: + TEST_LOG.error(abort_reason) + test_log = test_state.get("logfile") + if test_log: + open(test_log, "a").write("\nRUNNER: " + abort_reason + "\n") + if test_state.get("text_output"): + test_state["text_output"] += "\nRUNNER: " + abort_reason + "\n" + else: + test_state["text_output"] = abort_reason + test_state["status"] = "INTERRUPTED" + test_state["fail_reason"] = abort_reason + test_state["fail_class"] = "RUNNER" + # don't process other tests from the list if ctrl_c_count > 0: self.job.log.debug('') diff --git a/selftests/functional/test_basic.py b/selftests/functional/test_basic.py index f195c134fb1e40135347e7461b4b5838f8cee4cb..acf30d2a80ebc054ea7126c97f933453fd84a3aa 100644 --- a/selftests/functional/test_basic.py +++ b/selftests/functional/test_basic.py @@ -255,8 +255,8 @@ class RunnerOperationTest(unittest.TestCase): "Avocado crashed (rc %d):\n%s" % (unexpected_rc, result)) self.assertEqual(result.exit_status, expected_rc, "Avocado did not return rc %d:\n%s" % (expected_rc, result)) - self.assertIn("TestTimeoutInterrupted: Timeout reached waiting for", output, - "Test did not fail with timeout exception:\n%s" % output) + self.assertIn("RUNNER: Timeout reached", output, + "Timeout reached message not found in the output:\n%s" % output) # Ensure no test aborted error messages show up self.assertNotIn("TestAbortedError: Test aborted unexpectedly", output) @@ -630,8 +630,17 @@ class RunnerSimpleTest(unittest.TestCase): "stopped.") self.assertIn("TIME", output, "TIME not in the output, avocado " "probably died unexpectadly") - self.assertEqual(proc.get_status(), 1, "Avocado did not finish with " + self.assertEqual(proc.get_status(), 8, "Avocado did not finish with " "1.") + debug_log = os.path.join(self.tmpdir, "latest", "test-results", + "1-_bin_sleep 60", "debug.log") + debug_log = open(debug_log).read() + self.assertIn("RUNNER: Timeout reached", debug_log, "RUNNER: Timeout " + "reached message not in the test's debug.log:\n%s" + % debug_log) + self.assertNotIn("Traceback", debug_log, "Traceback present in the " + "test's debug.log file, but it was suppose to be " + "stopped and unable to produce it.\n%s" % debug_log) def tearDown(self): self.pass_script.remove() diff --git a/selftests/functional/test_job_timeout.py b/selftests/functional/test_job_timeout.py index 88842fd9941ed0e98d47c2fd703168a4b4a29d04..3ca216697ea64960a96ec470ea549ecb0e05ce83 100644 --- a/selftests/functional/test_job_timeout.py +++ b/selftests/functional/test_job_timeout.py @@ -1,3 +1,4 @@ +import glob import os import sys import tempfile @@ -98,6 +99,17 @@ class JobTimeOutTest(unittest.TestCase): "Unexpected number of test skips, " "XML:\n%s" % xml_output) + def _check_timeout_msg(self, idx): + res_dir = os.path.join(self.tmpdir, "latest", "test-results") + debug_log = glob.glob(os.path.join(res_dir, "%s-*" % idx, "debug.log")) + debug_log = open(debug_log[0]).read() + self.assertIn("RUNNER: Timeout reached", debug_log, "RUNNER: Timeout " + "reached message not in the %sst test's debug.log:\n%s" + % (idx, debug_log)) + self.assertIn("Traceback (most recent call last)", debug_log, + "Traceback not present in the %sst test's debug.log:\n%s" + % (idx, debug_log)) + def test_sleep_longer_timeout(self): cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off ' '--xunit - --job-timeout=5 %s examples/tests/passtest.py' % @@ -110,6 +122,7 @@ class JobTimeOutTest(unittest.TestCase): (self.tmpdir, self.script.path)) self.run_and_check(cmd_line, exit_codes.AVOCADO_JOB_INTERRUPTED, 2, 1, 0, 1) + self._check_timeout_msg(1) def test_sleep_short_timeout_with_test_methods(self): cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off ' @@ -117,6 +130,7 @@ class JobTimeOutTest(unittest.TestCase): (self.tmpdir, self.py.path)) self.run_and_check(cmd_line, exit_codes.AVOCADO_JOB_INTERRUPTED, 3, 1, 0, 2) + self._check_timeout_msg(1) def test_invalid_values(self): cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off '