avocado.core.output: View() API overhaul

Organize the log APIs into:

* APIs that log operation statuses (.log_ui_status)
* More generic ones (.log_ui)

The distinction helps and gives more insight on what is
actually accomplished by each method. This is a fairly
intrusive change, although it received a fair bit of
testing before submission.
Signed-off-by: NLucas Meneghel Rodrigues <lmr@redhat.com>

avocado/core/output.py

@@ -263,109 +263,109 @@ class View(object):
         else:
             self.console_log.log(level=level, msg=msg, extra=extra)
 
-    def info(self, msg, skip_newline=False):
+    def _log_ui_info(self, msg, skip_newline=False):
         """
-        Log a :mod:`logging.INFO` message.
+        Log a :mod:`logging.INFO` message to the UI.
 
         :param msg: Message to write.
         """
         self.log(msg, level=logging.INFO, skip_newline=skip_newline)
 
-    def error(self, msg):
+    def _log_ui_error(self, msg, skip_newline=False):
         """
-        Log a :mod:`logging.ERROR` message.
+        Log a :mod:`logging.ERROR` message to the UI.
 
         :param msg: Message to write.
         """
-        self.log(msg, level=logging.ERROR)
+        self.log(msg, level=logging.ERROR, skip_newline=skip_newline)
 
-    def log_healthy(self, msg, skip_newline=False):
+    def log_ui_healthy(self, msg, skip_newline=False):
         """
-        Log a message that indicates something healthy is going on
+        Log a message that indicates that things are going as expected.
 
         :param msg: Message to write.
         """
-        self.info(term_support.healthy_str(msg), skip_newline)
+        self._log_ui_info(term_support.healthy_str(msg), skip_newline)
 
-    def log_partial(self, msg, skip_newline=False):
+    def log_ui_partial(self, msg, skip_newline=False):
         """
         Log a message that indicates something (at least) partially OK
 
         :param msg: Message to write.
         """
-        self.info(term_support.partial_str(msg), skip_newline)
+        self._log_ui_info(term_support.partial_str(msg), skip_newline)
 
-    def log_header(self, msg):
+    def log_ui_header(self, msg):
         """
         Log a header message.
 
         :param msg: Message to write.
         """
-        self.info(term_support.header_str(msg))
+        self._log_ui_info(term_support.header_str(msg))
 
-    def log_fail_header(self, msg):
+    def log_ui_error(self, msg):
         """
-        Log a fail header message (red, for critical errors).
+        Log an error message (useful for critical errors).
 
         :param msg: Message to write.
         """
-        self.info(term_support.fail_header_str(msg))
+        self._log_ui_info(term_support.fail_header_str(msg))
 
-    def log_pass(self, t_elapsed):
+    def log_ui_status_pass(self, t_elapsed):
         """
-        Log a PASS message.
+        Log a PASS status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_pass_msg = term_support.pass_str() + " (%.2f s)" % t_elapsed
-        self.info(normal_pass_msg)
+        self._log_ui_info(normal_pass_msg)
 
-    def log_error(self, t_elapsed):
+    def log_ui_status_error(self, t_elapsed):
         """
-        Log an ERROR message.
+        Log an ERROR status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_error_msg = term_support.error_str() + " (%.2f s)" % t_elapsed
-        self.error(normal_error_msg)
+        self._log_ui_error(normal_error_msg)
 
-    def log_not_found(self, t_elapsed):
+    def log_ui_status_not_found(self, t_elapsed):
         """
-        Log a NOT_FOUND message.
+        Log a NOT_FOUND status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_error_msg = term_support.not_found_str() + " (%.2f s)" % t_elapsed
-        self.error(normal_error_msg)
+        self._log_ui_error(normal_error_msg)
 
-    def log_fail(self, t_elapsed):
+    def log_ui_status_fail(self, t_elapsed):
         """
-        Log a FAIL message.
+        Log a FAIL status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_fail_msg = term_support.fail_str() + " (%.2f s)" % t_elapsed
-        self.error(normal_fail_msg)
+        self._log_ui_error(normal_fail_msg)
 
-    def log_skip(self, t_elapsed):
+    def log_ui_status_skip(self, t_elapsed):
         """
-        Log a SKIP message.
+        Log a SKIP status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_skip_msg = term_support.skip_str()
-        self.info(normal_skip_msg)
+        self._log_ui_info(normal_skip_msg)
 
-    def log_warn(self, t_elapsed):
+    def log_ui_status_warn(self, t_elapsed):
         """
-        Log a WARN message.
+        Log a WARN status message for a given operation.
 
         :param t_elapsed: Time it took for the operation to complete.
         """
         normal_warn_msg = term_support.warn_str() + " (%.2f s)" % t_elapsed
-        self.error(normal_warn_msg)
+        self._log_ui_error(normal_warn_msg)
 
-    def throbber_progress(self, progress_from_test=False):
+    def log_ui_throbber_progress(self, progress_from_test=False):
         """
         Give an interactive indicator of the test progress
 
@@ -377,9 +377,9 @@ class View(object):
         :rtype: None
         """
         if progress_from_test:
-            self.log_healthy(self.THROBBER_MOVES[self.throbber_pos], True)
+            self.log_ui_healthy(self.THROBBER_MOVES[self.throbber_pos], True)
         else:
-            self.log_partial(self.THROBBER_MOVES[self.throbber_pos], True)
+            self.log_ui_partial(self.THROBBER_MOVES[self.throbber_pos], True)
 
         if self.throbber_pos == (len(self.THROBBER_MOVES) - 1):
             self.throbber_pos = 0

avocado/job.py

@@ -239,17 +239,17 @@ class TestRunner(object):
                                        ignore_window)
                             k_msg_3 = ("A new Ctrl+C sent after that will send a "
                                        "SIGKILL to them")
-                            self.job.output_manager.log_header("\n")
-                            self.job.output_manager.log_header(k_msg_1)
-                            self.job.output_manager.log_header(k_msg_2)
-                            self.job.output_manager.log_header(k_msg_3)
+                            self.job.output_manager.log_ui_header("\n")
+                            self.job.output_manager.log_ui_header(k_msg_1)
+                            self.job.output_manager.log_ui_header(k_msg_2)
+                            self.job.output_manager.log_ui_header(k_msg_3)
                             stage_1_msg_displayed = True
                         ignore_time_started = time.time()
                     if (ctrl_c_count > 2) and (time_elapsed > ignore_window):
                         if not stage_2_msg_displayed:
                             k_msg_3 = ("Ctrl+C received after the ignore window. "
                                        "Killing all active tests")
-                            self.job.output_manager.log_header(k_msg_3)
+                            self.job.output_manager.log_ui_header(k_msg_3)
                             stage_2_msg_displayed = True
                         os.kill(p.pid, signal.SIGKILL)
 
@@ -267,7 +267,7 @@ class TestRunner(object):
 
             # don't process other tests from the list
             if ctrl_c_count > 0:
-                self.job.output_manager.log_header("")
+                self.job.output_manager.log_ui_header("")
                 break
 
             self.result.check_test(test_state)
@@ -343,8 +343,8 @@ class Job(object):
                         if plugin_using_stdout is not None:
                             e_msg %= (plugin_using_stdout.command_line_arg_name,
                                       result_plugin.command_line_arg_name)
-                            self.view.log_fail_header(e_msg)
-                            self.view.log_fail_header(e_msg_2)
+                            self.view.log_ui_error(e_msg)
+                            self.view.log_ui_error(e_msg_2)
                             sys.exit(error_codes.numeric_status['AVOCADO_JOB_FAIL'])
                         else:
                             plugin_using_stdout = result_plugin
@@ -505,11 +505,11 @@ class Job(object):
         except exceptions.JobBaseException, details:
             self.status = details.status
             fail_class = details.__class__.__name__
-            self.view.log_fail_header('Avocado job failed: %s: %s' %
+            self.view.log_ui_error('Avocado job failed: %s: %s' %
                                    (fail_class, details))
             return error_codes.numeric_status['AVOCADO_JOB_FAIL']
         except exceptions.OptionValidationError, details:
-            self.view.log_fail_header(str(details))
+            self.view.log_ui_error(str(details))
             return error_codes.numeric_status['AVOCADO_JOB_FAIL']
 
         except Exception, details:
@@ -518,14 +518,14 @@ class Job(object):
             tb_info = traceback.format_exception(exc_type, exc_value,
                                                  exc_traceback.tb_next)
             fail_class = details.__class__.__name__
-            self.view.log_fail_header('Avocado crashed: %s: %s' %
+            self.view.log_ui_error('Avocado crashed: %s: %s' %
                                    (fail_class, details))
             for line in tb_info:
-                self.view.error(line)
-            self.view.log_fail_header('Please include the traceback '
+                self.view.log_ui_error(line)
+            self.view.log_ui_error('Please include the traceback '
                                    'info and command line used on '
                                    'your bug report')
-            self.view.log_fail_header('Report bugs visiting %s' %
+            self.view.log_ui_error('Report bugs visiting %s' %
                                    _NEW_ISSUE_LINK)
             return error_codes.numeric_status['AVOCADO_CRASH']
 

avocado/plugins/datadir.py

@@ -34,7 +34,7 @@ class DataDirList(plugin.Plugin):
 
     def run(self, args):
         view = output.View()
-        view.log_header('Avocado Data Directories:')
+        view.log_ui_header('Avocado Data Directories:')
         view.log('    base dir        ' + data_dir.get_base_dir())
         view.log('    tests dir       ' + data_dir.get_test_dir())
         view.log('    data dir        ' + data_dir.get_data_dir())

avocado/plugins/lister.py

@@ -35,7 +35,7 @@ class PluginsList(plugin.Plugin):
     def run(self, args):
         view = output.View()
         pm = get_plugin_manager()
-        view.log_header('Plugins loaded:')
+        view.log_ui_header('Plugins loaded:')
         blength = 0
         for plug in pm.plugins:
             clength = len(plug.name)
@@ -47,6 +47,6 @@ class PluginsList(plugin.Plugin):
             view.log(format_str % (plug.name, plug.description),
                      skip_newline=True)
             if plug.enabled:
-                view.log_healthy("(Enabled)")
+                view.log_ui_healthy("(Enabled)")
             else:
-                view.log_fail_header("(Disabled)")
+                view.log_ui_error("(Disabled)")

avocado/plugins/multiplexer.py

@@ -56,17 +56,17 @@ class Multiplexer(plugin.Plugin):
         view = output.View()
 
         if not args.multiplex_file:
-            view.log_fail_header('A multiplex file is required, aborting...')
+            view.log_ui_error('A multiplex file is required, aborting...')
             sys.exit(error_codes.numeric_status['AVOCADO_JOB_FAIL'])
 
         multiplex_file = os.path.abspath(args.multiplex_file)
 
         if not os.path.isfile(multiplex_file):
-            view.log_fail_header('Invalid multiplex file %s' % multiplex_file)
+            view.log_ui_error('Invalid multiplex file %s' % multiplex_file)
             sys.exit(error_codes.numeric_status['AVOCADO_JOB_FAIL'])
 
         if args.tree:
-            view.log_header('Config file tree structure:')
+            view.log_ui_header('Config file tree structure:')
             data = tree.read_ordered_yaml(open(multiplex_file))
             t = tree.create_from_ordered_data(data)
             view.log(t.get_ascii())
@@ -76,7 +76,7 @@ class Multiplexer(plugin.Plugin):
                                                          args.filter_only,
                                                          args.filter_out)
 
-        view.log_header('Variants generated:')
+        view.log_ui_header('Variants generated:')
         for (index, tpl) in enumerate(variants):
             paths = ', '.join([x.path for x in tpl])
             view.log('Variant %s:    %s' % (index+1, paths))

avocado/plugins/runner.py

@@ -66,7 +66,7 @@ class TestLister(plugin.Plugin):
                     blength = clength
                 test_dirs.append((t.split('.')[0], os.path.join(base_test_dir, t)))
         format_string = "    %-" + str(blength) + "s %s"
-        view.log_header('Tests dir: %s' % base_test_dir)
+        view.log_ui_header('Tests dir: %s' % base_test_dir)
         if len(test_dirs) > 0:
             view.log(format_string % ('Alias', 'Path'))
             for test_dir in test_dirs:

avocado/plugins/vm.py

@@ -152,42 +152,42 @@ class VMTestResult(TestResult):
         if self.args.vm_domain is None:
             e_msg = ('Please set Virtual Machine Domain with option '
                      '--vm-domain.')
-            self.stream.error(e_msg)
+            self.stream.log_ui_error(e_msg)
             raise exceptions.TestSetupFail(e_msg)
         if self.args.vm_hostname is None:
             e_msg = ('Please set Virtual Machine hostname with option '
                      '--vm-hostname.')
-            self.stream.error(e_msg)
+            self.stream.log_ui_error(e_msg)
             raise exceptions.TestSetupFail(e_msg)
-        self.stream.log_header("VM DOMAIN : %s" %
+        self.stream.log_ui_header("VM DOMAIN : %s" %
                                   self.args.vm_domain)
-        self.stream.log_header("VM LOGIN  : %s@%s" %
+        self.stream.log_ui_header("VM LOGIN  : %s@%s" %
                                   (self.args.vm_username, self.args.vm_hostname))
         self.vm = virt.vm_connect(self.args.vm_domain,
                                   self.args.vm_hypervisor_uri)
         if self.vm is None:
-            self.stream.error("Could not connect to VM '%s'" % self.args.vm_domain)
+            self.stream.log_ui_error("Could not connect to VM '%s'" % self.args.vm_domain)
             raise exceptions.TestSetupFail()
         if self.vm.start() is False:
-            self.stream.error("Could not start VM '%s'" % self.args.vm_domain)
+            self.stream.log_ui_error("Could not start VM '%s'" % self.args.vm_domain)
             raise exceptions.TestSetupFail()
         assert self.vm.domain.isActive() is not False
         if self.args.vm_cleanup is True:
             self.vm.create_snapshot()
             if self.vm.snapshot is None:
-                self.stream.error("Could not create snapshot on VM '%s'" % self.args.vm_domain)
+                self.stream.log_ui_error("Could not create snapshot on VM '%s'" % self.args.vm_domain)
                 raise exceptions.TestSetupFail()
         try:
             self.vm.setup_login(self.args.vm_hostname,
                                 self.args.vm_username,
                                 self.args.vm_password)
         except Exception as err:
-            self.stream.error("Could not login on VM '%s': %s" % (self.args.vm_hostname,
+            self.stream.log_ui_error("Could not login on VM '%s': %s" % (self.args.vm_hostname,
                                                                          err))
             self.tear_down()
             raise exceptions.TestSetupFail()
         if self.vm.logged is False or self.vm.remote.uptime() is '':
-            self.stream.error("Could not login on VM '%s'" % self.args.vm_hostname)
+            self.stream.log_ui_error("Could not login on VM '%s'" % self.args.vm_hostname)
             self.tear_down()
             raise exceptions.TestSetupFail()
         self._copy_tests()
@@ -201,21 +201,21 @@ class VMTestResult(TestResult):
         Called once before any tests are executed.
         """
         TestResult.start_tests(self)
-        self.stream.log_header("JOB ID    : %s" % self.stream.job_unique_id)
-        self.stream.log_header("JOB LOG   : %s" % self.stream.logfile)
-        self.stream.log_header("TESTS     : %s" % self.tests_total)
+        self.stream.log_ui_header("JOB ID    : %s" % self.stream.job_unique_id)
+        self.stream.log_ui_header("JOB LOG   : %s" % self.stream.logfile)
+        self.stream.log_ui_header("TESTS     : %s" % self.tests_total)
 
     def end_tests(self):
         """
         Called once after all tests are executed.
         """
-        self.stream.log_header("PASS      : %d" % len(self.passed))
-        self.stream.log_header("ERROR     : %d" % len(self.errors))
-        self.stream.log_header("NOT FOUND : %d" % len(self.not_found))
-        self.stream.log_header("FAIL      : %d" % len(self.failed))
-        self.stream.log_header("SKIP      : %d" % len(self.skipped))
-        self.stream.log_header("WARN      : %d" % len(self.warned))
-        self.stream.log_header("TIME      : %.2f s" % self.total_time)
+        self.stream.log_ui_header("PASS      : %d" % len(self.passed))
+        self.stream.log_ui_header("ERROR     : %d" % len(self.errors))
+        self.stream.log_ui_header("NOT FOUND : %d" % len(self.not_found))
+        self.stream.log_ui_header("FAIL      : %d" % len(self.failed))
+        self.stream.log_ui_header("SKIP      : %d" % len(self.skipped))
+        self.stream.log_ui_header("WARN      : %d" % len(self.warned))
+        self.stream.log_ui_header("TIME      : %.2f s" % self.total_time)
 
     def start_test(self, test):
         """
@@ -226,7 +226,7 @@ class VMTestResult(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)
+        self.stream.log(msg=self.test_label, skip_newline=True)
 
     def end_test(self, test):
         """
@@ -243,7 +243,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_pass(self, test)
-        self.stream.log_pass(test['time_elapsed'])
+        self.stream.log_ui_status_pass(test['time_elapsed'])
 
     def add_error(self, test):
         """
@@ -252,7 +252,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_error(self, test)
-        self.stream.log_error(test['time_elapsed'])
+        self.stream.log_ui_status_error(test['time_elapsed'])
 
     def add_not_found(self, test):
         """
@@ -261,7 +261,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_not_found(self, test)
-        self.stream.log_not_found(test['time_elapsed'])
+        self.stream.log_ui_status_not_found(test['time_elapsed'])
 
     def add_fail(self, test):
         """
@@ -270,7 +270,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_fail(self, test)
-        self.stream.log_fail(test['time_elapsed'])
+        self.stream.log_ui_status_fail(test['time_elapsed'])
 
     def add_skip(self, test):
         """
@@ -279,7 +279,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_skip(self, test)
-        self.stream.log_skip(test['time_elapsed'])
+        self.stream.log_ui_status_skip(test['time_elapsed'])
 
     def add_warn(self, test):
         """
@@ -288,7 +288,7 @@ class VMTestResult(TestResult):
         :param test: :class:`avocado.test.Test` instance.
         """
         TestResult.add_warn(self, test)
-        self.stream.log_warn(test['time_elapsed'])
+        self.stream.log_ui_status_warn(test['time_elapsed'])
 
 
 class RunVM(plugin.Plugin):

avocado/result.py

@@ -242,21 +242,21 @@ class HumanTestResult(TestResult):
         Called once before any tests are executed.
         """
         TestResult.start_tests(self)
-        self.stream.log_header("JOB ID    : %s" % self.stream.job_unique_id)
-        self.stream.log_header("JOB LOG   : %s" % self.stream.logfile)
-        self.stream.log_header("TESTS     : %s" % self.tests_total)
+        self.stream.log_ui_header("JOB ID    : %s" % self.stream.job_unique_id)
+        self.stream.log_ui_header("JOB LOG   : %s" % self.stream.logfile)
+        self.stream.log_ui_header("TESTS     : %s" % self.tests_total)
 
     def end_tests(self):
         """
         Called once after all tests are executed.
         """
-        self.stream.log_header("PASS      : %d" % len(self.passed))
-        self.stream.log_header("ERROR     : %d" % len(self.errors))
-        self.stream.log_header("FAIL      : %d" % len(self.failed))
-        self.stream.log_header("SKIP      : %d" % len(self.skipped))
-        self.stream.log_header("WARN      : %d" % len(self.warned))
-        self.stream.log_header("NOT FOUND : %d" % len(self.not_found))
-        self.stream.log_header("TIME      : %.2f s" % self.total_time)
+        self.stream.log_ui_header("PASS      : %d" % len(self.passed))
+        self.stream.log_ui_header("ERROR     : %d" % len(self.errors))
+        self.stream.log_ui_header("FAIL      : %d" % len(self.failed))
+        self.stream.log_ui_header("SKIP      : %d" % len(self.skipped))
+        self.stream.log_ui_header("WARN      : %d" % len(self.warned))
+        self.stream.log_ui_header("NOT FOUND : %d" % len(self.not_found))
+        self.stream.log_ui_header("TIME      : %.2f s" % self.total_time)
 
     def start_test(self, state):
         """
@@ -268,7 +268,7 @@ class HumanTestResult(TestResult):
         self.test_label = '(%s/%s) %s:  ' % (self.tests_run,
                                              self.tests_total,
                                              state['tagged_name'])
-        self.stream.info(msg=self.test_label, skip_newline=True)
+        self.stream.log(msg=self.test_label, skip_newline=True)
 
     def end_test(self, state):
         """
@@ -287,7 +287,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_pass(self, state)
-        self.stream.log_pass(state['time_elapsed'])
+        self.stream.log_ui_status_pass(state['time_elapsed'])
 
     def add_error(self, state):
         """
@@ -297,7 +297,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_error(self, state)
-        self.stream.log_error(state['time_elapsed'])
+        self.stream.log_ui_status_error(state['time_elapsed'])
 
     def add_not_found(self, state):
         """
@@ -307,7 +307,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_not_found(self, state)
-        self.stream.log_not_found(state['time_elapsed'])
+        self.stream.log_ui_status_not_found(state['time_elapsed'])
 
     def add_fail(self, state):
         """
@@ -317,7 +317,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_fail(self, state)
-        self.stream.log_fail(state['time_elapsed'])
+        self.stream.log_ui_status_fail(state['time_elapsed'])
 
     def add_skip(self, state):
         """
@@ -327,7 +327,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_skip(self, state)
-        self.stream.log_skip(state['time_elapsed'])
+        self.stream.log_ui_status_skip(state['time_elapsed'])
 
     def add_warn(self, state):
         """
@@ -337,7 +337,7 @@ class HumanTestResult(TestResult):
         :type state: dict
         """
         TestResult.add_warn(self, state)
-        self.stream.log_warn(state['time_elapsed'])
+        self.stream.log_ui_status_warn(state['time_elapsed'])
 
     def throbber_progress(self, progress_from_test=False):
-        self.stream.throbber_progress(progress_from_test)
+        self.stream.log_ui_throbber_progress(progress_from_test)

selftests/all/unit/avocado/vm_unittest.py

@@ -37,16 +37,16 @@ class _Stream(object):
     def start_file_logging(self, param1, param2):
         pass
 
-    def info(self, msg, skip_newline=False):
+    def stop_file_logging(self):
         pass
 
-    def log_header(self, param):
+    def log(self, msg, skip_newline=False):
         pass
 
-    def stop_file_logging(self):
+    def log_ui_header(self, param):
         pass
 
-    def log_pass(self, param1):
+    def log_ui_status_pass(self, param1):
         pass