Merge branch 'ldoktor-test-interruption2'

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('')

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()

selftests/functional/test_job_timeout.py

+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 '