avocado.core.runner: Unify the runner error handling

There are two places, where runner can modify the test's status, each
handling it differently. Let's create a method to handle such occasions
in the same manner.
Signed-off-by: NLukáš Doktor <ldoktor@redhat.com>

avocado/core/runner.py

@@ -40,6 +40,40 @@ TEST_LOG = logging.getLogger("avocado.test")
 APP_LOG = logging.getLogger("avocado.app")
 
 
+def add_runner_failure(test_state, new_status, message):
+    """
+    Append runner failure to the overall test status.
+
+    :param test_state: Original test state (dict)
+    :param new_status: New test status (PASS/FAIL/ERROR/INTERRUPTED/...)
+    :param message: The error message
+    """
+    # Try to propagate the message everywhere
+    message = ("Runner error occurred: %s\nOriginal status: %s\n%s"
+               % (message, test_state.get("status"), test_state))
+    TEST_LOG.error(message)
+    test_log = test_state.get("logfile")
+    if test_state.get("text_output"):
+        test_state["text_output"] = "%s\n%s\n" % (test_state["text_output"],
+                                                  message)
+    else:
+        test_state["text_output"] = message + "\n"
+    if test_log:
+        open(test_log, "a").write('\n' + message + '\n')
+    # Update the results
+    if test_state.get("fail_reason"):
+        test_state["fail_reason"] = "%s\n%s" % (test_state["fail_reason"],
+                                                message)
+    else:
+        test_state["fail_reason"] = message
+    if test_state.get("fail_class"):
+        test_state["fail_class"] = "%s\nRUNNER" % test_state["fail_class"]
+    else:
+        test_state["fail_class"] = "RUNNER"
+    test_state["status"] = new_status
+    return test_state
+
+
 class TestStatus(object):
 
     """
@@ -390,17 +424,8 @@ class TestRunner(object):
 
         # 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"
+            test_state = add_runner_failure(test_state, "INTERRUPTED",
+                                            abort_reason)
 
         # don't process other tests from the list
         if ctrl_c_count > 0:
@@ -408,14 +433,8 @@ class TestRunner(object):
 
         # Make sure the test status is correct
         if test_state.get('status') not in status.user_facing_status:
-            test_state['fail_reason'] = ("Test reports unsupported test "
-                                         "status %s.\nOriginal fail_reason: %s"
-                                         "\nOriginal fail_class: %s"
-                                         % (test_state.get('status'),
-                                            test_state.get('fail_reason'),
-                                            test_state.get('fail_class')))
-            test_state['fail_class'] = "RUNNER"
-            test_state['status'] = 'ERROR'
+            test_state = add_runner_failure(test_state, "ERROR", "Test reports"
+                                            " unsupported test status.")
 
         self.result.check_test(test_state)
         if test_state['status'] == "INTERRUPTED":

selftests/functional/test_basic.py

@@ -201,7 +201,7 @@ class RunnerOperationTest(unittest.TestCase):
             self.assertEqual(results["tests"][0]["status"], "ERROR",
                              "%s != %s\n%s" % (results["tests"][0]["status"],
                                                "ERROR", res))
-            self.assertIn("Original fail_reason: None",
+            self.assertIn("Runner error occurred: Test reports unsupported",
                           results["tests"][0]["fail_reason"])
 
     def test_hanged_test_with_status(self):
@@ -313,7 +313,7 @@ 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("RUNNER: Timeout reached", output,
+        self.assertIn("Runner error occurred: 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)
@@ -694,12 +694,13 @@ class RunnerSimpleTest(unittest.TestCase):
         debug_log = os.path.join(self.tmpdir, "latest", "test-results",
                                  sleep_dir, "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)
+        self.assertIn("Runner error occurred: Timeout reached", debug_log,
+                      "Runner error occurred: Timeout reached message not "
+                      "in the test's debug.log:\n%s" % debug_log)
+        self.assertNotIn("Traceback (most recent", 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

@@ -103,8 +103,9 @@ class JobTimeOutTest(unittest.TestCase):
         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"
+        self.assertIn("Runner error occurred: Timeout reached", debug_log,
+                      "Runner error occurred: 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"