avocado: Make each test to print its label at the beginning of each test

Fixes bug #77.

Replace the basic logging.StreamHandler used to control
avocado stdout for a version that allows us to skip printing
newlines at each message. Then use this stream handler to
log the test label at the beginning of each test, rather
than at the end. When the tests are done, they can now simply
print STATUS strings appropriately, therefore not requiring
to log the test label.

Both the HumanTestResult and VMTestResult classes were
adapted to use this new soluton.
Signed-off-by: NLucas Meneghel Rodrigues <lmr@redhat.com>

avocado/__init__.py

@@ -36,13 +36,18 @@ DEFAULT_LOGGING = {
             'class': 'logging.StreamHandler',
             'formatter': 'brief',
         },
+        'app': {
+            'level': 'INFO',
+            'class': 'avocado.core.output.ProgressStreamHandler',
+            'formatter': 'brief',
+        },
     },
     'loggers': {
         'avocado': {
             'handlers': ['console'],
         },
         'avocado.app': {
-            'handlers': ['console'],
+            'handlers': ['app'],
             'level': 'INFO',
             'propagate': False,
         },

avocado/core/output.py

@@ -22,6 +22,29 @@ import sys
 from avocado.utils import process
 
 
+class ProgressStreamHandler(logging.StreamHandler):
+
+    """
+    Handler class that allows users to skip new lines on each emission.
+    """
+
+    def emit(self, record):
+        try:
+            msg = self.format(record)
+            stream = self.stream
+            skip_newline = False
+            if hasattr(record, 'skip_newline'):
+                skip_newline = record.skip_newline
+            stream.write(msg)
+            if not skip_newline:
+                stream.write('\n')
+            self.flush()
+        except (KeyboardInterrupt, SystemExit):
+            raise
+        except:
+            self.handleError(record)
+
+
 def get_paginator():
     """
     Get a pipe. If we can't do that, return stdout.
@@ -95,21 +118,21 @@ class TermColors(object):
         self.WARN = ''
         self.ENDC = ''
 
-    def header_str(self, sr):
+    def header_str(self, msg):
         """
         Print a header string (blue colored).
 
         If the output does not support colors, just return the original string.
         """
-        return self.HEADER + sr + self.ENDC
+        return self.HEADER + msg + self.ENDC
 
-    def fail_header_str(self, sr):
+    def fail_header_str(self, msg):
         """
         Print a fail header string (red colored).
 
         If the output does not support colors, just return the original string.
         """
-        return self.FAIL + sr + self.ENDC
+        return self.FAIL + msg + self.ENDC
 
     def pass_str(self):
         """
@@ -164,13 +187,15 @@ class OutputManager(object):
     def __init__(self, logger_name='avocado.app'):
         self.console_log = logging.getLogger('avocado.app')
 
-    def _log(self, sr, level=logging.INFO):
+    def _log(self, msg, level=logging.INFO, skip_newline=False):
         """
         Write a message to the avocado.app logger.
 
-        :param sr: String to write.
+        :param msg: Message to write
+        :type msg: string
         """
-        self.console_log.log(level, sr)
+        extra = {'skip_newline': skip_newline}
+        self.console_log.log(level=level, msg=msg, extra=extra)
 
     def start_file_logging(self, logfile, level):
         """
@@ -205,88 +230,79 @@ class OutputManager(object):
         linux_logger.removeHandler(self.file_handler)
         self.file_handler.close()
 
-    def info(self, sr):
+    def info(self, msg, skip_newline=False):
         """
         Log a :mod:`logging.INFO` message.
 
-        :param sr: String to write.
+        :param msg: Message to write.
         """
-        self._log(sr, level=logging.INFO)
+        self._log(msg, level=logging.INFO, skip_newline=skip_newline)
 
-    def error(self, sr):
+    def error(self, msg):
         """
         Log a :mod:`logging.INFO` message.
 
-        :param sr: String to write.
+        :param msg: Message to write.
         """
-        self._log(sr, level=logging.ERROR)
+        self._log(msg, level=logging.ERROR)
 
-    def log_header(self, sr):
+    def log_header(self, msg):
         """
         Log a header message.
 
-        :param sr: String to write.
+        :param msg: Message to write.
         """
-        self.info(colors.header_str(sr))
+        self.info(colors.header_str(msg))
 
-    def log_fail_header(self, sr):
+    def log_fail_header(self, msg):
         """
         Log a fail header message (red, for critical errors).
 
-        :param sr: String to write.
+        :param msg: Message to write.
         """
-        self.info(colors.fail_header_str(sr))
+        self.info(colors.fail_header_str(msg))
 
-    def log_pass(self, label, t_elapsed):
+    def log_pass(self, t_elapsed):
         """
-        Log a test PASS message.
+        Log a PASS message.
 
-        :param label: Label for the PASS message (test name + index).
-        :param t_elapsed: Time it took for test to complete.
+        :param t_elapsed: Time it took for the operation to complete.
         """
-        normal_pass_msg = (label + " " + colors.pass_str() +
-                           " (%.2f s)" % t_elapsed)
+        normal_pass_msg = colors.pass_str() + " (%.2f s)" % t_elapsed
         self.info(normal_pass_msg)
 
-    def log_error(self, label, t_elapsed):
+    def log_error(self, t_elapsed):
         """
-        Log a test ERROR message.
+        Log an ERROR message.
 
-        :param label: Label for the FAIL message (test name + index).
-        :param t_elapsed: Time it took for test to complete.
+        :param t_elapsed: Time it took for the operation to complete.
         """
-        normal_error_msg = (label + " " + colors.error_str() +
-                            " (%.2f s)" % t_elapsed)
+        normal_error_msg = colors.error_str() + " (%.2f s)" % t_elapsed
         self.error(normal_error_msg)
 
-    def log_fail(self, label, t_elapsed):
+    def log_fail(self, t_elapsed):
         """
-        Log a test FAIL message.
+        Log a FAIL message.
 
-        :param label: Label for the FAIL message (test name + index).
-        :param t_elapsed: Time it took for test to complete.
+        :param t_elapsed: Time it took for the operation to complete.
         """
-        normal_fail_msg = (label + " " + colors.fail_str() +
-                           " (%.2f s)" % t_elapsed)
+        normal_fail_msg = colors.fail_str() + " (%.2f s)" % t_elapsed
         self.error(normal_fail_msg)
 
-    def log_skip(self, label, t_elapsed):
+    def log_skip(self, t_elapsed):
         """
-        Log a test SKIP message.
+        Log a SKIP message.
 
-        :param label: Label for the SKIP message (test name + index).
-        :param t_elapsed: Time it took for test to complete.
+        :param t_elapsed: Time it took for the operation to complete.
         """
-        normal_skip_msg = (label + " " + colors.skip_str())
+        normal_skip_msg = colors.skip_str()
         self.info(normal_skip_msg)
 
-    def log_warn(self, label, t_elapsed):
+    def log_warn(self, t_elapsed):
         """
-        Log a test WARN message.
+        Log a WARN message.
 
-        :param label: Label for the WARN message (test name + index).
-        :param t_elapsed: Time it took for test to complete.
+        :param t_elapsed: Time it took for the operation to complete.
         """
-        normal_warn_msg = (label + " " + colors.warn_str() +
-                           " (%.2f s)" % t_elapsed)
+        normal_warn_msg = colors.warn_str() + " (%.2f s)" % t_elapsed
         self.error(normal_warn_msg)

avocado/job.py

@@ -53,9 +53,9 @@ class TestRunner(object):
         self.job = job
         self.result = test_result
 
-    def _load_test_instance(self, params):
+    def load_test(self, params):
         """
-        Find the test url from the first component of the test shortname, and load the url.
+        Resolve and load the test url from the the test shortname.
 
         :param params: Dictionary with test params.
         :type params: dict
@@ -85,18 +85,6 @@ class TestRunner(object):
                                            job=self.job)
         return test_instance
 
-    def run_test(self, params):
-        """
-        Run a single test.
-
-        :param params: Dictionary with test params.
-        :type params: dict
-        :return: an instance of :class:`avocado.test.Test`.
-        """
-        test_instance = self._load_test_instance(params)
-        test_instance.run_avocado()
-        return test_instance
-
     def run(self, params_list):
         """
         Run one or more tests and report with test result.
@@ -108,7 +96,9 @@ class TestRunner(object):
         failures = []
         self.result.start_tests()
         for params in params_list:
-            test_instance = self.run_test(params)
+            test_instance = self.load_test(params)
+            self.result.start_test(test_instance)
+            test_instance.run_avocado()
             self.result.check_test(test_instance)
             if not status.mapping[test_instance.status]:
                 failures.append(test_instance.name)

avocado/plugins/vm.py

@@ -184,6 +184,8 @@ class VMTestResult(TestResult):
                                             self.tests_total,
                                             test.tagged_name)
 
+        self.stream.info(msg=self.test_label, skip_newline=True)
+
     def end_test(self, test):
         """
         Called when the given test has been run.
@@ -199,7 +201,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_pass(self, test)
-        self.stream.log_pass(self.test_label, test.time_elapsed)
+        self.stream.log_pass(test.time_elapsed)
 
     def add_error(self, test):
         """
@@ -208,7 +210,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_error(self, test)
-        self.stream.log_error(self.test_label, test.time_elapsed)
+        self.stream.log_error(test.time_elapsed)
 
     def add_fail(self, test):
         """
@@ -217,7 +219,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_fail(self, test)
-        self.stream.log_fail(self.test_label, test.time_elapsed)
+        self.stream.log_fail(test.time_elapsed)
 
     def add_skip(self, test):
         """
@@ -226,7 +228,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_skip(self, test)
-        self.stream.log_skip(self.test_label, test.time_elapsed)
+        self.stream.log_skip(test.time_elapsed)
 
     def add_warn(self, test):
         """
@@ -235,7 +237,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_warn(self, test)
-        self.stream.log_warn(self.test_label, test.time_elapsed)
+        self.stream.log_warn(test.time_elapsed)
 
 
 class RunVM(plugin.Plugin):

avocado/result.py

@@ -13,7 +13,12 @@
 # Authors: Lucas Meneghel Rodrigues <lmr@redhat.com>
 #          Ruda Moura <rmoura@redhat.com>
 
-"""Test result module."""
+"""
+Contains the definition of the TestResult class, used for output in avocado.
+
+It also contains the most basic test result class, HumanTestResult,
+used by the test runner.
+"""
 
 
 class TestResult(object):
@@ -116,7 +121,6 @@ class TestResult(object):
 
         :param test: an instance of :class:`avocado.test.Test`.
         """
-        self.start_test(test)
         status_map = {'PASS': self.add_pass,
                       'ERROR': self.add_error,
                       'FAIL': self.add_fail,
@@ -161,6 +165,7 @@ class HumanTestResult(TestResult):
         self.test_label = '(%s/%s) %s: ' % (self.tests_run,
                                             self.tests_total,
                                             test.tagged_name)
+        self.stream.info(msg=self.test_label, skip_newline=True)
 
     def end_test(self, test):
         """
@@ -177,7 +182,7 @@ class HumanTestResult(TestResult):
         :param test: an instance of :class:`avocado.test.Test`.
         """
         TestResult.add_pass(self, test)
-        self.stream.log_pass(self.test_label, test.time_elapsed)
+        self.stream.log_pass(test.time_elapsed)
 
     def add_error(self, test):
         """
@@ -186,7 +191,7 @@ class HumanTestResult(TestResult):
         :param test: an instance of :class:`avocado.test.Test`.
         """
         TestResult.add_error(self, test)
-        self.stream.log_error(self.test_label, test.time_elapsed)
+        self.stream.log_error(test.time_elapsed)
 
     def add_fail(self, test):
         """
@@ -195,7 +200,7 @@ class HumanTestResult(TestResult):
         :param test: an instance of :class:`avocado.test.Test`.
         """
         TestResult.add_fail(self, test)
-        self.stream.log_fail(self.test_label, test.time_elapsed)
+        self.stream.log_fail(test.time_elapsed)
 
     def add_skip(self, test):
         """
@@ -204,7 +209,7 @@ class HumanTestResult(TestResult):
         :param test: an instance of :class:`avocado.test.Test`.
         """
         TestResult.add_skip(self, test)
-        self.stream.log_skip(self.test_label, test.time_elapsed)
+        self.stream.log_skip(test.time_elapsed)
 
     def add_warn(self, test):
         """
@@ -213,4 +218,4 @@ class HumanTestResult(TestResult):
         :param test: an instance of :class:`avocado.test.Test`.
         """
         TestResult.add_warn(self, test)
-        self.stream.log_warn(self.test_label, test.time_elapsed)
+        self.stream.log_warn(test.time_elapsed)

selftests/all/unit/avocado/vm_unittest.py

@@ -35,13 +35,16 @@ class _Stream(object):
     def start_file_logging(self, param1, param2):
         pass
 
+    def info(self, msg, skip_newline=False):
+        pass
+
     def log_header(self, param):
         pass
 
     def stop_file_logging(self):
         pass
 
-    def log_pass(self, param1, param2):
+    def log_pass(self, param1):
         pass
 
 
@@ -65,6 +68,7 @@ class VMResultTest(unittest.TestCase):
             test = vm.Test(name=tst['test'],
                            time=tst['time'],
                            status=tst['status'])
+            self.test_result.start_test(test)
             self.test_result.check_test(test)
             if not status.mapping[test.status]:
                 failures.append(test.tagged_name)