From 3099aab7b57887978430d242b5bdc97d2181784b Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Thu, 25 Sep 2014 16:11:15 -0300 Subject: [PATCH] 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: Lucas Meneghel Rodrigues --- avocado/core/output.py | 72 +++++++++++------------ avocado/job.py | 38 ++++++------ avocado/plugins/datadir.py | 2 +- avocado/plugins/lister.py | 6 +- avocado/plugins/multiplexer.py | 8 +-- avocado/plugins/runner.py | 2 +- avocado/plugins/vm.py | 58 +++++++++--------- avocado/result.py | 36 ++++++------ selftests/all/unit/avocado/vm_unittest.py | 8 +-- 9 files changed, 115 insertions(+), 115 deletions(-) diff --git a/avocado/core/output.py b/avocado/core/output.py index a39ea78b..fae66908 100644 --- a/avocado/core/output.py +++ b/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 diff --git a/avocado/job.py b/avocado/job.py index af457998..32710ec0 100644 --- a/avocado/job.py +++ b/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' % - (fail_class, details)) + 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,15 +518,15 @@ 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' % - (fail_class, details)) + 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 ' - 'info and command line used on ' - 'your bug report') - self.view.log_fail_header('Report bugs visiting %s' % - _NEW_ISSUE_LINK) + 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_ui_error('Report bugs visiting %s' % + _NEW_ISSUE_LINK) return error_codes.numeric_status['AVOCADO_CRASH'] diff --git a/avocado/plugins/datadir.py b/avocado/plugins/datadir.py index 15555503..068bce21 100644 --- a/avocado/plugins/datadir.py +++ b/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()) diff --git a/avocado/plugins/lister.py b/avocado/plugins/lister.py index 18594f83..a3b380ae 100644 --- a/avocado/plugins/lister.py +++ b/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)") diff --git a/avocado/plugins/multiplexer.py b/avocado/plugins/multiplexer.py index 6bac8288..cf7f463f 100644 --- a/avocado/plugins/multiplexer.py +++ b/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)) diff --git a/avocado/plugins/runner.py b/avocado/plugins/runner.py index d779a21a..c86ef4b5 100644 --- a/avocado/plugins/runner.py +++ b/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: diff --git a/avocado/plugins/vm.py b/avocado/plugins/vm.py index f7e26d4f..0874d82a 100644 --- a/avocado/plugins/vm.py +++ b/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.args.vm_domain) - self.stream.log_header("VM LOGIN : %s@%s" % - (self.args.vm_username, self.args.vm_hostname)) + self.stream.log_ui_header("VM DOMAIN : %s" % + self.args.vm_domain) + 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, - err)) + 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): diff --git a/avocado/result.py b/avocado/result.py index b6c6f8aa..f3a23023 100644 --- a/avocado/result.py +++ b/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) diff --git a/selftests/all/unit/avocado/vm_unittest.py b/selftests/all/unit/avocado/vm_unittest.py index 71a91c91..09424038 100755 --- a/selftests/all/unit/avocado/vm_unittest.py +++ b/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 -- GitLab